Merge pull request #17056 from JasonFengJ9/tracenomethods-v0.38

(v0.38.0-release) CRIU Xtrace prepares the trace output file
eclipse-openj9 · Mar 29, 2023 · 353bdb0 · 353bdb0
2 parents 23a928a + f88b0a8
commit 353bdb0
Show file tree

Hide file tree

Showing 7 changed files with 157 additions and 18 deletions.
diff --git a/runtime/rasdump/dmpsup.c b/runtime/rasdump/dmpsup.c
@@ -407,9 +407,14 @@ static IDATA
 criuReloadXDumpAgents(J9JavaVM *vm, J9VMInitArgs *vmArgs)
 {
 	/* similar with startup except at CRIU restore */
-	IDATA result = configureDumpAgents(vm, vmArgs, FALSE);
+	IDATA result = 0;
+	J9VMThread *vmThread = vm->mainThread;
+
+	Trc_trcengine_criu_criuReloadXDumpAgents_Entry(vmThread);
+	result = configureDumpAgents(vm, vmArgs, FALSE);
 	unlockConfig();
 
+	Trc_trcengine_criu_criuReloadXDumpAgents_Exit(vmThread, result);
 	return result;
 }
 #endif /* defined(J9VM_OPT_CRIU_SUPPORT) */

diff --git a/runtime/rasdump/j9dmp.tdf b/runtime/rasdump/j9dmp.tdf
@@ -39,3 +39,6 @@ TraceEvent=Trc_dump_prepareForSilentDump_Event1 NoEnv Overhead=1 Level=4 Templat
 TraceEvent=Trc_dump_unwindAfterSilentDump_Event1 NoEnv Overhead=1 Level=4 Template="Unwinding after silent dump"
 
 TraceAssert=Assert_dump_true noEnv Overhead=1 Level=1 Assert="(P1)"
+
+TraceExit=Trc_trcengine_criu_criuReloadXDumpAgents_Exit Overhead=1 Level=5 Template="criuReloadXDumpAgents() returns %zd"
+TraceEntry=Trc_trcengine_criu_criuReloadXDumpAgents_Entry Overhead=1 Level=5 Template="criuReloadXDumpAgents()"
diff --git a/runtime/rastrace/j9trc.tdf b/runtime/rastrace/j9trc.tdf
@@ -31,3 +31,10 @@ TraceEvent=Trc_trcengine_reportTraceEvent_Event2 Overhead=1 Level=1 Template="Th
 TraceEvent=Trc_trcengine_checkMethod Overhead=1 Level=1 Template="Check for method match"
 TraceEvent=Trc_trcengine_reportThreadStart Overhead=1 Level=1 Template="Thread started VMthread = %p, name = %s, nativeID = %p"
 TraceEvent=Trc_trcengine_reportThreadEnd Overhead=1 Level=1 Template="Thread ended VMthread = %p, name = %s, nativeID = %p"
+
+TraceEvent=Trc_trcengine_criu_enableMethodTraceHooks_failed Overhead=1 Level=1 Template="criuRestoreInitializeTrace(): enableMethodTraceHooks() failed"
+TraceEvent=Trc_trcengine_criu_startTraceWorkerThread_failed Overhead=1 Level=1 Template="criuRestoreInitializeTrace(): startTraceWorkerThread() failed"
+TraceEvent=Trc_trcengine_criu_traceInitializationHelper_failed Overhead=1 Level=1 Template="criuRestoreInitializeTrace(): traceInitializationHelper() failed"
+TraceEvent=Trc_trcengine_criu_nomethodentries_succeed Overhead=1 Level=5 Template="criuRestoreInitializeTrace(): no entries within traceMethodTable/triggerOnMethods, returns true"
+TraceExit=Trc_trcengine_criu_criuRestoreInitializeTrace_Exit Overhead=1 Level=5 Template="criuRestoreInitializeTrace() returns %zd"
+TraceEntry=Trc_trcengine_criu_criuRestoreInitializeTrace_Entry Overhead=1 Level=5 Template="criuRestoreInitializeTrace()"
diff --git a/runtime/rastrace/trcengine.c b/runtime/rastrace/trcengine.c
@@ -1014,20 +1014,33 @@ criuRestoreInitializeTrace(J9VMThread *thr)
 	BOOLEAN result = FALSE;
 	UtThreadData **tempThr = UT_THREAD_FROM_VM_THREAD(thr);
 
+	Trc_trcengine_criu_criuRestoreInitializeTrace_Entry(thr);
 	if (J9VMDLLMAIN_OK == traceInitializationHelper(vm, tempThr, vm->checkpointState.restoreArgsList, TRUE)) {
-		RasGlobalStorage *j9ras = (RasGlobalStorage *)vm->j9rasGlobalStorage;
-		if ((NULL != j9ras->traceMethodTable)
-			|| (NULL != j9ras->triggerOnMethods)
-		) {
-			if (OMR_ERROR_NONE == enableMethodTraceHooks(vm)
-				&& (OMR_ERROR_NONE == setupTraceWorkerThread(tempThr))
+		/* prepare the trace file first if an output is specified */
+		if (OMR_ERROR_NONE == startTraceWorkerThread(tempThr)) {
+			RasGlobalStorage *j9ras = (RasGlobalStorage *)vm->j9rasGlobalStorage;
+			if ((NULL != j9ras->traceMethodTable)
+				|| (NULL != j9ras->triggerOnMethods)
 			) {
-				vm->internalVMFunctions->addInternalJVMClassIterationRestoreHook(thr, setRAMClassExtendedMethodFlagsHelper);
+				if (OMR_ERROR_NONE == enableMethodTraceHooks(vm)) {
+					vm->internalVMFunctions->addInternalJVMClassIterationRestoreHook(thr, setRAMClassExtendedMethodFlagsHelper);
+					result = TRUE;
+				} else {
+					Trc_trcengine_criu_enableMethodTraceHooks_failed(thr);
+				}
+			} else {
+				/* no entries within traceMethodTable/triggerOnMethods */
 				result = TRUE;
+				Trc_trcengine_criu_nomethodentries_succeed(thr);
 			}
+		} else {
+			Trc_trcengine_criu_startTraceWorkerThread_failed(thr);
 		}
+	} else {
+		Trc_trcengine_criu_traceInitializationHelper_failed(thr);
 	}
 
+	Trc_trcengine_criu_criuRestoreInitializeTrace_Exit(thr, result);
 	return result;
 }
 #endif /* defined(J9VM_OPT_CRIU_SUPPORT) */

diff --git a/test/functional/cmdLineTests/criu/criu_nonPortable.xml b/test/functional/cmdLineTests/criu/criu_nonPortable.xml
@@ -624,8 +624,8 @@
     <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
     <output type="failure" caseSensitive="yes" regex="no">org.eclipse.openj9.criu.JVMRestoreException</output>
   </test>
-  <test id="Restore trace options test with no trace options specified before checkpoint">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest 1</command>
+  <test id="Restore trace options test with no trace options specified before checkpoint - 1">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest1 1</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
@@ -644,6 +644,40 @@
     <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
     <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
   </test>
+  <test id="Restore trace options test with no trace options specified before checkpoint - 2">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest2 1</command>
+    <output type="success" caseSensitive="no" regex="no">Killed</output>
+    <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
+    <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
+    <output type="success" caseSensitive="yes" regex="no">TEST PASSED</output>
+    <output type="success" caseSensitive="yes" regex="no">Post-checkpoint</output>
+    <output type="failure" caseSensitive="yes" regex="no">org.eclipse.openj9.criu.JVMRestoreException</output>
+    <output type="failure" caseSensitive="yes" regex="no">TEST FAILED</output>
+    <output type="failure" caseSensitive="yes" regex="no">CRIU is not enabled</output>
+    <output type="failure" caseSensitive="yes" regex="no">Operation not permitted</output>
+    <!-- If CRIU can't acquire the original thread IDs, this test will fail. Nothing can be done about this failure. -->
+    <output type="success" caseSensitive="yes" regex="no">Thread pid mismatch</output>
+    <output type="success" caseSensitive="yes" regex="no">do not match expected</output>
+    <output type="success" caseSensitive="yes" regex="no">Unable to create a thread:</output>
+    <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
+    <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
+  </test>
+  <test id="Restore trace options test with no trace options specified before checkpoint - 3">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest3 1</command>
+    <output type="success" caseSensitive="no" regex="no">Killed</output>
+    <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
+    <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
+    <output type="success" caseSensitive="yes" regex="no">Post-checkpoint</output>
+    <output type="failure" caseSensitive="yes" regex="no">org.eclipse.openj9.criu.JVMRestoreException</output>
+    <output type="failure" caseSensitive="yes" regex="no">CRIU is not enabled</output>
+    <output type="failure" caseSensitive="yes" regex="no">Operation not permitted</output>
+    <!-- If CRIU can't acquire the original thread IDs, this test will fail. Nothing can be done about this failure. -->
+    <output type="success" caseSensitive="yes" regex="no">Thread pid mismatch</output>
+    <output type="success" caseSensitive="yes" regex="no">do not match expected</output>
+    <output type="success" caseSensitive="yes" regex="no">Unable to create a thread:</output>
+    <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
+    <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
+  </test>
   <test id="Restore dump options test with no dump options specified before checkpoint">
     <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ DumpOptionsTest 1</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>

diff --git a/test/functional/cmdLineTests/criu/criu_nonPortable_RAS.xml b/test/functional/cmdLineTests/criu/criu_nonPortable_RAS.xml
@@ -28,8 +28,8 @@
   <variable name="MAINCLASS_OPTIONSFILE_TEST" value="org.openj9.criu.OptionsFileTest" />
   <variable name="XDUMP_DYNAMIC" value="-Xdump:dynamic" />
 
-  <test id="Restore trace options test with -Xtrace before checkpoint">
-    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest 1</command>
+  <test id="Restore trace options test with -Xtrace before checkpoint - 1">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest1 1</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>
     <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
     <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
@@ -46,6 +46,40 @@
     <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
     <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
   </test>
+  <test id="Restore trace options test with -Xtrace before checkpoint - 2">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest2 1</command>
+    <output type="success" caseSensitive="no" regex="no">Killed</output>
+    <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
+    <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
+    <output type="success" caseSensitive="yes" regex="no">Post-checkpoint</output>
+    <output type="success" caseSensitive="yes" regex="no">TEST PASSED</output>
+    <output type="failure" caseSensitive="yes" regex="no">org.eclipse.openj9.criu.JVMRestoreException</output>
+    <output type="failure" caseSensitive="yes" regex="no">TEST FAILED</output>
+    <output type="failure" caseSensitive="yes" regex="no">CRIU is not enabled</output>
+    <output type="failure" caseSensitive="yes" regex="no">Operation not permitted</output>
+    <!-- If CRIU can't acquire the original thread IDs, this test will fail. Nothing can be done about this failure. -->
+    <output type="success" caseSensitive="yes" regex="no">Thread pid mismatch</output>
+    <output type="success" caseSensitive="yes" regex="no">do not match expected</output>
+    <output type="success" caseSensitive="yes" regex="no">Unable to create a thread:</output>
+    <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
+    <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
+  </test>
+  <test id="Restore trace options test with -Xtrace before checkpoint - 3">
+    <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ TraceOptionsTest3 1</command>
+    <output type="success" caseSensitive="no" regex="no">Killed</output>
+    <output type="required" caseSensitive="yes" regex="no">Pre-checkpoint</output>
+    <output type="success" caseSensitive="yes" regex="no">terminateRemainingThreads</output>
+    <output type="success" caseSensitive="yes" regex="no">Post-checkpoint</output>
+    <output type="failure" caseSensitive="yes" regex="no">org.eclipse.openj9.criu.JVMRestoreException</output>
+    <output type="failure" caseSensitive="yes" regex="no">CRIU is not enabled</output>
+    <output type="failure" caseSensitive="yes" regex="no">Operation not permitted</output>
+    <!-- If CRIU can't acquire the original thread IDs, this test will fail. Nothing can be done about this failure. -->
+    <output type="success" caseSensitive="yes" regex="no">Thread pid mismatch</output>
+    <output type="success" caseSensitive="yes" regex="no">do not match expected</output>
+    <output type="success" caseSensitive="yes" regex="no">Unable to create a thread:</output>
+    <!-- In the past, the failure below was caused by an issue where CRIU can't be found on the PATH. -->
+    <output type="failure" caseSensitive="yes" regex="no">Could not dump the JVM processes, err=-70</output>
+  </test>
   <test id="Restore dump options test with no dump options specified before checkpoint">
     <command>bash $SCRIPPATH$ $TEST_RESROOT$ $JAVA_COMMAND$ "$JVM_OPTIONS$" $MAINCLASS_OPTIONSFILE_TEST$ DumpOptionsTest 1</command>
     <output type="success" caseSensitive="no" regex="no">Killed</output>

diff --git a/test/functional/cmdLineTests/criu/src/org/openj9/criu/OptionsFileTest.java b/test/functional/cmdLineTests/criu/src/org/openj9/criu/OptionsFileTest.java
@@ -46,8 +46,14 @@ public static void main(String[] args) {
 		case "PropertiesTest4":
 			propertiesTest4();
 			break;
-		case "TraceOptionsTest":
-			traceOptionsTest();
+		case "TraceOptionsTest1":
+			traceOptionsTest1();
+			break;
+		case "TraceOptionsTest2":
+			traceOptionsTest2();
+			break;
+		case "TraceOptionsTest3":
+			traceOptionsTest3();
 			break;
 		case "DumpOptionsTest":
 			dumpOptionsTest();
@@ -160,8 +166,8 @@ static void propertiesTest4() {
 		System.out.println("ERR: failed properties test");
 	}
 
-	static void traceOptionsTest() {
-		String traceOutput = "traceOutput.txt";
+	static void traceOptionsTest1() {
+		String traceOutput = "traceOutput1.trc";
 		String optionsContents = "-Xtrace:print={j9vm.40}\n"
 				+ "-Xtrace:print=mt,methods=java/lang/System.getProperties()\n"
 				+ "-Xtrace:trigger=method{java/lang/System.getProperties,javadump}\n"
@@ -178,12 +184,49 @@ static void traceOptionsTest() {
 		System.getProperties();
 		System.out.println("Post-checkpoint");
 		if (new File(traceOutput).exists()) {
-			System.out.println("TEST PASSED - " + traceOutput + "was created successfully");
+			System.out.println("TEST PASSED - " + traceOutput + " was created successfully");
+		} else {
+			System.out.println("TEST FAILED - " + traceOutput + " was NOT created");
+		}
+	}
+
+	static void traceOptionsTest2() {
+		String traceOutput = "traceOutput2.trc";
+		String optionsContents = "-Xtrace:print={j9vm.40}\n"
+				+ "-Xtrace:none,maximal=j9vm,output={" + traceOutput + ",100m}";
+		Path optionsFilePath = CRIUTestUtils.createOptionsFile("options", optionsContents);
+
+		Path imagePath = Paths.get("cpData");
+		CRIUTestUtils.createCheckpointDirectory(imagePath);
+		CRIUSupport criuSupport = new CRIUSupport(imagePath);
+		criuSupport.registerRestoreOptionsFile(optionsFilePath);
+
+		System.out.println("Pre-checkpoint");
+		CRIUTestUtils.checkPointJVM(criuSupport, imagePath, true);
+		System.getProperties();
+		System.out.println("Post-checkpoint");
+		if (new File(traceOutput).exists()) {
+			System.out.println("TEST PASSED - " + traceOutput + " was created successfully");
 		} else {
-			System.out.println("TEST FAILED - " + traceOutput + "was NOT created");
+			System.out.println("TEST FAILED - " + traceOutput + " was NOT created");
 		}
 	}
 
+	static void traceOptionsTest3() {
+		String optionsContents = "-Xtrace:print={j9vm.40}\n";
+		Path optionsFilePath = CRIUTestUtils.createOptionsFile("options", optionsContents);
+
+		Path imagePath = Paths.get("cpData");
+		CRIUTestUtils.createCheckpointDirectory(imagePath);
+		CRIUSupport criuSupport = new CRIUSupport(imagePath);
+		criuSupport.registerRestoreOptionsFile(optionsFilePath);
+
+		System.out.println("Pre-checkpoint");
+		CRIUTestUtils.checkPointJVM(criuSupport, imagePath, true);
+		System.getProperties();
+		System.out.println("Post-checkpoint");
+	}
+
 	static void dumpOptionsTest() {
 		String optionsContents = "-Xdump:java:events=vmstop";
 		Path optionsFilePath = CRIUTestUtils.createOptionsFile("options", optionsContents);