alinux Create CRIU checkpoint image and restore three times - testMillisDelayBeforeCheckpointDone timeout

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_1/415 - ubu22-aarch64-4
23:33:15 cmdLineTester_criu_nonPortableRestore_0
23:33:15 cmdLineTester_criu_nonPortableRestore_1
23:33:15 cmdLineTester_criu_nonPortableRestore_4
23:33:15 cmdLineTester_criu_nonPortableRestore_6
23:33:15 cmdLineTester_criu_nonPortableRestore_8
23:33:15 cmdLineTester_criu_nonPortableRestoreJDK11Up_3

19:42:14  Testing: Create CRIU checkpoint image and restore three times - testMillisDelayBeforeCheckpointDone
19:42:14  Test start time: 2025/02/20 00:42:13 Coordinated Universal Time
19:42:14  Running command: bash /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java " -Xjit -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-747}" org.openj9.criu.TimeChangeTest testMillisDelayBeforeCheckpointDone 3 false true
19:42:14  Time spent starting: 9 milliseconds
19:47:21  ***[TEST INFO 2025/02/20 00:47:13] ProcessKiller detected a timeout after 300000 milliseconds!***
19:47:21  ***[TEST INFO 2025/02/20 00:47:13] executing /usr/bin/gdb -batch -x /tmp/debugger4140790850777354940.txt bash 823872***
19:47:21  GDB OUT [Thread debugging using libthread_db enabled]
19:47:21  GDB OUT Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1".
19:47:21  GDB OUT 0x0000ffff8d6f67b4 in __GI___wait4 (pid=-1, stat_loc=0xfffff5c9f600, options=0, usage=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
19:47:21  GDB OUT From                To                  Syms Read   Shared Object Library
19:47:21  GDB OUT 0x0000ffff8d7fd9b0  0x0000ffff8d80cde8  Yes (*)     /lib/aarch64-linux-gnu/libtinfo.so.6
19:47:21  GDB OUT 0x0000ffff8d667040  0x0000ffff8d773090  Yes         /lib/aarch64-linux-gnu/libc.so.6
19:47:21  GDB OUT 0x0000ffff8d833c40  0x0000ffff8d8520a4  Yes         /lib/ld-linux-aarch64.so.1
19:47:21  GDB OUT (*): Shared library is missing debugging information.
19:47:21  GDB OUT x0             0xffffffffffffffff  -1
19:47:21  GDB OUT x1             0xfffff5c9f600      281474805396992
19:47:21  GDB OUT x2             0x0                 0
19:47:21  GDB OUT x3             0x0                 0
19:47:21  GDB OUT x4             0xffff8d830020      281473055916064
19:47:21  GDB OUT x5             0xaaaabe297e54      187650311552596
19:47:21  GDB OUT x6             0x1                 1
19:47:21  GDB OUT x7             0x8                 8
19:47:21  GDB OUT x8             0x104               260
19:47:21  GDB OUT x9             0x1                 1
19:47:21  GDB OUT x10            0xffffffffe3fa2fe0  -470143008
19:47:21  GDB OUT x11            0x0                 0
19:47:21  GDB OUT x12            0x1                 1
19:47:21  GDB OUT x13            0xd88133fd0ab6904   975050484130474244
19:47:21  GDB OUT x14            0x50                80
19:47:21  GDB OUT x15            0xaaaada283028      187650781229096
19:47:21  GDB OUT x16            0xaaaabe28ba48      187650311502408
19:47:21  GDB OUT x17            0xffff8d6f6750      281473054631760
19:47:21  GDB OUT x18            0x0                 0
19:47:21  GDB OUT x19            0x0                 0
19:47:21  GDB OUT x20            0xffffffffffffffff  -1
19:47:21  GDB OUT x21            0xaaaabe297000      187650311548928
19:47:21  GDB OUT x22            0xaaaabe295140      187650311541056
19:47:21  GDB OUT x23            0xffff8d8307e0      281473055918048
19:47:21  GDB OUT x24            0xaaaabe28c000      187650311503872
19:47:21  GDB OUT x25            0xaaaabe295e5c      187650311544412
19:47:21  GDB OUT x26            0xaaaabe28d464      187650311509092
19:47:21  GDB OUT x27            0x0                 0
19:47:21  GDB OUT x28            0x0                 0
19:47:21  GDB OUT x29            0xfffff5c9f530      281474805396784
19:47:21  GDB OUT x30            0xaaaabe23548c      187650311148684
19:47:21  GDB OUT sp             0xfffff5c9f530      0xfffff5c9f530
19:47:21  GDB OUT pc             0xffff8d6f67b4      0xffff8d6f67b4 <__GI___wait4+52>
19:47:21  GDB OUT cpsr           0x60001000          [ EL=0 BTYPE=0 SSBS C Z ]
19:47:21  GDB OUT fpsr           0x0                 [ ]
19:47:21  GDB OUT fpcr           0x0                 [ RMode=0 ]
19:47:21  GDB OUT   Id   Target Id                                 Frame 
19:47:21  GDB OUT * 1    Thread 0xffff8d830020 (LWP 823872) "bash" 0x0000ffff8d6f67b4 in __GI___wait4 (pid=-1, stat_loc=0xfffff5c9f600, options=0, usage=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
19:47:21  GDB OUT 
19:47:21  GDB OUT Thread 1 (Thread 0xffff8d830020 (LWP 823872) "bash"):
19:47:21  GDB OUT #0  0x0000ffff8d6f67b4 in __GI___wait4 (pid=-1, stat_loc=0xfffff5c9f600, options=0, usage=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
19:47:21  GDB OUT         _x2tmp = <optimized out>
19:47:21  GDB OUT         _x0tmp = -1
19:47:21  GDB OUT         _x0 = -1
19:47:21  GDB OUT         _x2 = 0
19:47:21  GDB OUT         _x8 = 260
19:47:21  GDB OUT         _x3tmp = 0
19:47:21  GDB OUT         _x1tmp = 281474805396992
19:47:21  GDB OUT         _x1 = 281474805396992
19:47:21  GDB OUT         _x3 = 0
19:47:21  GDB OUT         _sys_result = <optimized out>
19:47:21  GDB OUT         sc_ret = <optimized out>
19:47:21  GDB OUT         sc_ret = <optimized out>
19:47:21  GDB OUT #1  0x0000aaaabe23548c in ?? ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT #2  0x0000aaaabe198b30 in wait_for ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT #3  0x0000aaaabe180e8c in execute_command_internal ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT #4  0x0000aaaabe1816ec in execute_command ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT #5  0x0000aaaabe17174c in reader_loop ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT #6  0x0000aaaabe164230 in main ()
19:47:21  GDB OUT No symbol table info available.
19:47:21  GDB OUT Saved corefile core.823872.1
19:47:21  GDB OUT [Inferior 1 (process 823872) detached]
19:47:21  INFO: Running '/usr/bin/gdb' failed with rc = 1
19:47:21  GDB ERR 30	../sysdeps/unix/sysv/linux/wait4.c: No such file or directory.
19:47:21  GDB ERR warning: target file /proc/823872/cmdline contained unexpected null characters
19:47:21  GDB ERR warning: Memory read failed for corefile section, 61440 bytes at 0xffff8d7c8000.
19:47:21  GDB ERR warning: Memory read failed for corefile section, 61440 bytes at 0xffff8d81c000.
19:47:21  GDB ERR warning: Memory read failed for corefile section, 8192 bytes at 0xffff8d869000.
19:47:21  GDB ERR /tmp/debugger4140790850777354940.txt:6: Error in sourced command file:
19:47:21  GDB ERR Requires argument (inferior id(s) to detach)

[pshipton]

@JasonFengJ9 @tajila fyi

[JasonFengJ9]

There were a couple of other timeout issues which seem similar

• cmdLineTester_criu_nonPortableRestore_FAILED test time out #17844
• Create CRIU checkpoint image and restore three times - testDateScheduledBeforeCheckpointDone timeout #18527

These timeouts were intermittent and didn't have a high reproducible rate.