One reset call now clears half the log

Measuring a load by clearing the counters first

There is a technique for measuring what a workload costs that every experienced operator has used and almost nobody has written down. Clear the shared counters, run the thing, read the counters. The numbers then belong to the run rather than to the months since the cluster was last restarted, which is the only way to answer a question like “what does this batch job cost us in write-ahead log” without subtracting two large numbers and hoping the error is small.

On 18 that technique quietly stops measuring half of what it used to, and it does so in the worst possible way: the call succeeds, the numbers it clears go to zero as expected, and the numbers it no longer clears sit there looking like they belong to the run.

The reason is that the write-ahead log timing left its old home. What used to be counters on the log’s own view are now rows in the general I/O accounting, and the two are cleared by different arguments to the same reset function. The change of location is covered from the other side on the page about the view that lost the columns. What follows is only about the reset, because that is the part nobody looks at until a number turns out to be wrong.

What the call used to cover

On 17, clearing the log counters clears everything that describes log I/O, because everything that describes log I/O is in one place.

CREATE TABLE shipment_events (event_id bigserial PRIMARY KEY, detail text);

CREATE TABLE

SELECT pg_stat_reset_shared('wal');
INSERT INTO shipment_events (detail) SELECT repeat('e', 250) FROM generate_series(1, 30000);
SELECT pg_sleep(1);
SELECT wal_records, wal_write, wal_sync,
       round(wal_write_time::numeric, 1) AS write_ms
FROM pg_stat_wal;
SELECT count(*) AS wal_rows_in_the_io_view FROM pg_stat_io WHERE object = 'wal';

 pg_stat_reset_shared 
----------------------
 
(1 row)

INSERT 0 30000
 pg_sleep 
----------
 
(1 row)

 wal_records | wal_write | wal_sync | write_ms 
-------------+-----------+----------+----------
       60994 |       646 |        3 |     73.1
(1 row)

 wal_rows_in_the_io_view 
-------------------------
                       0
(1 row)

Sixty-one thousand log records, six hundred and forty-six writes, three syncs and seventy-three milliseconds of write time, all belonging to the insert that ran between the reset and the read. The last line is the other half of the story: on 17 the I/O view has no rows for the log at all, so there is nowhere else for any of this to be hiding and one reset call is sufficient by construction.

The same routine on 18

Here the counters in both places are cleared, the same load runs, and both places are read.

SELECT pg_stat_reset_shared('wal');
SELECT pg_stat_reset_shared('io');
INSERT INTO shipment_events (detail) SELECT repeat('e', 250) FROM generate_series(1, 30000);
SELECT pg_sleep(1);
SELECT wal_records, wal_buffers_full FROM pg_stat_wal;
SELECT sum(writes) AS wal_writes, sum(fsyncs) AS wal_fsyncs,
       round(sum(write_time)::numeric, 1) AS write_ms
FROM pg_stat_io WHERE object = 'wal';

 pg_stat_reset_shared 
----------------------
 
(1 row)

 pg_stat_reset_shared 
----------------------
 
(1 row)

INSERT 0 30000
 pg_sleep 
----------
 
(1 row)

 wal_records | wal_buffers_full 
-------------+------------------
       60995 |              117
(1 row)

 wal_writes | wal_fsyncs | write_ms 
------------+------------+----------
        123 |          5 |    100.6
(1 row)

The same load generates the same sixty-one thousand records, which is reassuring and is the one number that means the same thing on both versions. Everything else has moved.

Now the part that matters. Reset only the log counters, as the old routine does, and read both places again.

SELECT pg_stat_reset_shared('wal');
SELECT pg_sleep(1);
SELECT wal_records, wal_buffers_full FROM pg_stat_wal;
SELECT sum(writes) AS wal_writes, sum(fsyncs) AS wal_fsyncs,
       round(sum(write_time)::numeric, 1) AS write_ms
FROM pg_stat_io WHERE object = 'wal';

 pg_stat_reset_shared 
----------------------
 
(1 row)

 pg_sleep 
----------
 
(1 row)

 wal_records | wal_buffers_full 
-------------+------------------
           0 |                0
(1 row)

 wal_writes | wal_fsyncs | write_ms 
------------+------------+----------
        123 |          5 |    100.6
(1 row)

The record count and the buffer-full counter went to zero. The write count, the sync count and the write time did not move at all. They are exactly what they were before the reset, because the reset did not touch them and nothing said so.

Clearing the other argument does clear them.

SELECT pg_stat_reset_shared('io');
SELECT pg_sleep(1);
SELECT sum(writes) AS wal_writes, sum(fsyncs) AS wal_fsyncs
FROM pg_stat_io WHERE object = 'wal';
SELECT stats_reset IS NOT NULL AS wal_view_has_a_reset_stamp FROM pg_stat_wal;

 pg_stat_reset_shared 
----------------------
 
(1 row)

 pg_sleep 
----------
 
(1 row)

 wal_writes | wal_fsyncs 
------------+------------
          0 |          0
(1 row)

 wal_view_has_a_reset_stamp 
----------------------------
 t
(1 row)

Why this one hurts more than it looks

Three reasons, in increasing order of how long they take to notice.

The first is the obvious one. A nightly job that clears the log counters so that the morning report covers one day now produces a report where the record count covers one day and the write and sync timing covers every day since the server started. Both figures appear in the same table, under the same heading, with no marker between them. Nobody reading that report has any way to tell.

The second is subtler and is about ratios rather than totals. Writes per record, or milliseconds of write time per megabyte of log, are the derived numbers worth watching, because they are the ones that change when the storage changes rather than when the workload does. Computing either from one cleared counter and one uncleared counter produces a ratio that drifts steadily towards zero as the uptime grows, which looks exactly like a slow degradation and is entirely an artefact.

The third is that the reset stamp does not help. Each view carries the time it was last cleared, and after the sequence above the log view has one, so a reader checking whether the counters were reset gets a yes. The stamp is per view, and the view being asked is the one that was actually reset.

There is a fourth consideration which is not about the bug but about the arithmetic, and it is worth stating because people try it. The write count in the new location is not the old write count under a different name. The measurements above are a hundred and twenty-three writes on 18 against six hundred and forty-six on 17 for the same load, because the log is now written in larger operations for the same reason reads are. The sum of the new rows is not the old counter, and a series that carries across the upgrade unchanged reports an improvement nobody made.

What to do about it

• Audit every call to the reset function in cron jobs, runbooks and scripts. On 18 a routine that wants the log counters cleared has to clear both arguments, and a routine that clears only the I/O argument now also clears every relation and temporary-relation counter on the cluster, which is a wider blast radius than its author intended.
• Prefer not resetting. Two reads and a subtraction is more code than one reset and one read, and it has the considerable advantage of not destroying a number that something else might be reading. A reset is a write to shared state on a cluster that other people are watching.
• If you do reset, read the stamp on every view you draw from and put it on the report. A report that says which window each figure covers is one where this class of mistake is visible instead of invisible.

Finding out whether you already have this problem

A cluster that has been on 18 for a few weeks may already be reporting a mixed window, and the question of whether it is has a direct answer.

Both views carry a reset stamp. Read them together. If the log view was cleared last night and the I/O view carries a stamp from the last restart, or no stamp at all, then every timing figure on the report covers the whole uptime and every volume figure covers one night. That check takes one query and it is worth building into whatever produces the report rather than running once, because the failure reappears the next time somebody adds a reset to a script.

The second symptom is the one people notice first without recognising it. Write time per record, or per megabyte, falling steadily and smoothly over weeks, with no corresponding change in latency anywhere else, is almost always this. A real storage improvement arrives as a step when something changes. An artefact of a growing denominator arrives as a curve.

The third check is arithmetic. Milliseconds of write time can never exceed the elapsed time of the window they are supposed to cover, multiplied by however many processes could have been writing at once. A figure that implies more write time than the window contains is a figure from a longer window, and that comparison is cheap to automate and catches the problem without knowing anything about the views involved.

The replacement routine, for anything that used to reset before measuring, is two reads and a subtraction with the window recorded explicitly. It is more code. It also composes: two teams can measure overlapping windows on the same cluster without interfering with each other, which a reset has never allowed.

One more consequence, for anyone building a dashboard from scratch

The split has a second effect that is not about resets at all and is easy to meet while fixing the first one. The log counters are now spread across two views with different shapes, and joining them is not possible in any meaningful sense.

The view that kept the record and byte counters has exactly one row. The I/O view has a row per process type, so the log writes are divided among the checkpointer, the log writer and whichever client backends were forced to write the log themselves before they could continue. Summing those rows gets you a total comparable to the old counter. Not summing them gets you something much more useful, because a log write done by a client backend is a backend that had to stop and wait, and a log write done by the log writer is the server doing its job in the background. Those were the same number before this release and are different numbers now.

The practical shape is that a panel showing log volume stays as one series, and a panel showing log write activity should become three. The second is more work and it is the one that answers the question people actually ask about the write-ahead log, which is whether it is making the application wait.

What it costs

Nothing here needs a restart, an extension or a setting. The reset function is available to a superuser and to roles granted the relevant monitoring privileges, and it takes effect immediately rather than on the next statistics flush.

The one setting in the neighbourhood is the write-ahead log timing switch, which gates the time columns in the new location and is off by default. Its scope narrowed with the move: it now governs the log rows of the I/O view rather than columns of the log view, and the general I/O timing setting governs everything else. Enabling one and reading the other is the most common way to conclude that the new accounting does not work, and both can be changed with a reload.