Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

cmdLineTester_criu_nonPortableRestore_0_FAILED testTimeCompensation() after CRIU restore elapsedMillisTime should NOT be greater than maxElapsedMillisTime or delayed elapsedMillisTime should NOT be less than minElapsedMillisTime #18513

Open
JasonFengJ9 opened this issue Nov 22, 2023 · 10 comments
Open

cmdLineTester_criu_nonPortableRestore_0_FAILED testTimeCompensation() after CRIU restore elapsedMillisTime should NOT be greater than maxElapsedMillisTime or delayed elapsedMillisTime should NOT be less than minElapsedMillisTime #18513

JasonFengJ9 opened this issue Nov 22, 2023 · 10 comments
Assignees
@JasonFengJ9
Labels
comp:test criu Used to track CRIU snapshot related work test excluded test failure

Comments

@JasonFengJ9
Copy link
Member

Failure link

From https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly/603/tapResults/

21:41:11  openjdk version "17.0.10-internal" 2024-01-16
21:41:11  OpenJDK Runtime Environment (build 17.0.10-internal+0-adhoc.****.BuildJDK17s390xlinuxNightly)
21:41:11  Eclipse OpenJ9 VM (build master-bc5b2d6c58c, JRE 17 Linux s390x-64-Bit Compressed References 20231116_617 (JIT enabled, AOT enabled)
21:41:11  OpenJ9   - bc5b2d6c58c
21:41:11  OMR      - d810fcb9869
21:41:11  JCL      - 22a20bec440 based on jdk-17.0.10+3)

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

Optional info

Failure output (captured from console output)

Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
Test start time: 2023/11/17 01:02:09 Eastern Standard Time
Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java " -Xjit -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu,j9jcl.533} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
Time spent starting: 9 milliseconds
Time spent executing: 11911 milliseconds
Test result: FAILED
Output from test:
 [OUT] start running script
 [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
 [OUT] export LD_BIND_NOT=on
 [OUT] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xjit -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu,j9jcl.533} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testTimeCompensation 1
 [OUT] testTimeCompensation() starts, current thread name: main, Fri Nov 17 01:02:09 EST 2023, System.currentTimeMillis(): 1700200929896, System.nanoTime(): 1700200929893582388
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime starts, current thread name: main, Fri Nov 17 01:02:10 EST 2023, System.currentTimeMillis() 1700200930546, System.nanoTime() 1700200930543601344
 [OUT] testTimeCompensation() sleep 100ms: startMillisTime (1700200930442ms) startNanoTime (1700200930439344478ns) currentMillisTime (1700200930544ms) currentNanoTime (1700200930541567550ns) elapsedMillisTime (102ms) elapsedNanoTime (102223072ns)
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime ends, current thread name: main, Fri Nov 17 01:02:10 EST 2023, System.currentTimeMillis() 1700200930573, System.nanoTime() 1700200930570004508
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Nov 17 01:02:10 EST 2023, System.currentTimeMillis() 1700200930674, System.nanoTime() 1700200930671586601
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms: startMillisTime (1700200930573ms) startNanoTime (1700200930570129051ns) currentMillisTime (1700200930674ms) currentNanoTime (1700200930671348700ns) elapsedMillisTime (101ms) elapsedNanoTime (101219649ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Nov 17 01:02:10 EST 2023, System.currentTimeMillis() 1700200930675, System.nanoTime() 1700200930672235100
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932579, System.nanoTime() 1700200932576289181
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s: startMillisTime (1700200930573ms) startNanoTime (1700200930570508527ns) currentMillisTime (1700200932579ms) currentNanoTime (1700200932576245190ns) elapsedMillisTime (2006ms) elapsedNanoTime (2005736663ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932579, System.nanoTime() 1700200932576648636
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime starts, current thread name: main, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932585, System.nanoTime() 1700200932582415270
 [OUT] testTimeCompensation() preCheckpoint: startMillisTime (1700200930573ms) startNanoTime (1700200930570604642ns) currentMillisTime (1700200932585ms) currentNanoTime (1700200932582405767ns) elapsedMillisTime (2012ms) elapsedNanoTime (2011801125ns)
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime ends, current thread name: main, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932585, System.nanoTime() 1700200932582643463
 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis(): 1700200932585, System.nanoTime(): 1700200932582717657
 [OUT] 06:02:12.806*0x69800          j9criu.9        > Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
 [OUT] 06:02:12.807 0x69800          j9criu.18       - Taking a checkpoint with active clinit
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime starts, current thread name: main, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932807, System.nanoTime() 1700200932804101171
 [OUT] testTimeCompensation() preCheckpointHook: startMillisTime (1700200930573ms) startNanoTime (1700200930570604642ns) currentMillisTime (1700200932807ms) currentNanoTime (1700200932804089867ns) elapsedMillisTime (2234ms) elapsedNanoTime (2233485225ns)
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime ends, current thread name: main, Fri Nov 17 01:02:12 EST 2023, System.currentTimeMillis() 1700200932807, System.nanoTime() 1700200932804351229
 [OUT] 06:02:12.808 0x69800          j9criu.13       - Before checkpoint, checkpointNanoTimeMonotonic = 1700200932805657569, checkpointNanoUTCTime = 1700200932808919945
 [OUT] 06:02:13.332 0x69800          j9criu.12       - Current syslogOptions: error,vital
 [OUT] 06:02:13.332 0x69800          j9criu.7        - Before checkpoint criu_dump(), j9time_nano_time() returns 1700200933329853444, j9time_current_time_nanos() returns 1700200933333115957
 [OUT] 06:02:16.575 0x69800          j9criu.24       - After checkpoint criu_dump(), criuRestoreNanoTimeMonotonic (1700200936572258390), criuRestoreNanoUTCTime (1700200936575521485), lastRestoreTimeMillis (1700200936575)
 [OUT] 06:02:16.575 0x69800          j9criu.15       - After checkpoint criu_dump(), j9time_nano_time() returns 1700200936572572176, j9time_current_time_nanos() returns 1700200936575834437
 [OUT] 06:02:16.575 0x69800          j9criu.14       - After restore, restoreNanoUTCTime = 1700200936575834437, checkpointNanoUTCTime = 1700200932808919945, checkpointRestoreTimeDelta = 3766914492, restoreNanoTimeMonotonic = 1700200936572572176, checkpointNanoTimeMonotonic = 1700200932805657569, nanoTimeMonotonicClockDelta = 3766914607
 [OUT] JVMJITM044W Some or all compiled code in the code cache invalidated post restore.
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime starts, current thread name: main, Fri Nov 17 01:02:16 EST 2023, System.currentTimeMillis() 1700200936580, System.nanoTime() 1700200932810251581
 [OUT] testTimeCompensation() postRestoreHook: startMillisTime (1700200930573ms) startNanoTime (1700200930570604642ns) currentMillisTime (1700200936580ms) currentNanoTime (1700200932810226083ns) elapsedMillisTime (6007ms) elapsedNanoTime (2239621441ns)
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime ends, current thread name: main, Fri Nov 17 01:02:16 EST 2023, System.currentTimeMillis() 1700200936580, System.nanoTime() 1700200932810559785
 [OUT] 06:02:16.581 0x69800          j9criu.10       < Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
 [OUT] testTimeCompensation() after CRIU restore checkElapseTime starts, current thread name: main, Fri Nov 17 01:02:16 EST 2023, System.currentTimeMillis() 1700200936581, System.nanoTime() 1700200932811565572
 [OUT] testTimeCompensation() after CRIU restore: startMillisTime (1700200930573ms) startNanoTime (1700200930570604642ns) currentMillisTime (1700200936581ms) currentNanoTime (1700200932811561333ns) elapsedMillisTime (6008ms) elapsedNanoTime (2240956691ns)
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Nov 17 01:02:16 EST 2023, System.currentTimeMillis() 1700200936584, System.nanoTime() 1700200932815026311
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms: startMillisTime (1700200932807ms) startNanoTime (1700200932804435211ns) currentMillisTime (1700200936584ms) currentNanoTime (1700200932815006291ns) elapsedMillisTime (3777ms) elapsedNanoTime (10571080ns)
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Nov 17 01:02:16 EST 2023, System.currentTimeMillis() 1700200936585, System.nanoTime() 1700200932815298795
 [OUT] FAILED: testTimeCompensation() after CRIU restore elapsedMillisTime (6008ms) should NOT be greater than maxElapsedMillisTime (6000ms)

>> Failure condition was found: [Output match: FAILED: testTimeCompensation]
>> Success condition was not found: [Output match: Thread pid mismatch]
>> Success condition was not found: [Output match: do not match expected]
>> Success condition was not found: [Output match: Unable to create a thread:]
>> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
>> Failure condition was not found: [Output match: User requested Java dump using]


---TEST RESULTS---
Number of PASSED tests: 56 out of 57
Number of FAILED tests: 1 out of 57

---SUMMARY OF FAILED TESTS---
Create CRIU checkpoint image and restore once - testTimeCompensation
-----------------------------

-----------------------------------
cmdLineTester_criu_nonPortableRestore_0_FAILED

This is a test issue, the maxElapsedMillisTime needs further adjustment for zLinux machines.
@JasonFengJ9 JasonFengJ9 added comp:test test failure criu Used to track CRIU snapshot related work labels Nov 22, 2023
@JasonFengJ9 JasonFengJ9 self-assigned this Nov 22, 2023
@JasonFengJ9 JasonFengJ9 mentioned this issue Nov 22, 2023
Merged
@JasonFengJ9 JasonFengJ9 changed the title cmdLineTester_criu_nonPortableRestore_0_FAILED zLinux FAILED: testTimeCompensation() after CRIU restore elapsedMillisTime (6008ms) should NOT be greater than maxElapsedMillisTime (6000ms) cmdLineTester_criu_nonPortableRestore_0_FAILED(zLinux) testTimeCompensation() after CRIU restore elapsedMillisTime (6008ms) should NOT be greater than maxElapsedMillisTime (6000ms) Nov 22, 2023
@hzongaro
Copy link
Member

Encountered this failure in a pull request test run on aarch64 Linux.

@hzongaro hzongaro mentioned this issue Nov 23, 2023
Merged
@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/105/
cmdLineTester_criu_nonPortableRestore_4

Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
Test start time: 2023/11/24 00:31:50 Coordinated Universal Time
Running command: bash /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu,j9jcl.533} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
Time spent starting: 4 milliseconds
Time spent executing: 12768 milliseconds
Test result: FAILED
Output from test:
 [OUT] start running script
 [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
 [OUT] export LD_BIND_NOT=on
 [OUT] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xjit:count=0 -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu,j9jcl.533} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testTimeCompensation 1
 [OUT] testTimeCompensation() starts, current thread name: main, Fri Nov 24 00:31:53 UTC 2023, System.currentTimeMillis(): 1700785913764, System.nanoTime(): 209527196817003
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime starts, current thread name: main, Fri Nov 24 00:31:54 UTC 2023, System.currentTimeMillis() 1700785914374, System.nanoTime() 209527806618288
 [OUT] testTimeCompensation() sleep 100ms: startMillisTime (1700785914239ms) startNanoTime (209527671882243ns) currentMillisTime (1700785914357ms) currentNanoTime (209527789950783ns) elapsedMillisTime (118ms) elapsedNanoTime (118068540ns)
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime ends, current thread name: main, Fri Nov 24 00:31:54 UTC 2023, System.currentTimeMillis() 1700785914515, System.nanoTime() 209527948086542
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Nov 24 00:31:54 UTC 2023, System.currentTimeMillis() 1700785914627, System.nanoTime() 209528060378593
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms: startMillisTime (1700785914515ms) startNanoTime (209527948426583ns) currentMillisTime (1700785914627ms) currentNanoTime (209528060276833ns) elapsedMillisTime (112ms) elapsedNanoTime (111850250ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Nov 24 00:31:54 UTC 2023, System.currentTimeMillis() 1700785914631, System.nanoTime() 209528063535198
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916530, System.nanoTime() 209529963326759
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s: startMillisTime (1700785914524ms) startNanoTime (209527957092996ns) currentMillisTime (1700785916529ms) currentNanoTime (209529961633516ns) elapsedMillisTime (2005ms) elapsedNanoTime (2004540520ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916532, System.nanoTime() 209529964974642
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime starts, current thread name: main, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916567, System.nanoTime() 209530000147455
 [OUT] testTimeCompensation() preCheckpoint: startMillisTime (1700785914528ms) startNanoTime (209527961460923ns) currentMillisTime (1700785916567ms) currentNanoTime (209530000095975ns) elapsedMillisTime (2039ms) elapsedNanoTime (2038635052ns)
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime ends, current thread name: main, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916568, System.nanoTime() 209530000528015
 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis(): 1700785916569, System.nanoTime(): 209530002034658
 [OUT] 00:31:56.635*0x11200          j9criu.9        > Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
 [OUT] 00:31:56.635 0x11200          j9criu.18       - Taking a checkpoint with active clinit
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime starts, current thread name: main, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916640, System.nanoTime() 209530072747845
 [OUT] testTimeCompensation() preCheckpointHook: startMillisTime (1700785914528ms) startNanoTime (209527961460923ns) currentMillisTime (1700785916637ms) currentNanoTime (209530070284361ns) elapsedMillisTime (2109ms) elapsedNanoTime (2108823438ns)
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime ends, current thread name: main, Fri Nov 24 00:31:56 UTC 2023, System.currentTimeMillis() 1700785916640, System.nanoTime() 209530073006125
 [OUT] 00:31:56.667 0x11200          j9criu.13       - Before checkpoint, checkpointNanoTimeMonotonic = 209530099492446, checkpointNanoUTCTime = 1700785916666998903
 [OUT] 00:31:56.710 0x11200          j9criu.12       - Current syslogOptions: error,vital
 [OUT] 00:31:56.710 0x11200          j9criu.7        - Before checkpoint criu_dump(), j9time_nano_time() returns 209530142888591, j9time_current_time_nanos() returns 1700785916710395008
 [OUT] 00:31:59.043 0x11200          j9criu.24       - After checkpoint criu_dump(), criuRestoreNanoTimeMonotonic (209532475933530), criuRestoreNanoUTCTime (1700785919043440027), lastRestoreTimeMillis (1700785919043)
 [OUT] 00:31:59.048 0x11200          j9criu.15       - After checkpoint criu_dump(), j9time_nano_time() returns 209532481023257, j9time_current_time_nanos() returns 1700785919048529754
 [OUT] 00:31:59.048 0x11200          j9criu.14       - After restore, restoreNanoUTCTime = 1700785919048529754, checkpointNanoUTCTime = 1700785916666998903, checkpointRestoreTimeDelta = 2381530851, restoreNanoTimeMonotonic = 209532481023257, checkpointNanoTimeMonotonic = 209530099492446, nanoTimeMonotonicClockDelta = 2381530811
 [OUT] JVMJITM044W Some or all compiled code in the code cache invalidated post restore.
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime starts, current thread name: main, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920599, System.nanoTime() 209531650694999
 [OUT] testTimeCompensation() postRestoreHook: startMillisTime (1700785914528ms) startNanoTime (209527961460923ns) currentMillisTime (1700785920555ms) currentNanoTime (209531606805892ns) elapsedMillisTime (6027ms) elapsedNanoTime (3645344969ns)
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime ends, current thread name: main, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920818, System.nanoTime() 209531869056810
 [OUT] 00:32:00.878 0x11200          j9criu.10       < Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920906, System.nanoTime() 209531957015783
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms: startMillisTime (1700785920826ms) startNanoTime (209531877310222ns) currentMillisTime (1700785920887ms) currentNanoTime (209531938703435ns) elapsedMillisTime (61ms) elapsedNanoTime (61393213ns)
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920934, System.nanoTime() 209531985376906
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920906, System.nanoTime() 209531957152063
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920911, System.nanoTime() 209531962118391
 [OUT] testTimeCompensation() after CRIU restore checkElapseTime starts, current thread name: main, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920906, System.nanoTime() 209531957019983
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s: startMillisTime (1700785914528ms) startNanoTime (209527961242122ns) currentMillisTime (1700785920911ms) currentNanoTime (209531962011071ns) elapsedMillisTime (6383ms) elapsedNanoTime (4000768949ns)
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms: startMillisTime (1700785916640ms) startNanoTime (209530073073606ns) currentMillisTime (1700785920883ms) currentNanoTime (209531934955590ns) elapsedMillisTime (4243ms) elapsedNanoTime (1861881984ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Fri Nov 24 00:32:00 UTC 2023, System.currentTimeMillis() 1700785920936, System.nanoTime() 209531987639390
 [OUT] testTimeCompensation() after CRIU restore: startMillisTime (1700785914528ms) startNanoTime (209527961460923ns) currentMillisTime (1700785920893ms) currentNanoTime (209531944498884ns) elapsedMillisTime (6365ms) elapsedNanoTime (3983037961ns)
 [OUT] FAILED: testTimeCompensation() after CRIU restore elapsedMillisTime (6365ms) should NOT be greater than maxElapsedMillisTime (6000ms)
 [OUT] FAILED: testTimeCompensation()() preCheckpointHook timer delayed 10ms elapsedNanoTimeInMillis (1862ms) should NOT be greater than maxElapsedNanoTimeInMillis (500ms)
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Nov 24 00:32:01 UTC 2023, System.currentTimeMillis() 1700785921537, System.nanoTime() 209532588560741
 [OUT] testTimeCompensation() after CRIU restore checkElapseTime ends, current thread name: main, Fri Nov 24 00:32:01 UTC 2023, System.currentTimeMillis() 1700785921538, System.nanoTime() 209532589325462
 [OUT] testTimeCompensation() postRestore, current thread name: main, Fri Nov 24 00:32:01 UTC 2023, System.currentTimeMillis(): 1700785921548, System.nanoTime(): 209532599627798
 [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Fri Nov 24 00:32:01 UTC 2023, System.currentTimeMillis() 1700785921650, System.nanoTime() 209532701337832
 [OUT] testTimeCompensation() postRestore timer delayed 100ms: startMillisTime (1700785921548ms) startNanoTime (209532599735198ns) currentMillisTime (1700785921649ms) currentNanoTime (209532700341830ns) elapsedMillisTime (101ms) elapsedNanoTime (100606632ns)
 [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Fri Nov 24 00:32:01 UTC 2023, System.currentTimeMillis() 1700785921650, System.nanoTime() 209532701426312
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Fri Nov 24 00:32:02 UTC 2023, System.currentTimeMillis() 1700785922877, System.nanoTime() 209533928735373
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s: startMillisTime (1700785920876ms) startNanoTime (209531927137538ns) currentMillisTime (1700785922877ms) currentNanoTime (209533928622813ns) elapsedMillisTime (2001ms) elapsedNanoTime (2001485275ns)
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Fri Nov 24 00:32:02 UTC 2023, System.currentTimeMillis() 1700785922889, System.nanoTime() 209533940074030
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923022, System.nanoTime() 209534073923673
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s: startMillisTime (1700785916640ms) startNanoTime (209530073346726ns) currentMillisTime (1700785923022ms) currentNanoTime (209534073816473ns) elapsedMillisTime (6382ms) elapsedNanoTime (4000469747ns)
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923023, System.nanoTime() 209534074193913
 [OUT] testTimeCompensation() postRestore checkElapseTime starts, current thread name: main, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923549, System.nanoTime() 209534600934152
 [OUT] testTimeCompensation() postRestore: startMillisTime (1700785921548ms) startNanoTime (209532599695558ns) currentMillisTime (1700785923549ms) currentNanoTime (209534600901632ns) elapsedMillisTime (2001ms) elapsedNanoTime (2001206074ns)
 [OUT] testTimeCompensation() postRestore checkElapseTime ends, current thread name: main, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923550, System.nanoTime() 209534601018752
 [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 2s, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923550, System.nanoTime() 209534601027312
 [OUT] testTimeCompensation() postRestore timer delayed 2s: startMillisTime (1700785921549ms) startNanoTime (209532600246519ns) currentMillisTime (1700785923549ms) currentNanoTime (209534600953712ns) elapsedMillisTime (2000ms) elapsedNanoTime (2000707193ns)
 [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 2s, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923550, System.nanoTime() 209534601107552
 [OUT] getResultAndCancelTimers before Thread.yield() taskRunning = 0, current thread name: main, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923661, System.nanoTime() 209534712600721
 [OUT] getResultAndCancelTimers before timer.cancel(), current thread name: main, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923661, System.nanoTime() 209534712850282
 [OUT] TimeTestTask tasksPassed: false, taskStarted: 9, taskExecuted: 9, current thread name: main, Fri Nov 24 00:32:03 UTC 2023, System.currentTimeMillis() 1700785923702, System.nanoTime() 209534753867704
 [OUT] FAILED: testTimeCompensation
 [OUT] Removed test output files
 [OUT] finished script
 [ERR] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 2235433 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
>> Success condition was found: [Output match: Killed]
>> Success condition was not found: [Output match: PASSED: testTimeCompensation]
>> Failure condition was not found: [Output match: CRIU is not enabled]
>> Failure condition was not found: [Output match: Operation not permitted]
>> Failure condition was found: [Output match: FAILED: testTimeCompensation]
>> Success condition was not found: [Output match: Thread pid mismatch]
>> Success condition was not found: [Output match: do not match expected]
>> Success condition was not found: [Output match: Unable to create a thread:]
>> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
>> Failure condition was not found: [Output match: User requested Java dump using]

@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_aarch64_linux_Nightly_testList_0/106/
cmdLineTester_criu_nonPortableRestore_3

@JasonFengJ9 JasonFengJ9 mentioned this issue Nov 28, 2023
Merged
@pshipton
Copy link
Member

pshipton commented Dec 1, 2023

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_aarch64_linux_Nightly_testList_0/578
cmdLineTester_criu_nonPortableRestore_1

@JasonFengJ9
Copy link
Member Author

#18513 (comment)
cmdLineTester_criu_nonPortableRestore_1

20:19:25   [OUT] FAILED: testTimeCompensation
20:19:25   [OUT] Removed test output files
20:19:25   [OUT] finished script
20:19:25   [ERR] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 4045788 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
20:19:25  >> Success condition was found: [Output match: Killed]
20:19:25  >> Success condition was not found: [Output match: PASSED: testTimeCompensation]
20:19:25  >> Failure condition was not found: [Output match: CRIU is not enabled]
20:19:25  >> Failure condition was not found: [Output match: Operation not permitted]
20:19:25  >> Failure condition was found: [Output match: FAILED: testTimeCompensation]
20:19:25  >> Success condition was not found: [Output match: Thread pid mismatch]
20:19:25  >> Success condition was not found: [Output match: do not match expected]
20:19:25  >> Success condition was not found: [Output match: Unable to create a thread:]
20:19:25  >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
20:19:25  >> Failure condition was not found: [Output match: User requested Java dump using]
20:19:25  
20:19:25  
20:19:25  ---TEST RESULTS---
20:19:25  Number of PASSED tests: 56 out of 57
20:19:25  Number of FAILED tests: 1 out of 57
20:19:25  
20:19:25  ---SUMMARY OF FAILED TESTS---
20:19:25  Create CRIU checkpoint image and restore once - testTimeCompensation
20:19:25  -----------------------------
20:19:25  
20:19:25  -----------------------------------
20:19:25  cmdLineTester_criu_nonPortableRestore_1_FAILED

This wasn't the initial failure for this issue testTimeCompensation() after CRIU restore elapsedMillisTime should NOT be greater than maxElapsedMillisTime, there wasn't a specific error in the console output.
Launched a 50x grinder - https://openj9-jenkins.osuosl.org/job/Grinder/3126/

@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/493
cmdLineTester_criu_nonPortableRestore_0

Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
Test start time: 2024/01/19 08:19:55 Eastern Standard Time
Running command: bash /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/jdkbinary/j2sdk-image/bin/java " -Xjit -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
Time spent starting: 4 milliseconds
Time spent executing: 9575 milliseconds
Test result: FAILED
Output from test:
 [OUT] start running script
 [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
 [OUT] export LD_BIND_NOT=on
 [OUT] /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xjit -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testTimeCompensation 1
 [OUT] testTimeCompensation() starts, current thread name: main, Fri Jan 19 08:19:56 EST 2024, System.currentTimeMillis(): 1705670396075, System.nanoTime(): 22451382348405899
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime starts, current thread name: main, Fri Jan 19 08:19:56 EST 2024, System.currentTimeMillis() 1705670396273, System.nanoTime() 22451382546449190
 [OUT] testTimeCompensation() sleep 100ms: startMillisTime (1705670396169ms) startNanoTime (22451382443074947ns) currentMillisTime (1705670396270ms) currentNanoTime (22451382543453580ns) elapsedMillisTime (101ms) elapsedNanoTime (100378633ns)
 [OUT] testTimeCompensation() sleep 100ms checkElapseTime ends, current thread name: main, Fri Jan 19 08:19:56 EST 2024, System.currentTimeMillis() 1705670396286, System.nanoTime() 22451382559385558
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Jan 19 08:19:56 EST 2024, System.currentTimeMillis() 1705670396387, System.nanoTime() 22451382661011276
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms: startMillisTime (1705670396286ms) startNanoTime (22451382559682175ns) currentMillisTime (1705670396387ms) currentNanoTime (22451382660835822ns) elapsedMillisTime (101ms) elapsedNanoTime (101153647ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Fri Jan 19 08:19:56 EST 2024, System.currentTimeMillis() 1705670396389, System.nanoTime() 22451382662901279
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398296, System.nanoTime() 22451384569951318
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s: startMillisTime (1705670396288ms) startNanoTime (22451382561379361ns) currentMillisTime (1705670398288ms) currentNanoTime (22451384562224592ns) elapsedMillisTime (2000ms) elapsedNanoTime (2000845231ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398298, System.nanoTime() 22451384571978609
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime starts, current thread name: main, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398303, System.nanoTime() 22451384576663433
 [OUT] testTimeCompensation() preCheckpoint: startMillisTime (1705670396288ms) startNanoTime (22451382562097239ns) currentMillisTime (1705670398303ms) currentNanoTime (22451384576594958ns) elapsedMillisTime (2015ms) elapsedNanoTime (2014497719ns)
 [OUT] testTimeCompensation() preCheckpoint checkElapseTime ends, current thread name: main, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398304, System.nanoTime() 22451384578058306
 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis(): 1705670398305, System.nanoTime(): 22451384578962475
 [OUT] 13:19:58.348*0x17000            j9vm.728      > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
 [OUT] 13:19:58.350 0x17000            j9vm.727      - Taking a checkpoint with active clinit
 [OUT] 13:19:58.350 0x17000            j9vm.684      > initializeCriuHooks
 [OUT] 13:19:58.350 0x17000            j9vm.723    * - initializeCriuHooks() j.u.Random class not found
 [OUT] 13:19:58.350 0x17000            j9vm.717      < initializeCriuHooks - checkpointState.hookRecords (00007FE9A429B5D0), classIterationRestoreHookRecords (00007FE9A429C710), delayedLockingOperationsRecords (00007FE9A429D850)
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime starts, current thread name: main, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398350, System.nanoTime() 22451384624278924
 [OUT] testTimeCompensation() preCheckpointHook: startMillisTime (1705670396288ms) startNanoTime (22451382562097239ns) currentMillisTime (1705670398350ms) currentNanoTime (22451384624153186ns) elapsedMillisTime (2062ms) elapsedNanoTime (2062055947ns)
 [OUT] testTimeCompensation() preCheckpointHook checkElapseTime ends, current thread name: main, Fri Jan 19 08:19:58 EST 2024, System.currentTimeMillis() 1705670398352, System.nanoTime() 22451384625759950
 [OUT] 13:19:58.353 0x17000            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000007FFEC1708
 [OUT] 13:19:58.354 0x17000            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000007FFEC1C38
 [OUT] 13:19:58.357 0x17000            j9vm.730      - Before checkpoint, checkpointNanoTimeMonotonic = 22451384630875508, checkpointNanoUTCTime = 1705670398357568431
 [OUT] 13:19:58.704 0x17000            j9vm.689      > runInternalJVMCheckpointHooks
 [OUT] 13:19:58.708 0x17000            j9vm.690      < runInternalJVMCheckpointHooks
 [OUT] 13:19:58.708 0x17000            j9vm.732      - Current syslogOptions: error,vital
 [OUT] 13:19:58.709 0x17000            j9vm.729      - Before checkpoint criu_dump(), j9time_nano_time() returns 22451384982332287, j9time_current_time_nanos() returns 1705670398709024952
 [OUT] 13:20:01.018 0x17000            j9vm.691      > runInternalJVMRestoreHooks
 [OUT] 13:20:01.018 0x17000            j9vm.692      < runInternalJVMRestoreHooks
 [OUT] 13:20:01.019 0x17000            j9vm.733      - After checkpoint criu_dump(), j9time_nano_time() returns 22451387292934937, j9time_current_time_nanos() returns 1705670401019627836
 [OUT] 13:20:01.019 0x17000            j9vm.734      - After restore, restoreNanoUTCTime = 1705670401019627836, checkpointNanoUTCTime = 1705670398357568431, checkpointRestoreTimeDelta = 2662059405, restoreNanoTimeMonotonic = 22451387292934937, checkpointNanoTimeMonotonic = 22451384630875508, nanoTimeMonotonicClockDelta = 2662059429
 [OUT] JVMJITM044W Some or all compiled code in the code cache invalidated post restore.
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime starts, current thread name: main, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401035, System.nanoTime() 22451384647125442
 [OUT] testTimeCompensation() postRestoreHook: startMillisTime (1705670396288ms) startNanoTime (22451382562097239ns) currentMillisTime (1705670401035ms) currentNanoTime (22451384646974879ns) elapsedMillisTime (4747ms) elapsedNanoTime (2084877640ns)
 [OUT] testTimeCompensation() postRestoreHook checkElapseTime ends, current thread name: main, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401039, System.nanoTime() 22451384651124948
 [OUT] 13:20:01.041 0x17000            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000007FFEC4A78
 [OUT] 13:20:01.041 0x17000            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000007FFEC4F78
 [OUT] 13:20:01.052 0x17000            j9vm.743      < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401051, System.nanoTime() 22451384663197993
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401051, System.nanoTime() 22451384663198028
 [OUT] testTimeCompensation() after CRIU restore checkElapseTime starts, current thread name: main, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401053, System.nanoTime() 22451384665074829
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms: startMillisTime (1705670401040ms) startNanoTime (22451384652071557ns) currentMillisTime (1705670401051ms) currentNanoTime (22451384663092489ns) elapsedMillisTime (11ms) elapsedNanoTime (11020932ns)
 [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401061, System.nanoTime() 22451384672403053
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms: startMillisTime (1705670398353ms) startNanoTime (22451384626649800ns) currentMillisTime (1705670401051ms) currentNanoTime (22451384663092550ns) elapsedMillisTime (2698ms) elapsedNanoTime (36442750ns)
 [OUT] testTimeCompensation() after CRIU restore: startMillisTime (1705670396288ms) startNanoTime (22451382562097239ns) currentMillisTime (1705670401053ms) currentNanoTime (22451384664989139ns) elapsedMillisTime (4765ms) elapsedNanoTime (2102891900ns)
 [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401069, System.nanoTime() 22451384680948157
 [OUT] testTimeCompensation() after CRIU restore checkElapseTime ends, current thread name: main, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401069, System.nanoTime() 22451384681223346
 [OUT] testTimeCompensation() postRestore, current thread name: main, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis(): 1705670401073, System.nanoTime(): 22451384684351341
 [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401175, System.nanoTime() 22451384786466221
 [OUT] testTimeCompensation() postRestore timer delayed 100ms: startMillisTime (1705670401074ms) startNanoTime (22451384685517599ns) currentMillisTime (1705670401175ms) currentNanoTime (22451384786303163ns) elapsedMillisTime (101ms) elapsedNanoTime (100785564ns)
 [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Fri Jan 19 08:20:01 EST 2024, System.currentTimeMillis() 1705670401177, System.nanoTime() 22451384789071518
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Fri Jan 19 08:20:02 EST 2024, System.currentTimeMillis() 1705670402952, System.nanoTime() 22451386564060121
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s: startMillisTime (1705670396288ms) startNanoTime (22451382561733199ns) currentMillisTime (1705670402951ms) currentNanoTime (22451386563187702ns) elapsedMillisTime (6663ms) elapsedNanoTime (4001454503ns)
 [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Fri Jan 19 08:20:02 EST 2024, System.currentTimeMillis() 1705670402953, System.nanoTime() 22451386565157894
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403043, System.nanoTime() 22451386654308564
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s: startMillisTime (1705670401041ms) startNanoTime (22451384652785867ns) currentMillisTime (1705670403042ms) currentNanoTime (22451386653394751ns) elapsedMillisTime (2001ms) elapsedNanoTime (2000608884ns)
 [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403043, System.nanoTime() 22451386655128368
 [OUT] testTimeCompensation() postRestore checkElapseTime starts, current thread name: main, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403075, System.nanoTime() 22451386686797858
 [OUT] testTimeCompensation() postRestore: startMillisTime (1705670401074ms) startNanoTime (22451384685494969ns) currentMillisTime (1705670403075ms) currentNanoTime (22451386686582992ns) elapsedMillisTime (2001ms) elapsedNanoTime (2001088023ns)
 [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 2s, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403075, System.nanoTime() 22451386686854419
 [OUT] testTimeCompensation() postRestore checkElapseTime ends, current thread name: main, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403077, System.nanoTime() 22451386688311755
 [OUT] testTimeCompensation() postRestore timer delayed 2s: startMillisTime (1705670401074ms) startNanoTime (22451384686010916ns) currentMillisTime (1705670403075ms) currentNanoTime (22451386686617184ns) elapsedMillisTime (2001ms) elapsedNanoTime (2000606268ns)
 [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 2s, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403077, System.nanoTime() 22451386689060835
 [OUT] getResultAndCancelTimers before Thread.yield() taskRunning = 2, current thread name: main, Fri Jan 19 08:20:03 EST 2024, System.currentTimeMillis() 1705670403079, System.nanoTime() 22451386691087163
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Fri Jan 19 08:20:05 EST 2024, System.currentTimeMillis() 1705670405018, System.nanoTime() 22451388630245412
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s: startMillisTime (1705670398353ms) startNanoTime (22451384627216044ns) currentMillisTime (1705670405018ms) currentNanoTime (22451388629352786ns) elapsedMillisTime (6665ms) elapsedNanoTime (4002136742ns)
 [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Fri Jan 19 08:20:05 EST 2024, System.currentTimeMillis() 1705670405020, System.nanoTime() 22451388631322239
 [OUT] getResultAndCancelTimers before timer.cancel(), current thread name: main, Fri Jan 19 08:20:05 EST 2024, System.currentTimeMillis() 1705670405020, System.nanoTime() 22451388631824035
 [OUT] TimeTestTask tasksPassed: true, taskStarted: 9, taskExecuted: 8, current thread name: main, Fri Jan 19 08:20:05 EST 2024, System.currentTimeMillis() 1705670405028, System.nanoTime() 22451388639818424
 [OUT] FAILED: testTimeCompensation
 [OUT] Removed test output files
 [OUT] finished script
 [ERR] /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_OMR_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 13721 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
>> Success condition was found: [Output match: Killed]
>> Success condition was not found: [Output match: PASSED: testTimeCompensation]
>> Failure condition was not found: [Output match: CRIU is not enabled]
>> Failure condition was not found: [Output match: Operation not permitted]
>> Failure condition was found: [Output match: FAILED: testTimeCompensation]
>> Success condition was not found: [Output match: Thread pid mismatch]
>> Success condition was not found: [Output match: do not match expected]
>> Success condition was not found: [Output match: Unable to create a thread:]
>> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
>> Failure condition was not found: [Output match: User requested Java dump using]

@JasonFengJ9
Copy link
Member Author

[OUT] TimeTestTask tasksPassed: true, taskStarted: 9, taskExecuted: 8, current thread name: main, Fri Jan 19 08:20:05 EST 2024, System.currentTimeMillis() 1705670405028, System.nanoTime() 22451388639818424
[OUT] FAILED: testTimeCompensation

There was no sub-test failure since tasksPassed: true, the failure was due to one task not executed as per taskStarted: 9, taskExecuted: 8, probably a test schedule issue.

@pshipton
Copy link
Member

pshipton commented Apr 1, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_Nightly_testList_0/637
cmdLineTester_criu_nonPortableRestore_8
Testing: Create CRIU checkpoint image and restore once - testTimeCompensation

@JasonFengJ9
Copy link
Member Author

JasonFengJ9 commented Apr 11, 2024 •
edited
Loading

JDK17 aarch64_linux(rhel8-aarch64-5)

openjdk version "17.0.11" 2024-04-16
IBM Semeru Runtime Open Edition 17.0.11.0-m2 (build 17.0.11+7)
Eclipse OpenJ9 VM 17.0.11.0-m2 (build v0.44.0-release-7d22ba038, JRE 17 Linux aarch64-64-Bit Compressed References 20240416_673 (JIT enabled, AOT enabled)
OpenJ9   - 7d22ba038
OMR      - 254af5a04
JCL      - fe21ca82758 based on jdk-17.0.11+7)

[2024-04-09T20:13:45.864Z] variation: -XX:+DebugOnRestore -Xjit
[2024-04-09T20:13:45.865Z] JVM_OPTIONS:  -XX:+DebugOnRestore -Xjit 

[2024-04-09T20:18:56.200Z] Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
[2024-04-09T20:18:56.200Z] Test start time: 2024/04/09 16:18:56 Eastern Standard Time
[2024-04-09T20:18:56.200Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_testList_2/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_testList_2/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_testList_2/jdkbinary/j2sdk-image/bin/java " -XX:+DebugOnRestore -Xjit  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
[2024-04-09T20:18:56.200Z] Time spent starting: 7 milliseconds
[2024-04-09T20:19:31.526Z] Time spent executing: 31075 milliseconds
[2024-04-09T20:19:31.526Z] Test result: FAILED

[2024-04-09T20:19:31.527Z]  [OUT] FAILED: testTimeCompensation() preCheckpoint timer delayed 4s elapsedMillisTime (5923ms) should NOT be less than minElapsedMillisTime (6000ms)

[2024-04-09T20:19:31.527Z]  [OUT] TimeTestTask tasksPassed: false, taskStarted: 9, taskExecuted: 9, current thread name: main, Tue Apr 09 16:19:27 EDT 2024, System.currentTimeMillis() 1712693967137, System.nanoTime() 39007443496117
[2024-04-09T20:19:31.527Z]  [OUT] FAILED: testTimeCompensation
[2024-04-09T20:19:31.527Z]  [OUT] initiate restore
[2024-04-09T20:19:31.527Z]  [OUT] Removed test output files
[2024-04-09T20:19:31.527Z]  [OUT] finished script
[2024-04-09T20:19:31.527Z]  [ERR] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_testList_2/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 471981 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
[2024-04-09T20:19:31.527Z] >> Success condition was found: [Output match: Killed]
[2024-04-09T20:19:31.527Z] >> Success condition was not found: [Output match: PASSED: testTimeCompensation]
[2024-04-09T20:19:31.527Z] >> Failure condition was not found: [Output match: CRIU is not enabled]
[2024-04-09T20:19:31.527Z] >> Failure condition was not found: [Output match: Operation not permitted]
[2024-04-09T20:19:31.527Z] >> Failure condition was found: [Output match: FAILED: testTimeCompensation]
[2024-04-09T20:19:31.527Z] >> Success condition was not found: [Output match: Thread pid mismatch]
[2024-04-09T20:19:31.527Z] >> Success condition was not found: [Output match: do not match expected]
[2024-04-09T20:19:31.527Z] >> Success condition was not found: [Output match: Unable to create a thread:]
[2024-04-09T20:19:31.527Z] >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
[2024-04-09T20:19:31.527Z] >> Failure condition was not found: [Output match: User requested Java dump using]

[2024-04-09T20:19:44.429Z] ---TEST RESULTS---
[2024-04-09T20:19:44.429Z] Number of PASSED tests: 63 out of 64
[2024-04-09T20:19:44.429Z] Number of FAILED tests: 1 out of 64
[2024-04-09T20:19:44.429Z] 
[2024-04-09T20:19:44.429Z] ---SUMMARY OF FAILED TESTS---
[2024-04-09T20:19:44.429Z] Create CRIU checkpoint image and restore once - testTimeCompensation
[2024-04-09T20:19:44.429Z] -----------------------------
[2024-04-09T20:19:44.429Z] 
[2024-04-09T20:19:44.429Z] -----------------------------------
[2024-04-09T20:19:44.429Z] cmdLineTester_criu_nonPortableRestore_9_FAILED

50x grinder - passed

@JasonFengJ9 JasonFengJ9 changed the title cmdLineTester_criu_nonPortableRestore_0_FAILED(zLinux) testTimeCompensation() after CRIU restore elapsedMillisTime (6008ms) should NOT be greater than maxElapsedMillisTime (6000ms) cmdLineTester_criu_nonPortableRestore_0_FAILED testTimeCompensation() after CRIU restore elapsedMillisTime should NOT be greater than maxElapsedMillisTime or delayed elapsedMillisTime should NOT be less than minElapsedMillisTime Apr 11, 2024
@pshipton
Copy link
Member

pshipton commented Apr 19, 2024 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_aarch64_linux_Nightly_testList_0/674 - ub20-aarch64-5
https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.functional_aarch64_linux_Nightly_testList_0/56/ - ub20-aarch64-5

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@JasonFengJ9 JasonFengJ9

Labels
comp:test criu Used to track CRIU snapshot related work test excluded test failure
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@JasonFengJ9 @pshipton @hzongaro