Re: pg_stat_io not tracking smgrwriteback() is confusing

Hi,

On 2023-04-24 16:39:36 -0400, Melanie Plageman wrote:
> On Wed, Apr 19, 2023 at 10:23:26AM -0700, Andres Freund wrote:
> > Hi,
> > 
> > I noticed that the numbers in pg_stat_io dont't quite add up to what I
> > expected in write heavy workloads. Particularly for checkpointer, the numbers
> > for "write" in log_checkpoints output are larger than what is visible in
> > pg_stat_io.
> > 
> > That partially is because log_checkpoints' "write" covers way too many things,
> > but there's an issue with pg_stat_io as well:
> > 
> > Checkpoints, and some other sources of writes, will often end up doing a lot
> > of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> > pre-existing forms of IO statistics.
> > 
> > It seems pretty clear that we should track writeback as well. I wonder if it's
> > worth doing so for 16? It'd give a more complete picture that way. The
> > counter-argument I see is that we didn't track the time for it in existing
> > stats either, and that nobody complained - but I suspect that's mostly because
> > nobody knew to look.
> 
> Not complaining about making pg_stat_io more accurate, but what exactly
> would we be tracking for smgrwriteback()? I assume you are talking about
> IO timing. AFAICT, on Linux, it does sync_file_range() with
> SYNC_FILE_RANGE_WRITE, which is asynchronous. Wouldn't we just be
> tracking the system call overhead time?

It starts blocking once "enough" IO is in flight. For things like an immediate
checkpoint, that can happen fairly quickly, unless you have a very fast IO
subsystem. So often it'll not matter whether we track smgrwriteback(), but
when it matter, it can matter a lot.

As an example, I inited' a pgbench w/ scale 1000, on a decent but not great
NVMe SSD. Created dirty data with:

  c=96;/srv/dev/build/m-opt/src/bin/pgbench/pgbench --random-seed=0 -n -M prepared -c$c -j$c -T30 -P1
and then measured the checkpoint:
  perf trace -s -p $pid_of_checkpointer psql -x -c "SELECT pg_stat_reset_shared('io')" -c "checkpoint"

 postgres (367444), 1891280 events, 100.0%

   syscall            calls  errors  total       min       avg       max       stddev
                                     (msec)    (msec)    (msec)    (msec)        (%)
   --------------- --------  ------ -------- --------- --------- ---------     ------
   sync_file_range   359176      0  4560.670     0.002     0.013   238.955     10.36%
   pwrite64          582964      0  2874.634     0.003     0.005     0.156      0.06%
   fsync                242      0   251.631     0.001     1.040    42.166     18.81%
   openat               317     65     2.171     0.002     0.007     0.068      5.69%
   rename                69      0     1.973     0.012     0.029     0.084      5.81%
   fdatasync              1      0     1.543     1.543     1.543     1.543      0.00%
   unlink               150    137     1.278     0.002     0.009     0.062     10.69%
   close                250      0     0.694     0.001     0.003     0.007      3.14%
   newfstatat           140     68     0.667     0.001     0.005     0.022      7.26%
   write                  5      0     0.067     0.005     0.013     0.025     24.55%
   lseek                 14      0     0.050     0.001     0.004     0.018     33.87%
   getdents64             8      0     0.047     0.002     0.006     0.022     39.51%
   kill                   3      0     0.029     0.008     0.010     0.011     10.18%
   epoll_wait             2      1     0.006     0.000     0.003     0.006    100.00%
   read                   1      0     0.004     0.004     0.004     0.004      0.00%

Log output:

2023-04-24 14:11:59.234 PDT [367444][checkpointer][:0][] LOG:  checkpoint starting: immediate force wait
2023-04-24 14:12:09.236 PDT [367444][checkpointer][:0][] LOG:  checkpoint complete: wrote 595974 buffers (28.4%); 0 WAL
file(s)added, 0 removed, 68 recycled; write=9.740 s, sync=0.057 s, total=10.002 s; sync files=27, longest=0.043 s,
average=0.003s; distance=4467386 kB, estimate=4467386 kB; lsn=6/E5D33F98, redo lsn=6/E5D33F28
 


# SELECT writes, write_time, fsyncs, fsync_time FROM pg_stat_io WHERE backend_type = 'checkpointer';
┌────────┬────────────────────┬────────┬────────────┐
│ writes │     write_time     │ fsyncs │ fsync_time │
├────────┼────────────────────┼────────┼────────────┤
│ 595914 │ 4002.1730000000002 │     24 │     46.359 │
└────────┴────────────────────┴────────┴────────────┘


Greetings,

Andres Freund