CRIU j9time_nano_time skips the elapsed time between Checkpoint/Restore

runtime/criusupport/criusupport.cpp

@@ -259,6 +259,8 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env,
 		char workDirBuf[STRING_BUFFER_SIZE];
 		char *workDirChars = workDirBuf;
 		BOOLEAN isAfterCheckpoint = FALSE;
+		I_64 beforeCheckpoint = 0;
+		I_64 afterRestore = 0;
 
 		vmFuncs->internalEnterVMFromJNI(currentThread);
 
@@ -399,9 +401,13 @@ Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl(JNIEnv *env,
 			goto wakeJavaThreadsWithExclusiveVMAccess;
 		}
 
-		Trc_CRIU_before_checkpoint(currentThread);
+		vm->portLibrary->checkpointRestoreTimeDelta = 0;
+		beforeCheckpoint = j9time_nano_time();
+		Trc_CRIU_before_checkpoint(currentThread, beforeCheckpoint);
 		systemReturnCode = criu_dump();
-		Trc_CRIU_after_checkpoint(currentThread);
+		afterRestore = j9time_nano_time();
+		vm->portLibrary->checkpointRestoreTimeDelta = afterRestore - beforeCheckpoint;
+		Trc_CRIU_after_checkpoint(currentThread, afterRestore, vm->portLibrary->checkpointRestoreTimeDelta);
 		if (systemReturnCode < 0) {
 			currentExceptionClass = vm->criuSystemCheckpointExceptionClass;
 			nlsMsgFormat = j9nls_lookup_message(J9NLS_DO_NOT_PRINT_MESSAGE_TAG | J9NLS_DO_NOT_APPEND_NEWLINE, J9NLS_JCL_CRIU_DUMP_FAILED, NULL);

runtime/criusupport/j9criu.tdf

@@ -33,7 +33,7 @@ TraceAssert=Assert_CRIU_mustNotHaveVMAccess noEnv Overhead=1 Level=1 Assert="0 =
 TraceException=Trc_CRIU_getNativeString_getStringSizeFail Overhead=1 Level=1 Template="Failed to get Java string size: mutf8String=%s mutf8StringSize=%zu"
 TraceException=Trc_CRIU_getNativeString_convertFail Overhead=1 Level=1 Template="Failed to convert Java string: mutf8String=%s mutf8StringSize=%zu requiredConvertedStringSize=%zd"
 
-TraceEvent=Trc_CRIU_before_checkpoint Overhead=1 Level=2 Template="Before checkpoint criu_dump()"
-TraceEvent=Trc_CRIU_after_checkpoint Overhead=1 Level=2 Template="After checkpoint criu_dump()"
+TraceEvent=Trc_CRIU_before_checkpoint Overhead=1 Level=2 Template="Before checkpoint criu_dump(), beforeCheckpoint = %lld"
+TraceEvent=Trc_CRIU_after_checkpoint Overhead=1 Level=2 Template="After checkpoint criu_dump(), afterRestore = %lld, checkpointRestoreTimeDelta = %lld"
 TraceEntry=Trc_CRIU_checkpointJVMImpl_Entry Overhead=1 Level=2 Template="Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl"
 TraceExit=Trc_CRIU_checkpointJVMImpl_Exit Overhead=1 Level=2 Template="Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl"

runtime/oti/j9port_generated.h

@@ -1,5 +1,5 @@
 /*******************************************************************************
- * Copyright (c) 1991, 2021 IBM Corp. and others
+ * Copyright (c) 1991, 2022 IBM Corp. and others
  *
  * This program and the accompanying materials are made available under
  * the terms of the Eclipse Public License 2.0 which accompanies this
@@ -387,6 +387,13 @@ typedef struct J9PortLibrary {
 #endif /* OMR_GC_CONCURRENT_SCAVENGER */
 	/** see @ref j9portcontrol.c::j9port_control "j9port_control"*/
 	int32_t (*port_control)(struct J9PortLibrary *portLibrary, const char *key, uintptr_t value) ;
+#if defined(J9VM_OPT_CRIU_SUPPORT)
+	/* The delta between Checkpoint and Restore of j9time_nano_time() return values.
+	 * It is initialized to 0 before Checkpoint, and set after restore.
+	 * Only supports one Checkpoint, could be restored multiple times.
+	 */
+	int64_t checkpointRestoreTimeDelta;
+#endif /* defined(J9VM_OPT_CRIU_SUPPORT) */
 } J9PortLibrary;
 
 #if defined(OMR_PORT_CAN_RESERVE_SPECIFIC_ADDRESS)
@@ -467,7 +474,12 @@ extern J9_CFUNC int32_t j9port_isCompatible(struct J9PortLibraryVersion *expecte
 #define j9time_usec_clock() OMRPORT_FROM_J9PORT(privatePortLibrary)->time_usec_clock(OMRPORT_FROM_J9PORT(privatePortLibrary))
 #define j9time_current_time_nanos(param1) OMRPORT_FROM_J9PORT(privatePortLibrary)->time_current_time_nanos(OMRPORT_FROM_J9PORT(privatePortLibrary),param1)
 #define j9time_current_time_millis() OMRPORT_FROM_J9PORT(privatePortLibrary)->time_current_time_millis(OMRPORT_FROM_J9PORT(privatePortLibrary))
-#define j9time_nano_time() OMRPORT_FROM_J9PORT(privatePortLibrary)->time_nano_time(OMRPORT_FROM_J9PORT(privatePortLibrary))
+#if defined(J9VM_OPT_CRIU_SUPPORT)
+#define NANO_TIME_ADJUSTMENT privatePortLibrary->checkpointRestoreTimeDelta
+#else /* defined(J9VM_OPT_CRIU_SUPPORT) */
+#define NANO_TIME_ADJUSTMENT 0
+#endif /* defined(J9VM_OPT_CRIU_SUPPORT) */
+#define j9time_nano_time() (OMRPORT_FROM_J9PORT(privatePortLibrary)->time_nano_time(OMRPORT_FROM_J9PORT(privatePortLibrary)) - NANO_TIME_ADJUSTMENT)
 #define j9time_hires_clock() OMRPORT_FROM_J9PORT(privatePortLibrary)->time_hires_clock(OMRPORT_FROM_J9PORT(privatePortLibrary))
 #define j9time_hires_frequency() OMRPORT_FROM_J9PORT(privatePortLibrary)->time_hires_frequency(OMRPORT_FROM_J9PORT(privatePortLibrary))
 #define j9time_hires_delta(param1,param2,param3) OMRPORT_FROM_J9PORT(privatePortLibrary)->time_hires_delta(OMRPORT_FROM_J9PORT(privatePortLibrary),param1,param2,param3)

test/functional/cmdLineTests/criu/criu.xml

@@ -25,9 +25,10 @@
 <!DOCTYPE suite SYSTEM "cmdlinetester.dtd">
 
 <suite id="J9 Criu Command-Line Option Tests" timeout="300">
+  <variable name="MAINCLASS_SIMPLE" value="org.openj9.criu.CRIUSimpleTest" />
 
   <test id="Create and Restore Criu Checkpoint Image once">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ "SingleCheckpoint"</command>
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ $MAINCLASS_SIMPLE$ SingleCheckpoint</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="required" caseSensitive="yes" regex="no">Post-checkpoint</output>
@@ -37,7 +38,7 @@
   </test>
 
   <test id="Create and Restore Criu Checkpoint Image twice">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ TwoCheckpoints</command>
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ $MAINCLASS_SIMPLE$ TwoCheckpoints</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="required" caseSensitive="yes" regex="no">Post-checkpoint 1</output>
@@ -47,8 +48,8 @@
     <output type="failure" caseSensitive="yes" regex="no">ERR</output>
   </test>
 
-    <test id="Create and Restore Criu Checkpoint Image three times">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ ThreeCheckpoints</command>
+  <test id="Create and Restore Criu Checkpoint Image three times">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ $JVM_OPTIONS$ $MAINCLASS_SIMPLE$ ThreeCheckpoints</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="required" caseSensitive="yes" regex="no">Post-checkpoint 1</output>

test/functional/cmdLineTests/criu/criuRandomScript.sh

@@ -31,7 +31,7 @@ echo "start running script"
 if [ "$4" = "Checkpoint" ]
 then
     # append to the file to capture the output before checkpoint and after both restores
-    $2 $3 -XX:+EnableCRIUSupport -cp $1/criu.jar CRIURandomTest >>testOutput 2>&1
+    $2 $3 -XX:+EnableCRIUSupport -cp $1/criu.jar org.openj9.criu.CRIURandomTest >>testOutput 2>&1
 fi
 if [ "$4" = "FirstRestore" ] || [ "$4" = "SecondRestore" ]
 then

test/functional/cmdLineTests/criu/criuScript.sh

@@ -23,15 +23,15 @@
 #
 
 echo "start running script";
-$2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" CRIUSimpleTest $4 >testOutput 2>&1;
+$2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 >testOutput 2>&1;
 sleep 2;
 criu restore -D ./cpData --shell-job;
-if [ "$4" == "TwoCheckpoints" ] || [ "$4" == "ThreeCheckpoints" ]
+if [ "$5" == "TwoCheckpoints" ] || [ "$5" == "ThreeCheckpoints" ]
 then
 sleep 2;
 criu restore -D ./cpData --shell-job;
 fi
-if [ "$4" == "ThreeCheckpoints" ]
+if [ "$5" == "ThreeCheckpoints" ]
 then
 sleep 2;
 criu restore -D ./cpData --shell-job;

test/functional/cmdLineTests/criu/criuSecurityScript.sh

@@ -27,7 +27,7 @@ echo "start running script"
 # $1 is the TEST_ROOT
 # $2 is the JAVA_COMMAND
 # $3 is the JVM_OPTIONS
-$2 $3 -XX:+EnableCRIUSupport -cp $1/criu.jar CRIUSecurityTest >testOutput 2>&1
+$2 $3 -XX:+EnableCRIUSupport -cp $1/criu.jar org.openj9.criu.CRIUSecurityTest >testOutput 2>&1
 criu restore -D cpData --shell-job
 cat testOutput
 rm -rf testOutput

test/functional/cmdLineTests/criu/criu_nonPortable.xml

@@ -25,9 +25,11 @@
 <!DOCTYPE suite SYSTEM "cmdlinetester.dtd">
 
 <suite id="J9 Criu Command-Line Option Tests" timeout="300">
+  <variable name="MAINCLASS_SIMPLE" value="org.openj9.criu.CRIUSimpleTest" />
+  <variable name="MAINCLASS_TIMECHANGE" value="org.openj9.criu.TimeChangeTest" />
 
   <test id="Create and Restore Criu Checkpoint Image once">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" "SingleCheckpoint"</command>
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_SIMPLE$ SingleCheckpoint</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="required" caseSensitive="yes" regex="no">Post-checkpoint</output>
@@ -37,7 +39,7 @@
   </test>
 
   <test id="Create and Restore Criu Checkpoint Image twice">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" TwoCheckpoints</command>
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_SIMPLE$ TwoCheckpoints</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="required" caseSensitive="yes" regex="no">Post-checkpoint 1</output>
@@ -48,4 +50,15 @@
     <output type="required" caseSensitive="yes" regex="no">Error</output>
   </test>
 
+  <test id="Create CRIU checkpoint image and restore three times">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_TIMECHANGE$ ThreeCheckpoints</command>
+    <output type="success" caseSensitive="no" regex="no">Killed</output>
+    <output type="required" caseSensitive="yes" regex="no">System.nanoTime() before CRIU checkpoint:</output>
+    <output type="required" caseSensitive="yes" regex="no">PASSED: System.nanoTime() after CRIU restore:</output>
+    <output type="failure" caseSensitive="yes" regex="no">CRIU is not enabled</output>
+    <output type="failure" caseSensitive="yes" regex="no">Operation not permitted</output>
+    <output type="failure" caseSensitive="yes" regex="no">FAILED: System.nanoTime() after CRIU restore:</output>
+    <output type="required" caseSensitive="yes" regex="no">Error</output>
+  </test>
+
 </suite>

test/functional/cmdLineTests/criu/src/CRIURandomTest.java → test/functional/cmdLineTests/criu/src/org/openj9/criu/CRIURandomTest.java

@@ -19,6 +19,7 @@
  *
  * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-exception-2.0 OR LicenseRef-GPL-2.0 WITH Assembly-exception
  *******************************************************************************/
+package org.openj9.criu;
 
 import java.io.BufferedReader;
 import java.io.FileReader;

test/functional/cmdLineTests/criu/src/CRIUSecurityTest.java → test/functional/cmdLineTests/criu/src/org/openj9/criu/CRIUSecurityTest.java

@@ -19,6 +19,7 @@
  *
  * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-exception-2.0 OR LicenseRef-GPL-2.0 WITH Assembly-exception
  *******************************************************************************/
+package org.openj9.criu;
 
 import java.io.File;
 import java.io.PrintStream;

test/functional/cmdLineTests/criu/src/CRIUSimpleTest.java → test/functional/cmdLineTests/criu/src/org/openj9/criu/CRIUSimpleTest.java

@@ -20,6 +20,8 @@
  *
  * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-exception-2.0 OR LicenseRef-GPL-2.0 WITH Assembly-exception
  *******************************************************************************/
+package org.openj9.criu;
+
 import java.nio.file.Paths;
 import java.nio.file.Path;
 

test/functional/cmdLineTests/criu/src/CRIUTestUtils.java → test/functional/cmdLineTests/criu/src/org/openj9/criu/CRIUTestUtils.java

@@ -19,6 +19,8 @@
  *
  * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-exception-2.0 OR LicenseRef-GPL-2.0 WITH Assembly-exception
  *******************************************************************************/
+package org.openj9.criu;
+
 import java.nio.file.Paths;
 import java.nio.file.Path;
 import java.nio.file.Files;

test/functional/cmdLineTests/criu/src/org/openj9/criu/TimeChangeTest.java

@@ -0,0 +1,49 @@
+/*******************************************************************************
+ * Copyright (c) 2022, 2022 IBM Corp. and others
+ *
+ * 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] http://openjdk.java.net/legal/assembly-exception.html
+ *
+ * SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-exception-2.0 OR LicenseRef-GPL-2.0 WITH Assembly-exception
+ *******************************************************************************/
+package org.openj9.criu;
+
+import java.nio.file.Paths;
+import java.nio.file.Path;
+
+public class TimeChangeTest {
+
+	// The elapsed time is expected less than 2 second.
+	private static long MAX_ELAPSED_TIME = 2000 * 1000 * 1000;
+	private static Path imagePath = Paths.get("cpData");
+
+	public static void main(String args[]) {
+		new TimeChangeTest().testSystemNanoTime();
+	}
+
+	public void testSystemNanoTime() {
+		final long beforeCheckpoint = System.nanoTime();
+		System.out.println("System.nanoTime() before CRIU checkpoint: " + beforeCheckpoint);
+		CRIUTestUtils.checkPointJVM(imagePath);
+		final long afterRestore = System.nanoTime();
+		final long elapsedTime = afterRestore - beforeCheckpoint;
+		if (elapsedTime < MAX_ELAPSED_TIME) {
+			System.out.println("PASSED: System.nanoTime() after CRIU restore: " + afterRestore + ", the elapse time is: " + elapsedTime);
+		} else {
+			System.out.println("FAILED: System.nanoTime() after CRIU restore: " + afterRestore + ", the elapse time is: " + elapsedTime);
+		}
+	}
+}