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@xxxxxxxxx> 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.
