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
