Re: pgsql: Add TAP tests for timeouts

On Fri, Mar 15, 2024 at 9:44 AM Michael Paquier <michael@paquier.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