Re: pgsql: Add TAP tests for timeouts

On Fri, Mar 15, 2024 at 9:44 AM Michael Paquier <michael(at)paquier(dot)xyz> wrote:
> On Fri, Mar 15, 2024 at 11:20:49AM +0500, Andrey M. Borodin wrote:
> > And hachi sometimes pass this test too [0].
> >
> > I’ll look more on this. Do I understand right that we have only 2
buildfarm members with injection points?
>
> I have added --enable-injection-points to three of them: hachi,
> gokiburi and batta. The switch is also enabled in the CI by defaultm
> where you may be able to capture a bit more information than the
> buildfarm.

I managed to reproduce the issue locally by setting the following extra
config via TEMP_CONFIG:

log_line_prefix = '%m [%p:%l] %q%a '
log_connections = 'true'
log_disconnections = 'true'
log_checkpoints = 'true'
log_statement = 'all'
wal_compression = 'on'
debug_parallel_query = regress
wal_compression = lz4
default_toast_compression = lz4

The backtrace is as follows. We loop in the interrupt checking, given that
the injection point handler checks for interrupts internally. I propose to
unset the timeout flag before the injection point (see the attached patch).

* thread #1, name = 'postgres', stop reason = signal SIGSTOP
* frame #0: 0x00007f3756f289e7 libc.so.6`epoll_wait(epfd=9,
events=0x0000556a302cabc8, maxevents=1, timeout=-1) at epoll_wait.c:30:10
frame #1: 0x0000556a2fc41aab postgres`WaitEventSetWait at latch.c:1570:7
frame #2: 0x0000556a2fc41e95 postgres`WaitLatch(latch=<unavailable>,
wakeEvents=<unavailable>, timeout=<unavailable>, wait_event_info=117440513)
at latch.c:538:6
frame #3: 0x0000556a2fc4f611
postgres`ConditionVariableTimedSleep(cv=0x00007f3757b0e224, timeout=-1,
wait_event_info=117440513) at condition_variable.c:163:10
frame #4: 0x00007f3757b10628 injection_points.so`injection_wait at
injection_points.c:153:3
frame #5: 0x0000556a2fdd4f54 postgres`InjectionPointRun at
injection_point.c:313:2
frame #6: 0x0000556a2fc6a8b3 postgres`ProcessInterrupts.part.0 at
postgres.c:3430:4
frame #7: 0x0000556a2fc4f70b
postgres`ConditionVariableTimedSleep(cv=0x00007f3757b0e224, timeout=-1,
wait_event_info=117440513) at condition_variable.c:196:3
frame #8: 0x00007f3757b10628 injection_points.so`injection_wait at
injection_points.c:153:3
frame #9: 0x0000556a2fdd4f54 postgres`InjectionPointRun at
injection_point.c:313:2
frame #10: 0x0000556a2fc6a8b3 postgres`ProcessInterrupts.part.0 at
postgres.c:3430:4
frame #11: 0x0000556a2fc4f70b
postgres`ConditionVariableTimedSleep(cv=0x00007f3757b0e224, timeout=-1,
wait_event_info=117440513) at condition_variable.c:196:3
frame #12: 0x00007f3757b10628 injection_points.so`injection_wait at
injection_points.c:153:3
frame #13: 0x0000556a2fdd4f54 postgres`InjectionPointRun at
injection_point.c:313:2
frame #14: 0x0000556a2fc6a8b3 postgres`ProcessInterrupts.part.0 at
postgres.c:3430:4
frame #15: 0x0000556a2fabe63d postgres`ExecGather at nodeGather.c:315:3
frame #16: 0x0000556a2fabe574 postgres`ExecGather at nodeGather.c:269:10
frame #17: 0x0000556a2fabe549
postgres`ExecGather(pstate=0x0000556a303d8138) at nodeGather.c:222:9
frame #18: 0x0000556a2faa21da postgres`standard_ExecutorRun at
executor.h:274:9
frame #19: 0x0000556a2fc6f3cf postgres`PortalRunSelect at pquery.c:924:4
frame #20: 0x0000556a2fc70b7e postgres`PortalRun at pquery.c:768:18
frame #21: 0x0000556a2fc6c996 postgres`exec_simple_query at
postgres.c:1274:10
frame #22: 0x0000556a2fc6e378 postgres`PostgresMain at postgres.c:4682:7
frame #23: 0x0000556a2fbcefa0 postgres`ServerLoop.isra.0 at
postmaster.c:4452:2
frame #24: 0x0000556a2fbcff8b postgres`PostmasterMain at
postmaster.c:1478:11
frame #25: 0x0000556a2f8cb5a7 postgres`main(argc=4,
argv=0x0000556a302ca340) at main.c:197:3
frame #26: 0x00007f3756e28150
libc.so.6`__libc_start_call_main(main=(postgres`main at main.c:59:1),
argc=4, argv=0x00007ffffc17e678) at libc_start_call_main.h:58:16
frame #27: 0x00007f3756e28209
libc.so.6`__libc_start_main_impl(main=(postgres`main at main.c:59:1),
argc=4, argv=0x00007ffffc17e678, init=<unavailable>, fini=<unavailable>,
rtld_fini=<unavailable>, stack_end=0x00007ffffc17e668) at libc-start.c:360:3
frame #28: 0x0000556a2f8cbb75 postgres`_start + 37

------
Regards,
Alexander Korotkov