search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 722 forks source link

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 11 months ago

JasonFengJ9 commented 11 months ago

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.

hzongaro commented 11 months ago

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

pshipton commented 11 months ago

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 commented 11 months ago

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

pshipton commented 11 months ago

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

JasonFengJ9 commented 11 months ago

https://github.com/eclipse-openj9/openj9/issues/18513#issuecomment-1836095048 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 commented 9 months ago

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 commented 9 months ago

[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 commented 7 months ago

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 commented 7 months ago

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

pshipton commented 6 months ago

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