Re: Show WAL write and fsync stats in pg_stat_io

Hi,

On Tue, 4 Feb 2025 at 10:55, Michael Paquier <michael(at)paquier(dot)xyz> wrote:
>
> On Mon, Feb 03, 2025 at 02:34:29PM +0300, Nazir Bilal Yavuz wrote:
> > On Mon, 3 Feb 2025 at 11:50, Bertrand Drouvot <
bertranddrouvot(dot)pg(at)gmail(dot)com> wrote:
> >> === 1
> >>
> >> + pgstat_count_io_op_time(IOOBJECT_WAL, IOCONTEXT_INIT,
IOOP_WRITE,
> >> + io_start, 1,
wal_segment_size);
> >>
> >> In case wal_init_zero is false, then we're only seeking to the end and
write a
> >> solitary byte. Then, is reporting "wal_segment_size" correct?
> >
> > I think you are right. It would make sense to have two
> > pgstat_count_io_op_time() calls here. One for wal_segment_size and one
> > for solitary byte.
>
> Ah, right. We can just use one call with the size written set
> depending on wal_init_zero, because this is still a IOOP_WRITE for a
> IOCONTEXT_INIT in both cases. Only the size changes as we are in
> XLogFileInitInternal().

Yes, that is better. Thanks!

> At the end, we want this patch and this data, and my benchmarcking is
> not showing much differences even if going through a workload with
> many pages, so I've used the version relying entirely on
> track_io_timing and applied it.

Thanks! My benchmark results are the same [1]. I could not see the
noticable difference between master and patched version. I run the
benchmark a couple of times, sometimes the patched version, sometimes the
master version is better. I think the differences are due to margin of
error. Sharing the latest benchmark run at the bottom [1].

> If we split these timings across more GUCs, one thing to consider
> would be a third GUC which is neither track_wal_io_timing nor
> track_io_timing to keep things independent, but I am not really
> convinced that's necessary.

I agree.

[1]
pgbench -n -c8 -j8-T60 -f <(echo "SELECT pg_logical_emit_message(true,
'test', repeat('0', ${emit_bytes}));";)
with emit bytes being 10 and 8192 for the 'acpi_pm', 'hpet' and 'tsc' clock
sources.

(I hope that table gets rendered correctly in the mailing list.)

╔══════════════╦════════════╦═════════════════╦═════════════════════╦════════╦═════════╦═══════════╗
║ clock source ║ emit_bytes ║ track_io_timing ║ track_wal_io_timing ║
master ║ patched ║ Change % ║
║ ║ ║ ║ ║ TPS
║ TPS ║ (Positive ║
║ ║ ║ ║ ║
║ ║ means ║
║ ║ ║ ║ ║
║ ║ better) ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ off ║ 2164
║ 2221 ║ 2.63 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2171
║ 2246 ║ 3.45 ║
║ ║ 10
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2243
║ 2178 ║ -2.90 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2188
║ 2148 ║ -1.83 ║
║
╠════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ acpi_pm ║ ║ off ║ off ║ 2226
║ 2172 ║ -2.43 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2219
║ 2203 ║ -0.72 ║
║ ║ 8192
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2168
║ 2223 ║ 2.54 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2229
║ 2204 ║ -1.12 ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ ║ ║
║ ║ ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ ║ ║
║ ║ ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ off ║ 2087
║ 2156 ║ 3.31 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2141
║ 2089 ║ -2.43 ║
║ ║ 10
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2085
║ 2071 ║ -0.67 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2024
║ 2052 ║ 1.38 ║
║
╠════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ hpet ║ ║ off ║ off ║ 2141
║ 2074 ║ -3.13 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2056
║ 2079 ║ 1.12 ║
║ ║ 8192
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2096
║ 2087 ║ -0.43 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2103
║ 2086 ║ -0.81 ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ ║ ║
║ ║ ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ ║ ║
║ ║ ║
╠══════════════╬════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ off ║ 2276
║ 2252 ║ -1.05 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2213
║ 2124 ║ -4.02 ║
║ ║ 10
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2183
║ 2250 ║ 3.07 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2287
║ 2250 ║ -1.62 ║
║
╠════════════╬═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ tsc ║ ║ off ║ off ║ 2178
║ 2179 ║ 0.05 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ off ║ 2203
║ 2187 ║ -0.73 ║
║ ║ 8192
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ off ║ on ║ 2220
║ 2240 ║ 0.90 ║
║ ║
╠═════════════════╬═════════════════════╬════════╬═════════╬═══════════╣
║ ║ ║ on ║ on ║ 2102
║ 2182 ║ 3.81 ║
╚══════════════╩════════════╩═════════════════╩═════════════════════╩════════╩═════════╩═══════════╝

--
Regards,
Nazir Bilal Yavuz
Microsoft