Date: Sun, 22 Nov 2020 11:30:57 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Nandakumar M <m.nanda92@gmail.com>
Cc: Pgsql Performance <pgsql-performance@lists.postgresql.org>
Subject: Re: Simple update query is slow
Message-ID: <20201122173057.GA24052@telsasoft.com>
References: 
 <CANcFUu6GG_i9g_cF4nHd3DNw16MAR-4Kx360-YD8E8Bb4veOgw@mail.gmail.com>
 <CANcFUu7T0U_UJk1FmYpX8djUENuDvMT+REtWDC+hQ-pKh37PLw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CANcFUu7T0U_UJk1FmYpX8djUENuDvMT+REtWDC+hQ-pKh37PLw@mail.gmail.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk

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.