Skip to content

Fix Intermittent vlog not found CRIU Jitserver test failures - #17578

Merged
mpirvu merged 1 commit into
eclipse-openj9:masterfrom
dsouzai:jitserver_criu_tests
Jun 15, 2023
Merged

Fix Intermittent vlog not found CRIU Jitserver test failures#17578
mpirvu merged 1 commit into
eclipse-openj9:masterfrom
dsouzai:jitserver_criu_tests

Conversation

@dsouzai

@dsouzai dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor

Sometimes, a restore can fail in a known way, in which case the test is set to pass; however, this causes subsequent tests that depend on the output of this test to fail. This PR adds a new script to wrap the cat commands that test for certain Jitserver characteristics post restore. This wrapper script will check the output of the previous test if the vlog to cat does not exist, and outputs a message that causes the test to pass if the previous test failed in one of the known ways.

This PR also modifies the existing criu scripts to take in an additional parameter to not delete the testOutput file if subsequent tests need it.

Fixes #17367

@dsouzai dsouzai added comp:test criu Used to track CRIU snapshot related work labels Jun 13, 2023
@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

@mpirvu @renfeiw could you review?

@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from 3364a53 to cdc2704 Compare June 13, 2023 01:20
@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

jenkins test sanity.functional xlinux jdk17

@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author
[2023-06-13T09:07:08.618Z] Testing: Check Verbose Log
[2023-06-13T09:07:08.618Z] Test start time: 2023/06/13 06:07:07 Atlantic Standard Time
[2023-06-13T09:07:08.618Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Personal_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuCatVlog.sh vlog true true
[2023-06-13T09:07:08.618Z] Time spent starting: 7 milliseconds
[2023-06-13T09:07:08.618Z] Time spent executing: 15 milliseconds
[2023-06-13T09:07:08.618Z] Test result: FAILED
[2023-06-13T09:07:08.618Z] Output from test:
[2023-06-13T09:07:08.618Z]  [OUT] start running script
[2023-06-13T09:07:08.618Z]  [OUT] Removed testOutput file
[2023-06-13T09:07:08.618Z]  [OUT] finished script
[2023-06-13T09:07:08.618Z] >> Success condition was not found: [Output match: CHECKPOINT RESTORE: Ready for restore]
[2023-06-13T09:07:08.618Z] >> Success condition was not found: [Output match: Connected to a server]
[2023-06-13T09:07:08.618Z] >> Success condition was not found: [Output match: CAT VLOG FORCE PASS]

Well... clearly this didn't fix it... I think I'll update the test to cat the testOutput file so we can see what the previous output was.

EDIT: Technically this is a different problem; if the vlog didnt exist then we'd enter the else path and we would've seen "Checking previous test output". This makes me believe that the vlog was generated but was empty for whatever reason. Either way, the PR has been updated to cat the previous test's output.

@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from cdc2704 to 367bd7b Compare June 13, 2023 12:44
@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

jenkins test sanity.functional xlinux jdk17

@dsouzai
dsouzai marked this pull request as draft June 13, 2023 13:50
@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from 367bd7b to 597e9af Compare June 13, 2023 14:01
@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

jenkins test sanity.functional xlinux jdk17

@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

Launched a 50x grinder here https://openj9-jenkins.osuosl.org/job/Grinder/2506/; lets see if we can reproduce the failure.

@dsouzai
dsouzai marked this pull request as ready for review June 13, 2023 21:14
@dsouzai

dsouzai commented Jun 13, 2023

Copy link
Copy Markdown
Contributor Author

50x grinder passed. At the very least, this PR should fix the vlog not found issue, and for all the others, it should at least print out the previous test's output whenever a test depends on it, so it's already an improvement from the existing infra.

@mpirvu @renfeiw good for review now.

@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from 597e9af to 61d947d Compare June 13, 2023 21:25
Comment thread test/functional/cmdLineTests/criu/criuCatVlog.sh Outdated

@mpirvu mpirvu left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from 61d947d to c4640eb Compare June 14, 2023 19:03
@dsouzai

dsouzai commented Jun 14, 2023

Copy link
Copy Markdown
Contributor Author

A thought occurred to me just now; if the restore fails in one of the known ways, is that going to show up in testOutput? testOutput is only the output of the java command right?

Signed-off-by: Irwin D'Souza <dsouzai.gh@gmail.com>
@dsouzai
dsouzai force-pushed the jitserver_criu_tests branch from c4640eb to fd6cb59 Compare June 14, 2023 19:46
@dsouzai

dsouzai commented Jun 14, 2023

Copy link
Copy Markdown
Contributor Author

I updated the scripts to save the output of the criu restore command and output that long with testOutput, in case the known error does not come from the JVM process.

@renfeiw renfeiw left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@mpirvu

mpirvu commented Jun 15, 2023

Copy link
Copy Markdown
Contributor

jenkins test sanity plinux,xlinux,zlinux jdk17

@mpirvu

mpirvu commented Jun 15, 2023

Copy link
Copy Markdown
Contributor

Failure on zlinux: cmdLineTester_criu_nonPortableRestore_0

Testing: Create CRIU checkpoint image and restore three times - testDateScheduledAfterCheckpointDone
Test start time: 2023/06/15 05:26:12 Eastern Standard Time
Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Personal_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Personal_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Personal_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit -XX:+CRIURestoreNonPortableMode " "org.openj9.criu.TimeChangeTest testDateScheduledAfterCheckpointDone" 3 3 false false
Time spent starting: 1 milliseconds
***[TEST INFO 2023/06/15 05:31:12] ProcessKiller detected a timeout after 300000 milliseconds!***
INFO: Cannot find '/usr/bin/gdb' using 'gdb' from the path.
***[TEST INFO 2023/06/15 05:31:12] executing gdb -batch -x /tmp/debugger11455924907567256480.txt bash 11064***
java.io.IOException: Cannot run program "gdb": error=2, No such file or directory
	at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1143)
	at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1073)
	at java.base/java.lang.Runtime.exec(Runtime.java:594)
	at java.base/java.lang.Runtime.exec(Runtime.java:453)
	at Test$ProcessKiller.captureCoreForProcess(Test.java:697)
	at Test$ProcessKiller.captureCoreForProcess(Test.java:646)
	at Test$ProcessKiller.run(Test.java:596)
Caused by: java.io.IOException: error=2, No such file or directory
	at java.base/java.lang.ProcessImpl.<init>(ProcessImpl.java:314)
	at java.base/java.lang.ProcessImpl.start(ProcessImpl.java:244)
	at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1110)
	... 6 more
***[TEST INFO 2023/06/15 05:31:12] executing kill -ABRT 11064***
Time spent executing: 300077 milliseconds
Test result: FAILED

Another (probably unrelated) failure on plinux: cmdLineTest_J9test_common_0

Testing: -Xlockword minimizeFootprint mode
Test start time: 2023/06/15 05:32:54 Coordinated Universal Time
Running command: "/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/openjdkbinary/j2sdk-image/bin/java"   -Xdump -cp "/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/utils/utils.jar" -Xlockword:mode=minimizeFootprint VMBench.FibBench
Time spent starting: 2 milliseconds
Time spent executing: 12710 milliseconds
Test result: FAILED
Output from test:
 [OUT] Fibonacci: iterations = 10000
 [OUT] fibonacci(12) = 144
 [ERR] Unhandled exception
 [ERR] Type=Segmentation error vmState=0x00000000
 [ERR] J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
 [ERR] Handler1=00007FFFA673F9E0 Handler2=00007FFFA6668AA0
 [ERR] R0=00007FFFA67C8C10 R1=00007FFFA6E5C450 R2=00007FFFA6986D00 R3=0000000000095800
 [ERR] R4=00000000000BFA50 R5=000000000017B320 R6=00000000000BF3D0 R7=000000000017B2F8
 [ERR] R8=0000000000000003 R9=00000000FFEAE04C R10=0000000000000004 R11=00007FFF4D46370C
 [ERR] R12=0000000028222442 R13=00007FFFA6E668E0 R14=000000000017B360 R15=0000000000095800
 [ERR] R16=0000000000000002 R17=0000000000000007 R18=000000004A39564D R19=00007FFFA6E5C620
 [ERR] R20=00007FFFA6E5C6A0 R21=00007FFFA6E5C720 R22=00000000FFEABC80 R23=0000000000000001
 [ERR] R24=0000000080000002 R25=0000000000095800 R26=FFFFFFFFFFFFFFFD R27=00007FFFA00296E0
 [ERR] R28=0000000000000008 R29=FFFFFFFFFFFFFFFF R30=0000000000000000 R31=0000000000095800
 [ERR] NIP=00007FFFA67CDB38 MSR=800000000280F033 ORIG_GPR3=00007FFFA67C3978 CTR=00007FFFA67C38BC
 [ERR] LINK=00007FFFA67C8C10 XER=0000000000000000 CCR=0000000048222442 SOFTE=0000000000000001
 [ERR] TRAP=0000000000000300 DAR=0000000000000024 dsisr=0000000040000000 RESULT=0000000000000000
 [ERR] FPR0 0000000000000003 (f: 3.000000, d: 1.482197e-323)
 [ERR] FPR1 405557b9a0000000 (f: 2684354560.000000, d: 8.537070e+01)
 [ERR] FPR2 3ff2349d60000000 (f: 1610612736.000000, d: 1.137845e+00)
 [ERR] FPR3 3fee666660000000 (f: 1610612736.000000, d: 9.500000e-01)
 [ERR] FPR4 40123143c0000000 (f: 3221225472.000000, d: 4.548110e+00)
 [ERR] FPR5 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR6 3fe62e42fefa39ef (f: 4277811712.000000, d: 6.931472e-01)
 [ERR] FPR7 3fd4043057b6ee09 (f: 1471606272.000000, d: 3.127557e-01)
 [ERR] FPR8 bfdffffef20a4123 (f: 4060758272.000000, d: -4.999997e-01)
 [ERR] FPR9 bfd00ea348b88334 (f: 1220051712.000000, d: -2.508934e-01)
 [ERR] FPR10 bfdfeff78394586c (f: 2207537152.000000, d: -4.990214e-01)
 [ERR] FPR11 41cdcd6500000000 (f: 0.000000, d: 1.000000e+09)
 [ERR] FPR12 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR13 000000001e1999fc (f: 504994304.000000, d: 2.495003e-315)
 [ERR] FPR14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR16 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR17 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR18 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR19 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR20 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR21 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR22 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR23 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR24 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR25 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR26 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR27 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR28 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR29 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR30 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] FPR31 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] Module=/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/openjdkbinary/j2sdk-image/lib/default/libj9vm29.so
 [ERR] Module_base_address=00007FFFA6700000
 [ERR] Target=2_90_20230615_454 (Linux 4.18.0-408.el8.ppc64le)
 [ERR] CPU=ppc64le (4 logical CPUs) (0x1dbc30000 RAM)
 [ERR] ----------- Stack Backtrace -----------
 [ERR] bytecodeLoopCompressed+0x19878 (0x00007FFFA67CDB38 [libj9vm29.so+0xcdb38])
 [ERR]  (0x00007FFFA686D7E0 [libj9vm29.so+0x16d7e0])
 [ERR] sendResolveInvokeDynamic+0x26c (0x00007FFFA6719B2C [libj9vm29.so+0x19b2c])
 [ERR] resolveInvokeDynamic+0x240 (0x00007FFFA678EC70 [libj9vm29.so+0x8ec70])
 [ERR] bytecodeLoopCompressed+0x1b7e4 (0x00007FFFA67CFAA4 [libj9vm29.so+0xcfaa4])
 [ERR]  (0x00007FFFA686D7E0 [libj9vm29.so+0x16d7e0])
 [ERR] runCallInMethod+0x258 (0x00007FFFA6719ED8 [libj9vm29.so+0x19ed8])
 [ERR] gpProtectedRunCallInMethod+0x54 (0x00007FFFA6743D64 [libj9vm29.so+0x43d64])
 [ERR] signalProtectAndRunGlue+0x28 (0x00007FFFA6880A58 [libj9vm29.so+0x180a58])
 [ERR] omrsig_protect+0x3f4 (0x00007FFFA6669F74 [libj9prt29.so+0x39f74])
 [ERR] gpProtectAndRun+0xa8 (0x00007FFFA6880B28 [libj9vm29.so+0x180b28])
 [ERR] gpCheckCallin+0xc4 (0x00007FFFA6746424 [libj9vm29.so+0x46424])
 [ERR] callStaticVoidMethod+0x48 (0x00007FFFA6743368 [libj9vm29.so+0x43368])
 [ERR] JavaMain+0x11e4 (0x00007FFFA7137304 [libjli.so+0x7304])
 [ERR] ThreadJavaMain+0x18 (0x00007FFFA713D258 [libjli.so+0xd258])
 [ERR] start_thread+0xf8 (0x00007FFFA70E9678 [libpthread-2.28.so+0x9678])
 [ERR] clone+0x74 (0x00007FFFA6FD8738 [libc-2.28.so+0x138738])
 [ERR] ---------------------------------------
 [ERR] JVMDUMP039I Processing dump event "gpf", detail "" at 2023/06/15 05:32:55 - please wait.
 [ERR] JVMDUMP032I JVM requested System dump using '/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/core.20230615.053255.3110853.0001.dmp' in response to an event
 [ERR] JVMDUMP010I System dump written to /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/core.20230615.053255.3110853.0001.dmp
 [ERR] JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/javacore.20230615.053255.3110853.0002.txt' in response to an event
 [ERR] JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/javacore.20230615.053255.3110853.0002.txt
 [ERR] JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/Snap.20230615.053255.3110853.0003.trc' in response to an event
 [ERR] JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/Snap.20230615.053255.3110853.0003.trc
 [ERR] JVMDUMP032I JVM requested JIT dump using '/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/jitdump.20230615.053255.3110853.0004.dmp' in response to an event
 [ERR] JVMDUMP051I JIT dump occurred in 'main' thread 0x0000000000095800
 [ERR] JVMDUMP053I JIT dump is recompiling java/lang/invoke/MemberName$Factory.resolveOrFail(BLjava/lang/invoke/MemberName;Ljava/lang/Class;ILjava/lang/Class;)Ljava/lang/invoke/MemberName;
 [ERR] JVMDUMP010I JIT dump written to /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Personal_testList_0/aqa-tests/TKG/output_1686805361485/cmdLineTest_J9test_common_0/jitdump.20230615.053255.3110853.0004.dmp
 [ERR] JVMDUMP013I Processed dump event "gpf", detail "".
>> Success condition was not found: [Return code: 0]

@dsouzai

dsouzai commented Jun 15, 2023

Copy link
Copy Markdown
Contributor Author

I think the zlinux failure is the same as #16980. The plinux failure can't be related because it's in a completely different test that I haven't modified.

@mpirvu

mpirvu commented Jun 15, 2023

Copy link
Copy Markdown
Contributor

Since the two failures are unrelated, this PR is good for merging

@mpirvu
mpirvu merged commit 3805a8f into eclipse-openj9:master Jun 15, 2023
@dsouzai
dsouzai deleted the jitserver_criu_tests branch April 3, 2024 13:55
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

comp:test criu Used to track CRIU snapshot related work

Projects

None yet

Development

Successfully merging this pull request may close these issues.

cmdLineTester_criu_jitPostRestore Check Verbose Log - vlog: No such file or directory

3 participants