Обсуждение: Simple update query is slow
Hi,
I noticed something strange in our PG server. I have a table named
'timetable' that has only one bigint column and one row.
Once in every 5 seconds this row is updated to the current time epoch
value in milliseconds.
The update query seems to be taking considerable time (avg 50
milliseconds). When I tried generating the explain (analyze,buffers)
for the query, the planning time + execution time is always less than
0.1 millisecond. However the query time as shown when /timing of psql
is enabled shows approx 30 milliseconds (I am connecting via psql from
the localhost).
Please find the details below.
postgres=> select version();
version
----------------------------------------------------------------------------------------------------------------
PostgreSQL 9.4.15 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
4.4.7 20120313 (Red Hat 4.4.7-18), 64-bit
(1 row)
Time: 0.572 ms
postgres=> \d+ timetable
Table "public.timetable"
Column | Type | Modifiers | Storage | Stats target | Description
--------+--------+-----------+---------+--------------+-------------
time | bigint | | plain | |
postgres=> table timetable ;
time
------------
1605988584
(1 row)
Time: 0.402 ms
postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
time=0.064..0.064 rows=0 loops=1)
Buffers: shared hit=5
-> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
(actual time=0.029..0.029 rows=1 loops=1)
Output: ("time" + 0), ctid
Buffers: shared hit=4
Planning time: 0.054 ms
Execution time: 0.093 ms
(7 rows)
Time: 27.685 ms
Sometimes this shoots up to even a few hundred milliseconds.
postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
time=0.048..0.048 rows=0 loops=1)
Buffers: shared hit=5
-> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
(actual time=0.027..0.028 rows=1 loops=1)
Output: ("time" + 0), ctid
Buffers: shared hit=4
Planning time: 0.063 ms
Execution time: 0.084 ms
(7 rows)
Time: 291.090 ms
I guess the problem here may somehow be linked to frequent updates to
the one row. However I want to understand what exactly is going wrong
here. Also I don't understand the discrepancy between planning +
execution time from explain analyze and the time taken by the query as
reported in pg log and in psql console.
Kindly help me on this.
Regards,
Nanda
Hi,
Just realised that the time difference between explain analyze plan
and /timing result is due to the implicit commit.
Sorry about that.
Regards,
Nanda
On Sun, 22 Nov 2020 at 01:57, Nandakumar M <m.nanda92@gmail.com> wrote:
>
> Hi,
>
> I noticed something strange in our PG server. I have a table named
> 'timetable' that has only one bigint column and one row.
>
> Once in every 5 seconds this row is updated to the current time epoch
> value in milliseconds.
>
> The update query seems to be taking considerable time (avg 50
> milliseconds). When I tried generating the explain (analyze,buffers)
> for the query, the planning time + execution time is always less than
> 0.1 millisecond. However the query time as shown when /timing of psql
> is enabled shows approx 30 milliseconds (I am connecting via psql from
> the localhost).
>
>
> Please find the details below.
>
> postgres=> select version();
> version
> ----------------------------------------------------------------------------------------------------------------
> PostgreSQL 9.4.15 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
> 4.4.7 20120313 (Red Hat 4.4.7-18), 64-bit
> (1 row)
>
> Time: 0.572 ms
>
>
>
>
>
> postgres=> \d+ timetable
> Table "public.timetable"
> Column | Type | Modifiers | Storage | Stats target | Description
> --------+--------+-----------+---------+--------------+-------------
> time | bigint | | plain | |
>
>
>
>
>
>
> postgres=> table timetable ;
> time
> ------------
> 1605988584
> (1 row)
>
> Time: 0.402 ms
>
>
>
>
>
> postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
> time=0.064..0.064 rows=0 loops=1)
> Buffers: shared hit=5
> -> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
> (actual time=0.029..0.029 rows=1 loops=1)
> Output: ("time" + 0), ctid
> Buffers: shared hit=4
> Planning time: 0.054 ms
> Execution time: 0.093 ms
> (7 rows)
>
> Time: 27.685 ms
>
>
> Sometimes this shoots up to even a few hundred milliseconds.
>
> postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
> time=0.048..0.048 rows=0 loops=1)
> Buffers: shared hit=5
> -> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
> (actual time=0.027..0.028 rows=1 loops=1)
> Output: ("time" + 0), ctid
> Buffers: shared hit=4
> Planning time: 0.063 ms
> Execution time: 0.084 ms
> (7 rows)
>
> Time: 291.090 ms
>
>
>
>
> I guess the problem here may somehow be linked to frequent updates to
> the one row. However I want to understand what exactly is going wrong
> here. Also I don't understand the discrepancy between planning +
> execution time from explain analyze and the time taken by the query as
> reported in pg log and in psql console.
>
> Kindly help me on this.
>
> Regards,
> Nanda
On Sun, Nov 22, 2020 at 02:18:10AM +0530, Nandakumar M wrote:
> Just realised that the time difference between explain analyze plan
> and /timing result is due to the implicit commit.
Can you run with SET client_min_messages=debug; and SET log_lock_waits=on;
Oh, but your server is too old for that...
On Sun, 22 Nov 2020 at 01:57, Nandakumar M <m.nanda92@gmail.com> wrote:
>
> Hi,
>
> I noticed something strange in our PG server. I have a table named
> 'timetable' that has only one bigint column and one row.
>
> Once in every 5 seconds this row is updated to the current time epoch
> value in milliseconds.
>
> The update query seems to be taking considerable time (avg 50
> milliseconds). When I tried generating the explain (analyze,buffers)
> for the query, the planning time + execution time is always less than
> 0.1 millisecond. However the query time as shown when /timing of psql
> is enabled shows approx 30 milliseconds (I am connecting via psql from
> the localhost).
>
>
> Please find the details below.
>
> postgres=> select version();
> version
> ----------------------------------------------------------------------------------------------------------------
> PostgreSQL 9.4.15 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
> 4.4.7 20120313 (Red Hat 4.4.7-18), 64-bit
> (1 row)
>
> Time: 0.572 ms
>
>
>
>
>
> postgres=> \d+ timetable
> Table "public.timetable"
> Column | Type | Modifiers | Storage | Stats target | Description
> --------+--------+-----------+---------+--------------+-------------
> time | bigint | | plain | |
>
>
>
>
>
>
> postgres=> table timetable ;
> time
> ------------
> 1605988584
> (1 row)
>
> Time: 0.402 ms
>
>
>
>
>
> postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
> time=0.064..0.064 rows=0 loops=1)
> Buffers: shared hit=5
> -> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
> (actual time=0.029..0.029 rows=1 loops=1)
> Output: ("time" + 0), ctid
> Buffers: shared hit=4
> Planning time: 0.054 ms
> Execution time: 0.093 ms
> (7 rows)
>
> Time: 27.685 ms
>
>
> Sometimes this shoots up to even a few hundred milliseconds.
>
> postgres=> explain (analyze,buffers,verbose) update timetable set time = time+0;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Update on public.timetable (cost=0.00..4.01 rows=1 width=14) (actual
> time=0.048..0.048 rows=0 loops=1)
> Buffers: shared hit=5
> -> Seq Scan on public.timetable (cost=0.00..4.01 rows=1 width=14)
> (actual time=0.027..0.028 rows=1 loops=1)
> Output: ("time" + 0), ctid
> Buffers: shared hit=4
> Planning time: 0.063 ms
> Execution time: 0.084 ms
> (7 rows)
>
> Time: 291.090 ms
>
> I guess the problem here may somehow be linked to frequent updates to
> the one row. However I want to understand what exactly is going wrong
> here. Also I don't understand the discrepancy between planning +
> execution time from explain analyze and the time taken by the query as
> reported in pg log and in psql console.