On Wed, Apr 10, 2019 at 09:26:22AM +1200, Duncan Kinnear wrote:
> ----- On 5 Apr, 2019, at 4:14 AM, Jeff Janes <jeff.janes@gmail.com> wrote:
>
> > On Thu, Apr 4, 2019 at 3:42 AM Duncan Kinnear <duncan.kinnear@mccarthy.co.nz | duncan.kinnear@mccarthy.co.nz ] >
wrote:
>
> >> the EXPLAIN (ANALYSE, TIMING TRUE) of this query gives:
>
> >> Update on next_id (cost=0.14..8.16 rows=1 width=36) (actual time=0.057..0.057
> >> rows=0 loops=1)
> >> -> Index Scan using next_id_pk on next_id (cost=0.14..8.16 rows=1 width=36)
> >> (actual time=0.039..0.040 rows=1 loops=1)
> >> Index Cond: ((id)::text = 'Session'::text)
> >> Planning Time: 0.083 ms
> >> Execution Time: 0.089 ms
>
> >> which is significantly less than 50ms.
>
> > The EXPLAIN ANALYZE doesn't include the time needed to fsync the transaction
> > logs. It measures only the update itself, not the implicit commit at the end.
> > DBeaver is seeing the fsync-inclusive time. 50ms is pretty long, but some file
> > systems and OSes seem to be pretty inefficient at this and take several disk
> > revolutions to get the data down.
>
> >> Now, if I point DBeaver to a VM server on the same gigabit network switch,
> >> running version:
> >> 9.5.3 on i386-pc-solaris2.11, compiled by cc: Sun C 5.10 SunOS_i386 Patch
> >> 142363-07 2010/12/09, 64-bit
> >> then the same query executes in about 2-3ms
>
> > That machine probably has hardware to do a fast fsync, has fsync turned off, or
> > is lying about the safety of its data.
>
> Just a quick update. I tried performing a sequence of BEGIN; UPDATE ...; COMMIT; and I got the following log
entries:
> Apr 10 09:02:40 duncanpc postgres[7656]: 2019-04-10 09:02:40.640 NZST [29887] LOG: duration: 0.003 ms bind
<unnamed>: commit
> Apr 10 09:02:40 duncanpc postgres[7656]: 2019-04-10 09:02:40.690 NZST [29887] LOG: duration: 50.237 ms execute
<unnamed>: commit
>
> So this confirms that the overhead is indeed happening in the COMMIT part. But how do I get more detailed logging to
seewhat it is doing?
commit is causing the fsync() Jeff mentioned.
You could test that's the issue by comparing with fsync=off (please read what
that means and don't run your production cluster like that).
https://www.postgresql.org/docs/current/runtime-config-wal.html#GUC-FSYNC
You could also put your XLOG on a separate FS (as a test or otherwise).
Justin
