pg19b1: TRAP: failed Assert("pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)")

While restoring from backup to v19, I hit a crash adding a unique
constraint, since 999dec9ec6a "aio: Don't wait for already in-progress
IO."

The crash is not consistent, and I don't have an easy reproducer, but I
can tell you that the crash involves the counts<=0 case, with
IOOBJECT_RELATION / IOCONTEXT_NORMAL / IOOP_READ, and depends on
maintenance_work_mem=512MB and track_io_timing=1, and always seems to
happens in a parallel worker.

LOG: background worker "parallel worker" (PID 1475078) was terminated by
signal 6: Aborted
DETAIL: Failed process was running: ALTER TABLE ONLY
public.counter_latest_data
ADD CONSTRAINT counter_latest_data_counter_id_site_id_key
UNIQUE (counter_id, site_id);
ALTER TABLE public.counter_latest_data CLUSTER ON
counter_latest_data_counter_id_site_id_key;

(gdb) bt
#0 __pthread_kill_implementation (threadid=<optimized out>,
signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1 0x00007f28d65d49ff in __pthread_kill_internal (threadid=<optimized
out>, signo=6) at ./nptl/pthread_kill.c:89
#2 0x00007f28d657fcc2 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#3 0x00007f28d65684ac in __GI_abort () at ./stdlib/abort.c:73
#4 0x00005596eca9bec6 in ExceptionalCondition
(conditionName=conditionName@entry=0x5596ecc47230
"pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)",
fileName=fileName@entry=0x5596ecc471d8
"../postgresql/src/backend/utils/activity/pgstat_io.c",
lineNumber=lineNumber@entry=228) at
../postgresql/src/backend/utils/error/assert.c:65
#5 0x00005596ec979b6d in pgstat_io_flush_cb (nowait=<optimized out>) at
../postgresql/src/backend/utils/activity/pgstat_io.c:228
#6 0x00005596ec9758ba in pgstat_report_stat (force=force@entry=true) at
../postgresql/src/backend/utils/activity/pgstat.c:810
#7 0x00005596ec975a9c in pgstat_shutdown_hook (code=<optimized out>,
arg=<optimized out>) at
../postgresql/src/backend/utils/activity/pgstat.c:646
#8 0x00005596ec92e901 in shmem_exit (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:250
#9 0x00005596ec92ea74 in proc_exit_prepare (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:199
#10 0x00005596ec92eb2e in proc_exit (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:112
#11 0x00005596ec89f2f0 in BackgroundWorkerMain (startup_data=<optimized
out>, startup_data_len=<optimized out>) at
../postgresql/src/backend/postmaster/bgworker.c:853
#12 0x00005596ec8a1a4d in postmaster_child_launch
(child_type=child_type@entry=B_BG_WORKER, child_slot=239,
startup_data=startup_data@entry=0x55972a7244d8,
startup_data_len=startup_data_len@entry=1472,
client_sock=client_sock@entry=0x0) at
../postgresql/src/backend/postmaster/launch_backend.c:263
#13 0x00005596ec8a34bd in StartBackgroundWorker (rw=0x55972a7244d8) at
../postgresql/src/backend/postmaster/postmaster.c:4176
#14 maybe_start_bgworkers () at
../postgresql/src/backend/postmaster/postmaster.c:4341
#15 0x00005596ec8a4e05 in LaunchMissingBackgroundProcesses () at
../postgresql/src/backend/postmaster/postmaster.c:3416
#16 ServerLoop () at ../postgresql/src/backend/postmaster/postmaster.c:1728
#17 0x00005596ec8a7257 in PostmasterMain (argc=argc@entry=12,
argv=argv@entry=0x55972a6a0ec0) at
../postgresql/src/backend/postmaster/postmaster.c:1403
#18 0x00005596ec5cbd1c in main (argc=12, argv=0x55972a6a0ec0) at
../postgresql/src/backend/main/main.c:231

--
Justin

I think the assert in pgstat_io_flush_cb() after 999dec9ec6a comes from IO
stats on the foreign IO path.
When AsyncReadBuffers() finds IO already in progress, it sets foreign_io
and returns without counting a read. But WaitReadBuffers() still calls:
```
pgstat_count_io_op_time(..., IOOP_READ, io_start, 0, 0);
```
The comment there assumes the read was already counted in
AsyncReadBuffers(). That holds for IO we started ourselves, but not when
we're waiting on another backend's IO. With track_io_timing = on, we get
non-zero IOOP_READ time and zero count, and pgstat_bktype_io_stats_valid()
trips on backend exit.

fix proposal:
```
-                               pgstat_count_io_op_time(io_object,
io_context, IOOP_READ,
-
io_start, 0, 0);
+                               if (!operation->foreign_io)
+                                       pgstat_count_io_op_time(io_object,
io_context, IOOP_READ,
+
io_start, 0, 0);
```

ср, 8 июл. 2026 г. в 19:58, Justin Pryzby <pryzby@telsasoft.com>:

While restoring from backup to v19, I hit a crash adding a unique
constraint, since 999dec9ec6a "aio: Don't wait for already in-progress
IO."

The crash is not consistent, and I don't have an easy reproducer, but I
can tell you that the crash involves the counts<=0 case, with
IOOBJECT_RELATION / IOCONTEXT_NORMAL / IOOP_READ, and depends on
maintenance_work_mem=512MB and track_io_timing=1, and always seems to
happens in a parallel worker.

LOG: background worker "parallel worker" (PID 1475078) was terminated by
signal 6: Aborted
DETAIL: Failed process was running: ALTER TABLE ONLY
public.counter_latest_data
ADD CONSTRAINT counter_latest_data_counter_id_site_id_key
UNIQUE (counter_id, site_id);
ALTER TABLE public.counter_latest_data CLUSTER ON
counter_latest_data_counter_id_site_id_key;

(gdb) bt
#0 __pthread_kill_implementation (threadid=<optimized out>,
signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1 0x00007f28d65d49ff in __pthread_kill_internal (threadid=<optimized
out>, signo=6) at ./nptl/pthread_kill.c:89
#2 0x00007f28d657fcc2 in __GI_raise (sig=sig@entry=6) at
../sysdeps/posix/raise.c:26
#3 0x00007f28d65684ac in __GI_abort () at ./stdlib/abort.c:73
#4 0x00005596eca9bec6 in ExceptionalCondition
(conditionName=conditionName@entry=0x5596ecc47230
"pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)",
fileName=fileName@entry=0x5596ecc471d8
"../postgresql/src/backend/utils/activity/pgstat_io.c",
lineNumber=lineNumber@entry=228) at
../postgresql/src/backend/utils/error/assert.c:65
#5 0x00005596ec979b6d in pgstat_io_flush_cb (nowait=<optimized out>) at
../postgresql/src/backend/utils/activity/pgstat_io.c:228
#6 0x00005596ec9758ba in pgstat_report_stat (force=force@entry=true) at
../postgresql/src/backend/utils/activity/pgstat.c:810
#7 0x00005596ec975a9c in pgstat_shutdown_hook (code=<optimized out>,
arg=<optimized out>) at
../postgresql/src/backend/utils/activity/pgstat.c:646
#8 0x00005596ec92e901 in shmem_exit (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:250
#9 0x00005596ec92ea74 in proc_exit_prepare (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:199
#10 0x00005596ec92eb2e in proc_exit (code=code@entry=0) at
../postgresql/src/backend/storage/ipc/ipc.c:112
#11 0x00005596ec89f2f0 in BackgroundWorkerMain (startup_data=<optimized
out>, startup_data_len=<optimized out>) at
../postgresql/src/backend/postmaster/bgworker.c:853
#12 0x00005596ec8a1a4d in postmaster_child_launch
(child_type=child_type@entry=B_BG_WORKER, child_slot=239,
startup_data=startup_data@entry=0x55972a7244d8,
startup_data_len=startup_data_len@entry=1472,
client_sock=client_sock@entry=0x0) at
../postgresql/src/backend/postmaster/launch_backend.c:263
#13 0x00005596ec8a34bd in StartBackgroundWorker (rw=0x55972a7244d8) at
../postgresql/src/backend/postmaster/postmaster.c:4176
#14 maybe_start_bgworkers () at
../postgresql/src/backend/postmaster/postmaster.c:4341
#15 0x00005596ec8a4e05 in LaunchMissingBackgroundProcesses () at
../postgresql/src/backend/postmaster/postmaster.c:3416
#16 ServerLoop () at
../postgresql/src/backend/postmaster/postmaster.c:1728
#17 0x00005596ec8a7257 in PostmasterMain (argc=argc@entry=12,
argv=argv@entry=0x55972a6a0ec0) at
../postgresql/src/backend/postmaster/postmaster.c:1403
#18 0x00005596ec5cbd1c in main (argc=12, argv=0x55972a6a0ec0) at
../postgresql/src/backend/main/main.c:231

--
Justin

Thanks, Justin, for the report

On Thu, Jul 16, 2026 at 11:03 AM Andrey Rachitskiy <pl0h0yp1@gmail.com>
wrote:

With track_io_timing=on, foreign IO wait time is currently recorded:

when WaitReadBuffers() waits on foreign_io, it calls
pgstat_count_io_op_time() with cnt=0. So we do write non-zero IOOP_READ
time into this backend's pending pg_stat_io stats, without incrementing the
read count in this backend.

Thus, this fix introduces a real change: it disables recording foreign

IO wait time in pg_stat_io statistics for the backend that is performing
the wait.

What we lose is only that wait time. The initiating backend still

records the read count and its own IO time, and the waiting backend still
records a buffer hit once the IO completes.

Yea, so, I don't think we can just not record the wait time for
foreign IOs. For asynchronous reads, read time in pg_stat_io is almost
entirely wait time. That's also why it doesn't make sense to have a
separate IOOP_WAIT -- unless we start measuring and displaying read
latency (how long the actual reads took) in pg_stat_io and then you
could separate that from wait time.

My first thought is that we should relax the restriction in
pgstat_bktype_io_stats_valid() that requires non-zero counts if time
is non-zero. But that seems silly: 1) we lose lots of validation for
cases where this would be bogus and 2) anyone looking at the view that
seems non-zero IO time and 0 count will be very confused and 3) it
makes any math dividing read time by read operations meaningless
(though I don't know how meaningful that is now).

If read time is truly just wait time, we could just pass
pg_stat_count_io_op_time() a count of 1 for foreign IO in
WaitReadBuffers(). In 19, we should likely either do this or do as
Andrey suggested and not count the wait time for foreign IOs.

For master, I'd like to do something more satisfying, but I'm not sure
what.

It did get me thinking that there is 0 way for the user (or developer)
to know about foreign IOs. Maybe that's okay...?

- Melanie

Hi,

On 2026-07-16 15:59:12 -0400, Melanie Plageman wrote:

Thanks, Justin, for the report

On Thu, Jul 16, 2026 at 11:03 AM Andrey Rachitskiy <pl0h0yp1@gmail.com>

wrote:

With track_io_timing=on, foreign IO wait time is currently recorded:

when WaitReadBuffers() waits on foreign_io, it calls
pgstat_count_io_op_time() with cnt=0. So we do write non-zero IOOP_READ
time into this backend's pending pg_stat_io stats, without incrementing the
read count in this backend.

Thus, this fix introduces a real change: it disables recording foreign

IO wait time in pg_stat_io statistics for the backend that is performing
the wait.

What we lose is only that wait time. The initiating backend still

records the read count and its own IO time, and the waiting backend still
records a buffer hit once the IO completes.

Yea, so, I don't think we can just not record the wait time for
foreign IOs.

Agreed.

For asynchronous reads, read time in pg_stat_io is almost entirely wait
time.

Right. And for some workloads a decent percentage of the waits can be due
to
foreign IOs (often started by ourselves). That's particularly true once
index
readahead goes in.

That's also why it doesn't make sense to have a separate IOOP_WAIT --

unless

we start measuring and displaying read latency (how long the actual reads
took) in pg_stat_io and then you could separate that from wait time.

My main problem with IOOP_WAIT would be that it would conflate waiting for
different IO operations. Read, write, fsync latencies can be wildly
different...

My first thought is that we should relax the restriction in
pgstat_bktype_io_stats_valid() that requires non-zero counts if time
is non-zero.

I think that may be the way. There's other places where that assertion
causes
us to track less well than we otherwise could:

/*
* We must get an IO handle before StartBufferIO(), as
pgaio_io_acquire()
* might block, which we don't want after setting IO_IN_PROGRESS.
If we
* don't need to do the IO, we'll release the handle.
*
* If we need to wait for IO before we can get a handle, submit
* already-staged IO first, so that other backends don't need to
wait.
* There wouldn't be a deadlock risk, as pgaio_io_acquire() just
needs to
* wait for already submitted IO, which doesn't require additional
locks,
* but it could still cause undesirable waits.
*
* A secondary benefit is that this would allow us to measure the
time in
* pgaio_io_acquire() without causing undue timer overhead in the
common,
* non-blocking, case. However, currently the pgstats
infrastructure
* doesn't really allow that, as it a) asserts that an operation
can't
* have time without operations b) doesn't have an API to report
* "accumulated" time.
*/

The a) in the last paragraph in particular.

But that seems silly: 1) we lose lots of validation for cases where this
would be bogus

But how likely is that actually going to be a problem?

Perhaps we should add a separate function that explicitly just counts
timing
(no operation count), and only allow that one to work with a 0 operations
count?

and 2) anyone looking at the view that seems non-zero IO time and 0 count
will be very confused

But I don't think you would really see that - normally the IO count will
have
been increemented by another operation.

and 3) it makes any math dividing read time by read operations

meaningless

(though I don't know how meaningful that is now).

Hm. The fix for that is to write read_time / NULLIF(reads, 0). But it's
somewhat annoying to have to know to do that, as it will be quite rare to
encounter cases where just the wait time, but no operation count will have
been reported. At least for pg_stat_io, I guess pg_stat_get_backend_io()
will
make it a bit more common.

But I just don't really see an alternative.

If read time is truly just wait time

It's not always that way. For a fast IO subsystem with a deep enough queue
most of the time will actually be in the submission path (since that's
where
you trigger interrupts and do kernel work like identifying the disk block
the
requested data is on etc).

we could just pass pg_stat_count_io_op_time() a count of 1 for foreign

IO in

WaitReadBuffers(). In 19, we should likely either do this or do as Andrey
suggested and not count the wait time for foreign IOs.

For master, I'd like to do something more satisfying, but I'm not sure

what.

I think medium term we might need to redesign where the pg_stat_io
accounting
happens. Not primarily because of this, but because there's at the moment
sources of waits that are not properly accounted.

Consider e.g. this:
- io_max_concurrency=32
- some read stream starts 32 reads
- another part of the query tries to do a single AIO write
- that needs to do a blocking pgaio_io_acquire(), as there are no unused
handles
- as part of that, pgaio_io_acquire() will wait on the oldest in-flight
IO,
which was a read

Today the wait time for that (as explained in the comment above) is
unattributed. If we were to account it were the comment suggests, we'd
attribute it to the *write*, even though the waiting is actually unrelated
to
the write itself, its waiting for some old read to finish.

The same thing could happen with reads that fall into different contexts,
e.g. we could end up attributing waits triggered by relation/bulkread to
relation/normal, just because the bulkread filled up the queue.

Now, some fuzziness here is fundamental. Having N IOs in the queue before
an
additional IO X will increase the latency of X. If we only wait for X, not
for
any of the earlier IOs, the latency of those other IOs will be attributed
to X
to some degree. But I feel the case of waiting for specific earlier IOs to
complete is different, as that's not an indirect increase in latency due to
deeper queues, it's directly waiting for other IO operations - and those
other
IO operations might be much higher latency ones (the most extreme case is
probably io_max_concurrency fsyncs queued when trying to start a small
read).

So a larger refactoring could be to add something like
pgstat_io_set_stats_target(), which would then allow the pgstat reporting
to
happen within the AIO subsystem.

It did get me thinking that there is 0 way for the user (or developer)
to know about foreign IOs. Maybe that's okay...?

I think it may be OK, we historically have not exposed having to wait in
StartBufferIO() when the buffer is undergoing IO in another backend either.

It's not entirely clear what the alternative is either. One relatively easy
thing we could do is to have more separated out wait events. E.g.:

1) a direct wait for IO started by the current backend

2) a direct wait for an IO started by another backend

3) a wait for an IO started by the current backend, but as part of
acquiring
an IO handle.

4) a wait as part of pgaio_closing_fd()

5) a wait as part of pgaio_shutdown()

With possible subdivisions for 1), to separate out "foreign" IOs that have
been started by the current backend from plain waits on the IO itself. But
that's a bit of a weird division, because for the AIO subsystem there's
zero
difference between those cases.

It's not entirely trivial to introduce that separation, because
pgaio_io_wait() already has different wait events, because you may need to
wait for the IO to actually complete (WAIT_EVENT_AIO_IO_URING_EXECUTION) or
you may need to wait for another backend to execute the IO completion
(WAIT_EVENT_AIO_IO_COMPLETION).

Which is not helped by WAIT_EVENT_AIO_IO_COMPLETION covering different
things
for different IO methods. For io_uring it will just be used when the kernel
has executed the IO, but the callback hasn't yet been executed, whereas for
sync/worker modes, it'll be used for the entire IO duration.

Greetings,

Andres Freund