From 22fef30d3b522c51a3720f06426c05d65a7835b6 Mon Sep 17 00:00:00 2001 From: Jason Feng Date: Fri, 27 Oct 2023 14:17:10 -0400 Subject: [PATCH] CRIU checkpointRestoreTimeDelta adjustment & add time compensation tests Adjusted J9JavaVM->checkpointState.checkpointRestoreTimeDelta and J9PortLibrary->nanoTimeMonotonicClockDelta calculation; Added tests for CRIU and non-CRIU scenarios. Signed-off-by: Jason Feng --- runtime/criusupport/criusupport.cpp | 69 ++++---- runtime/criusupport/j9criu.tdf | 1 + .../org/openj9/test/util/TimeUtilities.java | 150 ++++++++++++++++++ .../cmdLineTest_J9tests/build.xml | 7 + .../j9tests_elapsedTime.xml | 33 ++++ .../cmdLineTest_J9tests/playlist.xml | 18 +++ .../cmdLineTest_J9tests/src/ElapsedTime.java | 67 ++++++++ test/functional/cmdLineTests/criu/build.xml | 11 ++ .../cmdLineTests/criu/criu_nonPortable.xml | 16 ++ .../src/org/openj9/criu/TimeChangeTest.java | 108 +++++++++++++ 10 files changed, 447 insertions(+), 33 deletions(-) create mode 100644 test/functional/TestUtilities/src/org/openj9/test/util/TimeUtilities.java create mode 100644 test/functional/cmdLineTests/cmdLineTest_J9tests/j9tests_elapsedTime.xml create mode 100644 test/functional/cmdLineTests/cmdLineTest_J9tests/src/ElapsedTime.java diff --git a/runtime/criusupport/criusupport.cpp b/runtime/criusupport/criusupport.cpp index c393912a35f..d8a6afdf5e5 100644 --- a/runtime/criusupport/criusupport.cpp +++ b/runtime/criusupport/criusupport.cpp @@ -941,8 +941,8 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env, VM_VMHelpers::setVMState(currentThread, J9VMSTATE_CRIU_SUPPORT_RESTORE_PHASE_START); restoreNanoTimeMonotonic = j9time_nano_time(); restoreNanoUTCTime = j9time_current_time_nanos(&success); - vm->checkpointState.lastRestoreTimeMillis = (I_64)(restoreNanoUTCTime/J9TIME_NANOSECONDS_PER_MILLIS); - Trc_CRIU_after_checkpoint(currentThread, restoreNanoTimeMonotonic, restoreNanoUTCTime); + vm->checkpointState.lastRestoreTimeMillis = (I_64)(restoreNanoUTCTime / J9TIME_NANOSECONDS_PER_MILLIS); + Trc_CRIU_after_criu_dump(currentThread, restoreNanoTimeMonotonic, restoreNanoUTCTime, vm->checkpointState.lastRestoreTimeMillis); if (!syslogFlagNone) { /* Re-open the system logger, and set options with saved string value. */ j9port_control(J9PORT_CTLDATA_SYSLOG_OPEN, 0); @@ -954,36 +954,6 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env, nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, J9NLS_JCL_CRIU_DUMP_FAILED, NULL); goto wakeJavaThreadsWithExclusiveVMAccess; } - if (0 == success) { - systemReturnCode = errno; - currentExceptionClass = vm->checkpointState.criuJVMRestoreExceptionClass; - nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, J9NLS_JCL_CRIU_J9_CURRENT_TIME_NANOS_FAILURE, NULL); - goto wakeJavaThreadsWithExclusiveVMAccess; - } - /* JVM downtime between checkpoint and restore is calculated with j9time_current_time_nanos() - * which is expected to be accurate in scenarios such as host rebooting, CRIU image moving across timezones. - */ - vm->checkpointState.checkpointRestoreTimeDelta = (I_64)(restoreNanoUTCTime - checkpointNanoUTCTime); - if (vm->checkpointState.checkpointRestoreTimeDelta < 0) { - /* A negative value was calculated for checkpointRestoreTimeDelta, - * Trc_CRIU_checkpoint_nano_times & Trc_CRIU_restore_nano_times can be used for further investigation. - * Currently OpenJ9 CRIU only supports 64-bit systems, and IDATA is equivalent to int64_t here. - */ - systemReturnCode = (IDATA)vm->checkpointState.checkpointRestoreTimeDelta; - currentExceptionClass = vm->checkpointState.criuJVMRestoreExceptionClass; - nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, - J9NLS_JCL_CRIU_NEGATIVE_CHECKPOINT_RESTORE_TIME_DELTA, NULL); - goto wakeJavaThreadsWithExclusiveVMAccess; - } - /* j9time_nano_time() might be based on a different starting point in scenarios - * such as host rebooting, CRIU image moving across timezones. - * The adjustment calculated below is expected to be same as checkpointRestoreTimeDelta - * if there is no change for j9time_nano_time() start point. - * This value might be negative. - */ - portLibrary->nanoTimeMonotonicClockDelta = restoreNanoTimeMonotonic - checkpointNanoTimeMonotonic; - Trc_CRIU_restore_nano_times(currentThread, restoreNanoUTCTime, checkpointNanoUTCTime, vm->checkpointState.checkpointRestoreTimeDelta, - restoreNanoTimeMonotonic, checkpointNanoTimeMonotonic, portLibrary->nanoTimeMonotonicClockDelta); /* We can only end up here if the CRIU restore was successful */ isAfterCheckpoint = TRUE; @@ -1021,6 +991,40 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env, goto wakeJavaThreads; } + restoreNanoTimeMonotonic = j9time_nano_time(); + restoreNanoUTCTime = j9time_current_time_nanos(&success); + if (0 == success) { + systemReturnCode = errno; + currentExceptionClass = vm->checkpointState.criuJVMRestoreExceptionClass; + nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, J9NLS_JCL_CRIU_J9_CURRENT_TIME_NANOS_FAILURE, NULL); + goto wakeJavaThreadsWithExclusiveVMAccess; + } + Trc_CRIU_after_checkpoint(currentThread, restoreNanoTimeMonotonic, restoreNanoUTCTime); + /* JVM downtime between checkpoint and restore is calculated with j9time_current_time_nanos() + * which is expected to be accurate in scenarios such as host rebooting, CRIU image moving across timezones. + */ + vm->checkpointState.checkpointRestoreTimeDelta = (I_64)(restoreNanoUTCTime - checkpointNanoUTCTime); + if (vm->checkpointState.checkpointRestoreTimeDelta < 0) { + /* A negative value was calculated for checkpointRestoreTimeDelta, + * Trc_CRIU_checkpoint_nano_times & Trc_CRIU_restore_nano_times can be used for further investigation. + * Currently OpenJ9 CRIU only supports 64-bit systems, and IDATA is equivalent to int64_t here. + */ + systemReturnCode = (IDATA)vm->checkpointState.checkpointRestoreTimeDelta; + currentExceptionClass = vm->checkpointState.criuJVMRestoreExceptionClass; + nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, + J9NLS_JCL_CRIU_NEGATIVE_CHECKPOINT_RESTORE_TIME_DELTA, NULL); + goto wakeJavaThreadsWithExclusiveVMAccess; + } + /* j9time_nano_time() might be based on a different starting point in scenarios + * such as host rebooting, CRIU image moving across timezones. + * The adjustment calculated below is expected to be same as checkpointRestoreTimeDelta + * if there is no change for j9time_nano_time() start point. + * This value might be negative. + */ + portLibrary->nanoTimeMonotonicClockDelta = restoreNanoTimeMonotonic - checkpointNanoTimeMonotonic; + Trc_CRIU_restore_nano_times(currentThread, restoreNanoUTCTime, checkpointNanoUTCTime, vm->checkpointState.checkpointRestoreTimeDelta, + restoreNanoTimeMonotonic, checkpointNanoTimeMonotonic, portLibrary->nanoTimeMonotonicClockDelta); + VM_VMHelpers::setVMState(currentThread, J9VMSTATE_CRIU_SUPPORT_RESTORE_PHASE_INTERNAL_HOOKS); if (FALSE == vmFuncs->jvmRestoreHooks(currentThread)) { @@ -1052,7 +1056,6 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env, } } - wakeJavaThreads: acquireSafeOrExcusiveVMAccess(currentThread, vmFuncs, safePoint); diff --git a/runtime/criusupport/j9criu.tdf b/runtime/criusupport/j9criu.tdf index 0dc87ccac4a..e79ac301783 100644 --- a/runtime/criusupport/j9criu.tdf +++ b/runtime/criusupport/j9criu.tdf @@ -52,3 +52,4 @@ TraceException=Trc_CRIU_setupJNIFieldIDsAndCRIUAPI_load_criu_failure Overhead=1 TraceException=Trc_CRIU_setupJNIFieldIDsAndCRIUAPI_not_find_criu_methods Overhead=1 Level=1 Template="setupJNIFieldIDsAndCRIUAPI() The JVM could not find critical criu functions in libcriu.so: %zi" TraceException=Trc_CRIU_checkpointJVMImpl_triggerOneOffJavaDump Overhead=1 Level=1 Template="checkpointJVMImpl triggerOneOffDump() returns %d" +TraceEvent=Trc_CRIU_after_criu_dump Overhead=1 Level=2 Template="After checkpoint criu_dump(), criuRestoreNanoTimeMonotonic (%lld), criuRestoreNanoUTCTime (%llu), lastRestoreTimeMillis (%lld)" diff --git a/test/functional/TestUtilities/src/org/openj9/test/util/TimeUtilities.java b/test/functional/TestUtilities/src/org/openj9/test/util/TimeUtilities.java new file mode 100644 index 00000000000..270945f1553 --- /dev/null +++ b/test/functional/TestUtilities/src/org/openj9/test/util/TimeUtilities.java @@ -0,0 +1,150 @@ +/******************************************************************************* + * Copyright IBM Corp. and others 2023 + * + * This program and the accompanying materials are made available under + * the terms of the Eclipse Public License 2.0 which accompanies this + * distribution and is available at https://www.eclipse.org/legal/epl-2.0/ + * or the Apache License, Version 2.0 which accompanies this distribution and + * is available at https://www.apache.org/licenses/LICENSE-2.0. + * + * This Source Code may also be made available under the following + * Secondary Licenses when the conditions for such availability set + * forth in the Eclipse Public License, v. 2.0 are satisfied: GNU + * General Public License, version 2 with the GNU Classpath + * Exception [1] and GNU General Public License, version 2 with the + * OpenJDK Assembly Exception [2]. + * + * [1] https://www.gnu.org/software/classpath/license.html + * [2] https://openjdk.org/legal/assembly-exception.html + * + * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-exception-2.0 OR GPL-2.0-only WITH OpenJDK-assembly-exception-1.0 + *******************************************************************************/ +package org.openj9.test.util; + +import java.util.ArrayList; +import java.util.Date; +import java.util.Timer; +import java.util.TimerTask; + +/** + * Utility class to check time. + */ +public class TimeUtilities { + public final static long TIME_NANOSECONDS_PER_MILLIS = 1000000; + + public static void showThreadCurrentTime(String msgHeader) { + System.out.println(msgHeader + ", current thread name: " + Thread.currentThread().getName() + ", " + new Date() + + ", System.currentTimeMillis() " + System.currentTimeMillis() + ", System.nanoTime() " + + System.nanoTime()); + } + + public static boolean checkElapseTime(String testName, long startMillisTime, long startNanoTime, + long minElapsedMillisTime, long maxElapsedMillisTime, long minElapsedNanoTimeInMillis, + long maxElapsedNanoTimeInMillis) { + boolean result = true; + final long currentMillisTime = System.currentTimeMillis(); + final long currentNanoTime = System.nanoTime(); + showThreadCurrentTime(testName + " checkElapseTime starts"); + + final long elapsedMillisTime = currentMillisTime - startMillisTime; + final long elapsedNanoTime = currentNanoTime - startNanoTime; + // Get the smallest value that is greater than or equal to the elapsed nano time + // in milliseconds for the case that the elapsed nano + // time is slightly less than the elapsedMillisTime, such as the elapsedNanoTime + // (1999997603ns) less than elapsedMillisTime * TIME_NANOSECONDS_PER_MILLIS + // (2000000000ns) + // This behaviour was observed in both RI and OpenJ9. + final long elapsedNanoTimeInMillis = elapsedNanoTime / TIME_NANOSECONDS_PER_MILLIS + + ((elapsedNanoTime % TIME_NANOSECONDS_PER_MILLIS == 0) ? 0 : 1); + + System.out.println(testName + ": startMillisTime (" + startMillisTime + "ms) startNanoTime (" + startNanoTime + + "ns)" + " currentMillisTime (" + currentMillisTime + "ms) currentNanoTime (" + currentNanoTime + + "ns) elapsedMillisTime (" + elapsedMillisTime + "ms) elapsedNanoTime (" + elapsedNanoTime + "ns)"); + if (elapsedMillisTime < minElapsedMillisTime) { + result = false; + System.out.println("FAILED: " + testName + " elapsedMillisTime (" + elapsedMillisTime + + "ms) should NOT be less than minElapsedMillisTime (" + minElapsedMillisTime + "ms)"); + } else if (elapsedMillisTime > maxElapsedMillisTime) { + result = false; + System.out.println("FAILED: " + testName + " elapsedMillisTime (" + elapsedMillisTime + + "ms) should NOT be greater than maxElapsedMillisTime (" + maxElapsedMillisTime + "ms)"); + } + if (elapsedNanoTimeInMillis < minElapsedNanoTimeInMillis) { + result = false; + System.out.println("FAILED: " + testName + " elapsedNanoTimeInMillis (" + elapsedNanoTimeInMillis + + "ms) should NOT be less than minElapsedNanoTimeInMillis (" + minElapsedNanoTimeInMillis + "ms)"); + } else if (elapsedNanoTimeInMillis > maxElapsedNanoTimeInMillis) { + result = false; + System.out.println("FAILED: " + testName + " elapsedNanoTimeInMillis (" + elapsedNanoTimeInMillis + + "ms) should NOT be greater than maxElapsedNanoTimeInMillis (" + maxElapsedNanoTimeInMillis + + "ms)"); + } + showThreadCurrentTime(testName + " checkElapseTime ends"); + + return result; + } + + private volatile boolean tasksPassed = true; + private volatile int taskRunning = 0; + private volatile int taskStarted = 0; + private volatile int taskExecuted = 0; + private final ArrayList timers = new ArrayList(); + + public void timerSchedule(String testName, long startMillisTime, long startNanoTime, long minElapsedMillisTime, + long maxElapsedMillisTime, long minElapsedNanoTimeInMillis, long maxElapsedNanoTimeInMillis, long delay) { + Timer timer = new Timer(testName); + timer.schedule(new TimeTestTask(testName, startMillisTime, startNanoTime, minElapsedMillisTime, + maxElapsedMillisTime, minElapsedNanoTimeInMillis, maxElapsedNanoTimeInMillis), delay); + timers.add(timer); + } + + public boolean getResultAndCancelTimers() { + showThreadCurrentTime("getResultAndCancelTimers before Thread.yield() taskRunning = " + taskRunning); + while (taskRunning > 0) { + Thread.yield(); + } + + showThreadCurrentTime("getResultAndCancelTimers before timer.cancel()"); + for (Timer timer : timers) { + timer.cancel(); + } + + showThreadCurrentTime("TimeTestTask tasksPassed: " + tasksPassed + ", taskStarted: " + taskStarted + + ", taskExecuted: " + taskExecuted); + return tasksPassed && (taskStarted == taskExecuted); + } + + class TimeTestTask extends TimerTask { + + private final String testName; + private final long startMillisTime; + private final long startNanoTime; + private final long minElapsedMillisTime; + private final long maxElapsedMillisTime; + private final long minElapsedNanoTimeInMillis; + private final long maxElapsedNanoTimeInMillis; + + TimeTestTask(String testName, long startMillisTime, long startNanoTime, long minElapsedMillisTime, + long maxElapsedMillisTime, long minElapsedNanoTimeInMillis, long maxElapsedNanoTimeInMillis) { + this.testName = testName; + this.startMillisTime = startMillisTime; + this.startNanoTime = startNanoTime; + this.minElapsedMillisTime = minElapsedMillisTime; + this.maxElapsedMillisTime = maxElapsedMillisTime; + this.minElapsedNanoTimeInMillis = minElapsedNanoTimeInMillis; + this.maxElapsedNanoTimeInMillis = maxElapsedNanoTimeInMillis; + + taskStarted++; + taskRunning++; + } + + public void run() { + taskExecuted++; + if (!checkElapseTime(testName, startMillisTime, startNanoTime, minElapsedMillisTime, maxElapsedMillisTime, + minElapsedNanoTimeInMillis, maxElapsedNanoTimeInMillis)) { + tasksPassed = false; + } + taskRunning--; + } + } +} diff --git a/test/functional/cmdLineTests/cmdLineTest_J9tests/build.xml b/test/functional/cmdLineTests/cmdLineTest_J9tests/build.xml index 764e82436bf..64d1f1e4bab 100644 --- a/test/functional/cmdLineTests/cmdLineTest_J9tests/build.xml +++ b/test/functional/cmdLineTests/cmdLineTest_J9tests/build.xml @@ -34,6 +34,7 @@ + @@ -49,6 +50,11 @@ ===debug: on ===destdir: ${DEST} + + + + + @@ -56,6 +62,7 @@ + diff --git a/test/functional/cmdLineTests/cmdLineTest_J9tests/j9tests_elapsedTime.xml b/test/functional/cmdLineTests/cmdLineTest_J9tests/j9tests_elapsedTime.xml new file mode 100644 index 00000000000..f904fae202c --- /dev/null +++ b/test/functional/cmdLineTests/cmdLineTest_J9tests/j9tests_elapsedTime.xml @@ -0,0 +1,33 @@ + + + + + + + + $EXE$ -cp $Q$$JARPATH$$Q$ ElapsedTime + Thread-0 + PASSED: testElapsedTime + FAILED: testElapsedTime + + diff --git a/test/functional/cmdLineTests/cmdLineTest_J9tests/playlist.xml b/test/functional/cmdLineTests/cmdLineTest_J9tests/playlist.xml index 7ca1fe2576e..f067ca08e69 100644 --- a/test/functional/cmdLineTests/cmdLineTest_J9tests/playlist.xml +++ b/test/functional/cmdLineTests/cmdLineTest_J9tests/playlist.xml @@ -289,4 +289,22 @@ SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-ex openj9 + + cmdLineTest_J9test_elapsedTime + $(JAVA_COMMAND) $(CMDLINETESTER_JVM_OPTIONS) \ + -DJARPATH=$(Q)$(TESTNG)$(P)$(TEST_RESROOT)$(D)cmdLineTest_J9tests.jar$(Q) \ + -DJVMLIBPATH=$(Q)$(J9VM_PATH)$(Q) \ + -DTESTDIR=$(Q)$(TEST_RESROOT)$(Q) -DRESJAR=$(CMDLINETESTER_RESJAR) -DEXE=$(SQ)$(JAVA_COMMAND) $(JVM_OPTIONS)$(SQ) \ + -jar $(CMDLINETESTER_JAR) \ + -config $(Q)$(TEST_RESROOT)$(D)j9tests_elapsedTime.xml$(Q) \ + -xids all,$(PLATFORM) -plats all,$(PLATFORM) -xlist $(Q)$(TEST_RESROOT)$(D)j9tests_exclude.xml$(Q) \ + -explainExcludes -nonZeroExitWhenError; \ + $(TEST_STATUS) + + sanity + + + functional + + diff --git a/test/functional/cmdLineTests/cmdLineTest_J9tests/src/ElapsedTime.java b/test/functional/cmdLineTests/cmdLineTest_J9tests/src/ElapsedTime.java new file mode 100644 index 00000000000..65d46cbc53a --- /dev/null +++ b/test/functional/cmdLineTests/cmdLineTest_J9tests/src/ElapsedTime.java @@ -0,0 +1,67 @@ + +/******************************************************************************* + * Copyright IBM Corp. and others 2023 + * + * This program and the accompanying materials are made available under + * the terms of the Eclipse Public License 2.0 which accompanies this + * distribution and is available at https://www.eclipse.org/legal/epl-2.0/ + * or the Apache License, Version 2.0 which accompanies this distribution and + * is available at https://www.apache.org/licenses/LICENSE-2.0. + * + * This Source Code may also be made available under the following + * Secondary Licenses when the conditions for such availability set + * forth in the Eclipse Public License, v. 2.0 are satisfied: GNU + * General Public License, version 2 with the GNU Classpath + * Exception [1] and GNU General Public License, version 2 with the + * OpenJDK Assembly Exception [2]. + * + * [1] https://www.gnu.org/software/classpath/license.html + * [2] https://openjdk.org/legal/assembly-exception.html + * + * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-exception-2.0 OR GPL-2.0-only WITH OpenJDK-assembly-exception-1.0 + *******************************************************************************/ + +import java.util.Timer; +import java.util.TimerTask; + +import org.openj9.test.util.TimeUtilities; +import org.testng.AssertJUnit; + +public class ElapsedTime { + public static void main(String[] args) throws Exception { + testElapsedTime(); + } + + private static void testElapsedTime() throws InterruptedException { + TimeUtilities tu = new TimeUtilities(); + final Object dummy = new Object(); + long millisTimeStart = System.currentTimeMillis(); + long nanoTimeStart = System.nanoTime(); + + synchronized (dummy) { + dummy.wait(100); + } + AssertJUnit.assertTrue( + tu.checkElapseTime("testElapsedTime() wait 100ms", millisTimeStart, nanoTimeStart, 100, 800, 100, 800)); + + millisTimeStart = System.currentTimeMillis(); + nanoTimeStart = System.nanoTime(); + Thread.currentThread().sleep(100); + AssertJUnit.assertTrue(tu.checkElapseTime("testElapsedTime() sleep 100ms", millisTimeStart, nanoTimeStart, 100, + 800, 100, 800)); + + millisTimeStart = System.currentTimeMillis(); + nanoTimeStart = System.nanoTime(); + tu.timerSchedule("testElapsedTime() timer delayed 100ms", millisTimeStart, nanoTimeStart, 100, 500, 100, 500, + 100); + + millisTimeStart = System.currentTimeMillis(); + nanoTimeStart = System.nanoTime(); + tu.timerSchedule("testElapsedTime() timer delayed 2s", millisTimeStart, nanoTimeStart, 2000, 3000, 2000, 3000, + 2000); + + AssertJUnit.assertTrue(tu.getResultAndCancelTimers()); + + System.out.println("PASSED: testElapsedTime()"); + } +} diff --git a/test/functional/cmdLineTests/criu/build.xml b/test/functional/cmdLineTests/criu/build.xml index 169503294c3..84e5dcbb084 100644 --- a/test/functional/cmdLineTests/criu/build.xml +++ b/test/functional/cmdLineTests/criu/build.xml @@ -33,6 +33,7 @@ + @@ -66,6 +67,11 @@ + + + + + @@ -76,6 +82,11 @@ + + + + + diff --git a/test/functional/cmdLineTests/criu/criu_nonPortable.xml b/test/functional/cmdLineTests/criu/criu_nonPortable.xml index 90619b79ba8..9d9aa02a8ba 100644 --- a/test/functional/cmdLineTests/criu/criu_nonPortable.xml +++ b/test/functional/cmdLineTests/criu/criu_nonPortable.xml @@ -1030,4 +1030,20 @@ Could not dump the JVM processes, err=-70 User requested Java dump using + + + bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$ -Xtrace:print={j9criu,j9jcl.533} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" $MAINCLASS_TIMECHANGE$ testTimeCompensation 1 false false + Killed + PASSED: testTimeCompensation + CRIU is not enabled + Operation not permitted + FAILED: testTimeCompensation + + Thread pid mismatch + do not match expected + Unable to create a thread: + + Could not dump the JVM processes, err=-70 + User requested Java dump using + diff --git a/test/functional/cmdLineTests/criu/src/org/openj9/criu/TimeChangeTest.java b/test/functional/cmdLineTests/criu/src/org/openj9/criu/TimeChangeTest.java index e9c8551ba90..a6ee3c1075d 100644 --- a/test/functional/cmdLineTests/criu/src/org/openj9/criu/TimeChangeTest.java +++ b/test/functional/cmdLineTests/criu/src/org/openj9/criu/TimeChangeTest.java @@ -25,11 +25,16 @@ import java.lang.management.RuntimeMXBean; import java.nio.file.Path; import java.nio.file.Paths; +import java.util.ArrayList; import java.util.Date; import java.util.Timer; import java.util.TimerTask; import openj9.internal.criu.InternalCRIUSupport; +import org.eclipse.openj9.criu.CRIUSupport; + +import org.openj9.test.util.TimeUtilities; +import org.testng.AssertJUnit; public class TimeChangeTest { @@ -66,6 +71,9 @@ public static void main(String args[]) throws InterruptedException { case "testSystemNanoTimeJitPostCheckpointCompile": tct.testSystemNanoTimeJitPostCheckpointCompile(); break; + case "testTimeCompensation": + tct.testTimeCompensation(); + break; default: // timer related tests tct.test(testName); @@ -100,6 +108,106 @@ private void test(String testName) throws InterruptedException { timer.cancel(); } + private void testTimeCompensation() throws InterruptedException { + CRIUSupport criu = CRIUTestUtils.prepareCheckPointJVM(CRIUTestUtils.imagePath); + if (criu == null) { + // "CRIU is not enabled" is to appear and cause the test failure. + return; + } + CRIUTestUtils.showThreadCurrentTime("testTimeCompensation() starts"); + final TimeUtilities tu = new TimeUtilities(); + final Object dummy = new Object(); + long millisTimeStart = System.currentTimeMillis(); + long nanoTimeStart = System.nanoTime(); + + synchronized (dummy) { + dummy.wait(100); + } + TimeUtilities.checkElapseTime("testTimeCompensation() wait 100ms", millisTimeStart, nanoTimeStart, 100, 800, + 100, 800); + + millisTimeStart = System.currentTimeMillis(); + nanoTimeStart = System.nanoTime(); + Thread.currentThread().sleep(100); + TimeUtilities.checkElapseTime("testTimeCompensation() sleep 100ms", millisTimeStart, nanoTimeStart, 100, 800, + 100, 800); + + // this TimerTask is to run before CRIUR checkpoint + tu.timerSchedule("testTimeCompensation() preCheckpoint timer delayed 100ms", System.currentTimeMillis(), + System.nanoTime(), 100, 500, 100, 500, 100); + + // this TimerTask is to run before CRIUR checkpoint + tu.timerSchedule("testTimeCompensation() preCheckpoint timer delayed 2s", System.currentTimeMillis(), + System.nanoTime(), 2000, 3000, 2000, 3000, 2000); + + // this TimerTask is to run after CRIUR restore + tu.timerSchedule("testTimeCompensation() preCheckpoint timer delayed 4s", System.currentTimeMillis(), + System.nanoTime(), 6000, 10000, 4000, 8000, 4000); + + final long preCheckpointMillisTime = System.currentTimeMillis(); + final long preCheckpointNanoTime = System.nanoTime(); + + Thread.currentThread().sleep(2000); + + criu.registerPreCheckpointHook(new Runnable() { + public void run() { + // check time elapsed within preCheckpoint hook + TimeUtilities.checkElapseTime("testTimeCompensation() preCheckpointHook", preCheckpointMillisTime, + preCheckpointNanoTime, 2000, 4000, 2000, 4000); + + // scheduled task can't run before the checkpoint because all threads are halted + // in single threaded mode except the current thread performing CRIU checkpoit + tu.timerSchedule("testTimeCompensation()() preCheckpointHook timer delayed 10ms", + System.currentTimeMillis(), System.nanoTime(), 2000, 8000, 10, 500, 10); + tu.timerSchedule("testTimeCompensation() preCheckpointHook timer delayed 4s", + System.currentTimeMillis(), System.nanoTime(), 6000, 10000, 4000, 4500, 4000); + } + }); + // assuming 2s between CRIU checkpoint and restore at criuScript.sh + criu.registerPostRestoreHook(new Runnable() { + public void run() { + // check time elapsed within postRestore hook + TimeUtilities.checkElapseTime("testTimeCompensation() postRestoreHook", preCheckpointMillisTime, + preCheckpointNanoTime, 4000, 8000, 2000, 4000); + + tu.timerSchedule("testTimeCompensation() postRestoreHook timer delayed 10ms", + System.currentTimeMillis(), System.nanoTime(), 10, 800, 9, 800, 10); + tu.timerSchedule("testTimeCompensation() postRestoreHook timer delayed 2s", System.currentTimeMillis(), + System.nanoTime(), 2000, 3000, 2000, 3000, 2000); + } + }); + + TimeUtilities.checkElapseTime("testTimeCompensation() preCheckpoint", preCheckpointMillisTime, + preCheckpointNanoTime, 2000, 3000, 2000, 3000); + + CRIUTestUtils.checkPointJVMNoSetup(criu, CRIUTestUtils.imagePath, false); + + TimeUtilities.checkElapseTime("testTimeCompensation() after CRIU restore", preCheckpointMillisTime, + preCheckpointNanoTime, 2000, 6000, 2000, 6000); + + CRIUTestUtils.showThreadCurrentTime("testTimeCompensation() postRestore"); + final long postRestoreMillisTime = System.currentTimeMillis(); + final long postRestoreNanoTime = System.nanoTime(); + + // following two timer tasks are expected to run after taking a checkpoint + tu.timerSchedule("testTimeCompensation() postRestore timer delayed 100ms", System.currentTimeMillis(), + System.nanoTime(), 100, 800, 100, 800, 100); + + tu.timerSchedule("testTimeCompensation() postRestore timer delayed 2s", System.currentTimeMillis(), + System.nanoTime(), 2000, 3000, 2000, 3000, 2000); + + Thread.currentThread().sleep(2000); + + TimeUtilities.checkElapseTime("testTimeCompensation() postRestore", postRestoreMillisTime, postRestoreNanoTime, + 2000, 3000, 2000, 3000); + + if (tu.getResultAndCancelTimers()) { + System.out.println("PASSED: " + "testTimeCompensation"); + } else { + System.out.println("FAILED: " + "testTimeCompensation"); + } + } + public void testSystemNanoTime() { final long beforeCheckpoint = System.nanoTime(); System.out.println("System.nanoTime() before CRIU checkpoint: " + beforeCheckpoint);