Re: pg19b1: TRAP: failed Assert("pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)") - Mailing list pgsql-hackers
| From | Andrey Rachitskiy |
|---|---|
| Subject | Re: pg19b1: TRAP: failed Assert("pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)") |
| Date | |
| Msg-id | CAB8bMisd2y+R5PdiAh8+BgEV2xRZyWw7dJ4swwViKUh3gt3GXw@mail.gmail.com Whole thread |
| In response to | Re: pg19b1: TRAP: failed Assert("pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)") (Andrey Rachitskiy <pl0h0yp1@gmail.com>) |
| Responses |
Re: pg19b1: TRAP: failed Assert("pgstat_bktype_io_stats_valid(bktype_shstats, MyBackendType)")
|
| List | pgsql-hackers |
Still reproduced on the master branch.
A bit more on what the proposed fix changes.
A bit more on what the proposed fix changes.
```
diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index 3908529872a..e2f209b8ec7 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -1831,9 +1831,12 @@ WaitReadBuffers(ReadBuffersOperation *operation)
/*
* The IO operation itself was already counted earlier, in
* AsyncReadBuffers(), this just accounts for the wait time.
+ * For foreign IO, the read was counted by another backend,
+ * so skip reporting wait time here.
*/
- 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);
}
else
{
index 3908529872a..e2f209b8ec7 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -1831,9 +1831,12 @@ WaitReadBuffers(ReadBuffersOperation *operation)
/*
* The IO operation itself was already counted earlier, in
* AsyncReadBuffers(), this just accounts for the wait time.
+ * For foreign IO, the read was counted by another backend,
+ * so skip reporting wait time here.
*/
- 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);
}
else
{
```
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.
The current behavior is also not a reliable metric: the wait time is merged into the shared per-BackendType pg_stat_io bucket (B_BG_WORKER for parallel workers), and only remains valid if the initiating backend has already flushed its read count. Otherwise, pgstat_bktype_io_stats_valid() trips on backend exit — which is the bug we're seeing.
So the fix trades a partial and crash-prone statistic for correctness. A fuller solution would need separate support for accumulated wait time, as already noted in a comment near AsyncReadBuffers().
```
if (operation->foreign_io)
pgstat_count_io_op_time(io_object, io_context, IOOP_WAIT, io_start, 1, 0);
else
pgstat_count_io_op_time(io_object, io_context, IOOP_READ, io_start, 0, 0);
```
This would properly account for foreign wait time without breaking stats consistency, but would require extending pg_stat_io to support a new operation type. The current fix takes a simpler approach: it drops the foreign wait time entirely, accepting the loss of this metric in exchange for stability.
---
Regards,
Rachitskiy Andrey
ср, 8 июл. 2026 г. в 20:26, Andrey Rachitskiy <pl0h0yp1@gmail.com>:
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
pgsql-hackers by date: