Skip to content

cmdLineTester_criu_nonPortableRestore_FAILED test time out #17844

Open
@JasonFengJ9

Description

@JasonFengJ9

Failure link

From an internal build(rhel7lert-1-9):

java version "17.0.8" 2023-07-18
IBM Semeru Runtime Certified Edition 17.0.8.0-rc1 (build 17.0.8+7)
Eclipse OpenJ9 VM 17.0.8.0-rc1 (build v0.40.0-release-b681a676a, JRE 17 Linux ppc64le-64-Bit Compressed References 20230718_452 (JIT enabled, AOT enabled)
OpenJ9   - b681a676a
OMR      - e80bff83b
JCL      - ca817eae983 based on jdk-17.0.8+7)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2023-07-19T19:37:10.742Z] variation: -Xjit:count=0 -XX:+CRIURestoreNonPortableMode
[2023-07-19T19:37:10.742Z] JVM_OPTIONS:  -Xjit:count=0 -XX:+CRIURestoreNonPortableMode 

[2023-07-19T19:37:59.265Z] Testing: Create CRIU checkpoint image and restore three times - testMillisDelayBeforeCheckpointDone
[2023-07-19T19:37:59.265Z] Test start time: 2023/07/19 12:37:58 Pacific Standard Time
[2023-07-19T19:37:59.265Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode " "org.openj9.criu.TimeChangeTest testMillisDelayBeforeCheckpointDone" 3 3 false
[2023-07-19T19:37:59.265Z] Time spent starting: 3 milliseconds
[2023-07-19T19:43:05.473Z] ***[TEST INFO 2023/07/19 12:42:58] ProcessKiller detected a timeout after 300000 milliseconds!***
[2023-07-19T19:43:05.473Z] ***[TEST INFO 2023/07/19 12:42:59] executing /usr/bin/gdb -batch -x /tmp/debugger1074686980007286826.txt bash 23161***
[2023-07-19T19:43:05.473Z] GDB OUT 0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:43:05.473Z] GDB OUT From                To                  Syms Read   Shared Object Library
[2023-07-19T19:43:05.473Z] GDB OUT 0x00003fff8bd7cb20  0x00003fff8bd8d73c  Yes (*)     /lib64/libtinfo.so.5
[2023-07-19T19:43:05.473Z] GDB OUT 0x00003fff8bd40dc0  0x00003fff8bd423ec  Yes (*)     /lib64/libdl.so.2
[2023-07-19T19:43:05.473Z] GDB OUT 0x00003fff8bb71d00  0x00003fff8bcd7870  Yes (*)     /lib64/libc.so.6
[2023-07-19T19:43:05.473Z] GDB OUT 0x00003fff8bdf0d60  0x00003fff8be178cc  Yes (*)     /lib64/ld64.so.2
[2023-07-19T19:43:05.473Z] GDB OUT (*): Shared library is missing debugging information.
[2023-07-19T19:43:05.473Z] GDB OUT r0             0x7	7
[2023-07-19T19:43:05.473Z] GDB OUT r1             0x3fffc1dfae00	70367701872128
[2023-07-19T19:43:05.473Z] GDB OUT r2             0x3fff8bd37400	70366795101184
[2023-07-19T19:43:05.473Z] GDB OUT r3             0x200	512
[2023-07-19T19:43:05.473Z] GDB OUT r4             0x3fffc1dfae70	70367701872240
[2023-07-19T19:43:05.473Z] GDB OUT r5             0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r6             0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r7             0x10030080340	1100317459264
[2023-07-19T19:43:05.473Z] GDB OUT r8             0x1003007c1b0	1100317442480
[2023-07-19T19:43:05.473Z] GDB OUT r9             0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r10            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r11            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r12            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r13            0x3fff8be3b330	70366796165936
[2023-07-19T19:43:05.473Z] GDB OUT r14            0x1013b38c	269726604
[2023-07-19T19:43:05.473Z] GDB OUT r15            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r16            0x1013b380	269726592
[2023-07-19T19:43:05.473Z] GDB OUT r17            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r18            0x10130d40	269684032
[2023-07-19T19:43:05.473Z] GDB OUT r19            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r20            0x4	4
[2023-07-19T19:43:05.473Z] GDB OUT r21            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r22            0x1	1
[2023-07-19T19:43:05.473Z] GDB OUT r23            0x2	2
[2023-07-19T19:43:05.473Z] GDB OUT r24            0xffffffffffffffff	18446744073709551615
[2023-07-19T19:43:05.473Z] GDB OUT r25            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r26            0xffff	65535
[2023-07-19T19:43:05.473Z] GDB OUT r27            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT r28            0x1013b38c	269726604
[2023-07-19T19:43:05.473Z] GDB OUT r29            0x10139fd0	269721552
[2023-07-19T19:43:05.473Z] GDB OUT r30            0x1003007c1b0	1100317442480
[2023-07-19T19:43:05.473Z] GDB OUT r31            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT pc             0x3fff8bc2e488	0x3fff8bc2e488 <__waitpid_nocancel+36>
[2023-07-19T19:43:05.473Z] GDB OUT msr            0x800000010000d033	9223372041149796403
[2023-07-19T19:43:05.473Z] GDB OUT cr             0x52042844	1376004164
[2023-07-19T19:43:05.473Z] GDB OUT lr             0x1004ffb4	0x1004ffb4 <waitchld.isra.10+292>
[2023-07-19T19:43:05.473Z] GDB OUT ctr            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT xer            0x0	0
[2023-07-19T19:43:05.473Z] GDB OUT orig_r3        0xffffffffffffffff	-1
[2023-07-19T19:43:05.473Z] GDB OUT trap           0xc00	3072
[2023-07-19T19:43:05.473Z] GDB OUT   Id   Target Id         Frame 
[2023-07-19T19:43:05.473Z] GDB OUT * 1    process 23161 "bash" 0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:43:05.473Z] GDB OUT 
[2023-07-19T19:43:05.473Z] GDB OUT Thread 1 (process 23161):
[2023-07-19T19:43:05.473Z] GDB OUT #0  0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #1  0x000000001004ffb4 in waitchld.isra.10 ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #2  0x000000001005190c in wait_for ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #3  0x000000001003c620 in execute_command_internal ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #4  0x000000001003c89c in execute_command ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #5  0x000000001001f97c in reader_loop ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT #6  0x000000001001d49c in main ()
[2023-07-19T19:43:05.473Z] GDB OUT No symbol table info available.
[2023-07-19T19:43:05.473Z] GDB OUT Saved corefile core.23161.1
[2023-07-19T19:43:05.473Z] GDB OUT [Inferior 1 (process 23161) detached]
[2023-07-19T19:43:05.473Z] INFO: Sleep for 60000 millis before next capture.
[2023-07-19T19:44:08.191Z] ***[TEST INFO 2023/07/19 12:43:59] executing /usr/bin/gdb -batch -x /tmp/debugger1074686980007286826.txt bash 23161***
[2023-07-19T19:44:08.191Z] GDB OUT 0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:44:08.191Z] GDB OUT From                To                  Syms Read   Shared Object Library
[2023-07-19T19:44:08.191Z] GDB OUT 0x00003fff8bd7cb20  0x00003fff8bd8d73c  Yes (*)     /lib64/libtinfo.so.5
[2023-07-19T19:44:08.191Z] GDB OUT 0x00003fff8bd40dc0  0x00003fff8bd423ec  Yes (*)     /lib64/libdl.so.2
[2023-07-19T19:44:08.191Z] GDB OUT 0x00003fff8bb71d00  0x00003fff8bcd7870  Yes (*)     /lib64/libc.so.6
[2023-07-19T19:44:08.191Z] GDB OUT 0x00003fff8bdf0d60  0x00003fff8be178cc  Yes (*)     /lib64/ld64.so.2
[2023-07-19T19:44:08.191Z] GDB OUT (*): Shared library is missing debugging information.
[2023-07-19T19:44:08.191Z] GDB OUT r0             0x7	7
[2023-07-19T19:44:08.191Z] GDB OUT r1             0x3fffc1dfae00	70367701872128
[2023-07-19T19:44:08.191Z] GDB OUT r2             0x3fff8bd37400	70366795101184
[2023-07-19T19:44:08.191Z] GDB OUT r3             0x200	512
[2023-07-19T19:44:08.191Z] GDB OUT r4             0x3fffc1dfae70	70367701872240
[2023-07-19T19:44:08.191Z] GDB OUT r5             0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r6             0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r7             0x10030080340	1100317459264
[2023-07-19T19:44:08.191Z] GDB OUT r8             0x1003007c1b0	1100317442480
[2023-07-19T19:44:08.191Z] GDB OUT r9             0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r10            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r11            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r12            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r13            0x3fff8be3b330	70366796165936
[2023-07-19T19:44:08.191Z] GDB OUT r14            0x1013b38c	269726604
[2023-07-19T19:44:08.191Z] GDB OUT r15            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r16            0x1013b380	269726592
[2023-07-19T19:44:08.191Z] GDB OUT r17            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r18            0x10130d40	269684032
[2023-07-19T19:44:08.191Z] GDB OUT r19            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r20            0x4	4
[2023-07-19T19:44:08.191Z] GDB OUT r21            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r22            0x1	1
[2023-07-19T19:44:08.191Z] GDB OUT r23            0x2	2
[2023-07-19T19:44:08.191Z] GDB OUT r24            0xffffffffffffffff	18446744073709551615
[2023-07-19T19:44:08.191Z] GDB OUT r25            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r26            0xffff	65535
[2023-07-19T19:44:08.191Z] GDB OUT r27            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT r28            0x1013b38c	269726604
[2023-07-19T19:44:08.191Z] GDB OUT r29            0x10139fd0	269721552
[2023-07-19T19:44:08.191Z] GDB OUT r30            0x1003007c1b0	1100317442480
[2023-07-19T19:44:08.191Z] GDB OUT r31            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT pc             0x3fff8bc2e488	0x3fff8bc2e488 <__waitpid_nocancel+36>
[2023-07-19T19:44:08.191Z] GDB OUT msr            0x800000010000d033	9223372041149796403
[2023-07-19T19:44:08.191Z] GDB OUT cr             0x52042844	1376004164
[2023-07-19T19:44:08.191Z] GDB OUT lr             0x1004ffb4	0x1004ffb4 <waitchld.isra.10+292>
[2023-07-19T19:44:08.191Z] GDB OUT ctr            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT xer            0x0	0
[2023-07-19T19:44:08.191Z] GDB OUT orig_r3        0xffffffffffffffff	-1
[2023-07-19T19:44:08.191Z] GDB OUT trap           0xc00	3072
[2023-07-19T19:44:08.191Z] GDB OUT   Id   Target Id         Frame 
[2023-07-19T19:44:08.191Z] GDB OUT * 1    process 23161 "bash" 0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:44:08.191Z] GDB OUT 
[2023-07-19T19:44:08.191Z] GDB OUT Thread 1 (process 23161):
[2023-07-19T19:44:08.191Z] GDB OUT #0  0x00003fff8bc2e488 in __waitpid_nocancel () from /lib64/libc.so.6
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #1  0x000000001004ffb4 in waitchld.isra.10 ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #2  0x000000001005190c in wait_for ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #3  0x000000001003c620 in execute_command_internal ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #4  0x000000001003c89c in execute_command ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #5  0x000000001001f97c in reader_loop ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT #6  0x000000001001d49c in main ()
[2023-07-19T19:44:08.191Z] GDB OUT No symbol table info available.
[2023-07-19T19:44:08.191Z] GDB OUT Saved corefile core.23161.2
[2023-07-19T19:44:08.191Z] GDB OUT A debugging session is active.
[2023-07-19T19:44:08.191Z] GDB OUT 
[2023-07-19T19:44:08.191Z] GDB OUT 	Inferior 1 [process 23161] will be detached.
[2023-07-19T19:44:08.191Z] GDB OUT 
[2023-07-19T19:44:08.191Z] GDB OUT Quit anyway? (y or n) [answered Y; input not from terminal]
[2023-07-19T19:44:08.191Z] GDB OUT [Inferior 1 (process 23161) detached]
[2023-07-19T19:44:08.191Z] ***[TEST INFO 2023/07/19 12:43:59] executing kill -ABRT 23161***
[2023-07-19T19:44:08.191Z] ***[TEST INFO 2023/07/19 12:43:59] kill -ABRT signal sent***
[2023-07-19T19:44:08.191Z] Time spent executing: 360908 milliseconds
[2023-07-19T19:44:08.191Z] Test result: FAILED
[2023-07-19T19:44:08.191Z] Output from test:
[2023-07-19T19:44:08.191Z]  [OUT] start running script
[2023-07-19T19:44:08.191Z]  [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
[2023-07-19T19:44:08.191Z]  [OUT] export LD_BIND_NOT=on
[2023-07-19T19:44:08.192Z]  [OUT] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/openjdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xjit:count=0 -XX:+CRIURestoreNonPortableMode  -cp /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testMillisDelayBeforeCheckpointDone 3 3

[2023-07-19T19:44:08.192Z] Testing: Create CRIU checkpoint image and restore three times - testMillisDelayBeforeCheckpointDone
[2023-07-19T19:44:08.192Z] Test start time: 2023/07/19 12:43:59 Pacific Standard Time
[2023-07-19T19:44:08.192Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode " "org.openj9.criu.TimeChangeTest testMillisDelayAfterCheckpointDone" 3 3 false
[2023-07-19T19:44:08.192Z] Time spent starting: 9 milliseconds
[2023-07-19T19:44:08.192Z] ***[TEST INFO 2023/07/19 12:43:59] ABRT completed***
[2023-07-19T19:44:08.192Z] Output from test:
[2023-07-19T19:49:13.729Z] ***[TEST INFO 2023/07/19 12:48:59] ProcessKiller detected a timeout after 300000 milliseconds!***

[2023-07-19T19:50:08.993Z] Testing: Create CRIU checkpoint image and restore three times - testDateScheduledBeforeCheckpointDone
[2023-07-19T19:50:08.993Z] Test start time: 2023/07/19 12:50:00 Pacific Standard Time
[2023-07-19T19:50:08.993Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode " "org.openj9.criu.TimeChangeTest testDateScheduledBeforeCheckpointDone" 3 3 false
[2023-07-19T19:50:08.993Z] Time spent starting: 4 milliseconds
[2023-07-19T19:50:08.993Z] ***[TEST INFO 2023/07/19 12:50:00] ABRT completed***
[2023-07-19T19:50:08.993Z] Output from test:
[2023-07-19T19:55:04.522Z] ***[TEST INFO 2023/07/19 12:55:00] ProcessKiller detected a timeout after 300000 milliseconds!***

[2023-07-19T19:56:05.036Z] Testing: Create CRIU checkpoint image and restore three times - testDateScheduledAfterCheckpointDone
[2023-07-19T19:56:05.036Z] Test start time: 2023/07/19 12:56:00 Pacific Standard Time
[2023-07-19T19:56:05.036Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode " "org.openj9.criu.TimeChangeTest testDateScheduledAfterCheckpointDone" 3 3 false
[2023-07-19T19:56:05.036Z] Time spent starting: 4 milliseconds
[2023-07-19T19:56:05.036Z] ***[TEST INFO 2023/07/19 12:56:00] ABRT completed***
[2023-07-19T19:56:05.036Z] Output from test:
[2023-07-19T20:01:07.391Z] ***[TEST INFO 2023/07/19 13:01:00] ProcessKiller detected a timeout after 300000 milliseconds!***

[2023-07-19T20:05:42.386Z] cmdLineTester_criu_nonPortableRestore_2_FAILED

50x internal grinder - reproduced at prhel248, 20/20 passed in other 2 machines, 20/20 known failure in another 2 machines.

This timeout might be related to the machine setup issue org.eclipse.openj9.criu.SystemCheckpointException: Could not dump the JVM processes, err=-52.

Metadata

Metadata

Assignees

No one assigned

    Labels

    criuUsed to track CRIU snapshot related worktest failure

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions