Re: Remove wal_[sync|write][_time] from pg_stat_wal and track_wal_io_timing

Hi,

On Mon, Feb 24, 2025 at 06:15:53AM -0500, Andres Freund wrote:
> Hi,
>
> On 2025-02-24 10:54:54 +0000, Bertrand Drouvot wrote:
> > a051e71e28a added the "timing tracking" in the WAL code path with "only"
> > track_io_timing enabled (and track_wal_io_timing still false). Here, in this thread,
> > we remove unnecessary INSTR_TIME_SET_CURRENT()/INSTR_TIME_ACCUM_DIFF() calls when
> > both track_io_timing and track_wal_io_timing were enabled.
> >
> > So I think that your main concern comes from the fact that a051e71e28a added the
> > "timing tracking" in the WAL code path with "only" track_io_timing enabled.
>
> Correct.
>
>
> > That's a concern we also had and discussed in [1]. The question was: should
> > we track the WAL timing stats in pg_stat_io only when track_wal_io_timing is
> > enabled or relying only on track_io_timing would be enough?
> >
> > We ran several benchmarks ([2], [3] and [4]) and based on the results we reached
> > the conclusion that to rely only on track_io_timing to display the WAL timing
> > stats in pg_stat_io was "good" enough.
>
> Sorry to be blunt, but those benchmarks miss the mark. The benchmark
>
> - emits WAL in a transactional fashion, with fairly small transactions, where
> the disk is fairly slow. It's absolutely guaranteed that the bottleneck is
> just the WAL flush disk time. You're doing ~1k-2k TPS - the timing overhead
> would have to be *ginormous* to show up.
>
> - emits WAL at a low concurrency thus lock contention not really an issue.
>
> - likely is executed so on a system with very cheap timing functions - but
> often production workloads unfortunately don't. While it's not quite as
> common as it used to be, virtualized systems often have considerably slower
> clocks.
>
>
> On this system it'll likely be fine overhead-wise:
>
> $ echo tsc | sudo tee /sys/devices/system/clocksource/clocksource0/current_clocksource
> tsc
>
> $ src/bin/pg_test_timing/pg_test_timing
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 19.17 ns
> Histogram of timing durations:
> < us % of total count
> 1 98.08521 153484414
> 2 1.91421 2995376
> 4 0.00040 619
> 8 0.00014 225
> 16 0.00002 35
> 32 0.00001 9
> 64 0.00001 10
> 128 0.00000 3
> 256 0.00000 2
> 512 0.00000 1
>
>
> On this system however, I'd not want to bet on it:
>
> $ echo hpet | sudo tee /sys/devices/system/clocksource/clocksource0/current_clocksource
> $ src/bin/pg_test_timing/pg_test_timing
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 1228.91 ns
> Histogram of timing durations:
> < us % of total count
> 1 0.15574 3802
> 2 78.51065 1916598
> 4 21.26778 519188
> 8 0.02069 505
> 16 0.03957 966
> 32 0.00356 87
> 64 0.00193 47
> 128 0.00008 2
>
>

I agree that we've to put everything in the picture (system with or without
cheap timing functions, lock contention and WAL flush disk time) and that we
can certainly find configuration/workload that would get benefits from a
dedicated track_wal_io_timing GUC.

PFA a patch to re-introduce the track_wal_io_timing GUC and to ensure that the
WAL write and fsync timing activities are tracked in pg_stat_io (and
pg_stat_get_backend_io()) only if both track_io_timing and track_wal_io_timing
are enabled.

Note that to change the a051e71e28a behavior, the attached patch adds an extra
"track_io_guc" parameter to pgstat_count_io_op_time() (like pgstat_prepare_io_time
already had in a051e71e28a).

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com