Merge pull request #21882 from thallium/jfr-gc-event

Add JFR SystemGC event

Author: tajila

runtime/oti/j9consts.h

@@ -958,6 +958,7 @@ extern "C" {
 #define J9JFR_EVENT_TYPE_THREAD_PARK 9
 #define J9JFR_EVENT_TYPE_THREAD_STATISTICS 10
 #define J9JFR_EVENT_TYPE_MONITOR_ENTER 11
+#define J9JFR_EVENT_TYPE_SYSTEM_GC 12
 
 /* JFR thread states */
 

runtime/oti/j9nonbuilder.h

@@ -498,6 +498,13 @@ typedef struct J9JFRThreadContextSwitchRate {
 	float switchRate;
 } J9JFRThreadContextSwitchRate;
 
+typedef struct J9JFRSystemGC {
+	J9JFR_EVENT_WITH_STACKTRACE_FIELDS
+	I_64 duration;
+} J9JFRSystemGC;
+
+#define J9JFRSYSTEMGC_STACKTRACE(jfrEvent) ((UDATA *)(((J9JFRSystemGC *)(jfrEvent)) + 1))
+
 #endif /* defined(J9VM_OPT_JFR) */
 
 /* @ddr_namespace: map_to_type=J9CfrError */

runtime/oti/j9vm.hdf

@@ -1421,4 +1421,12 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		<struct>J9VMCRIURestoreEvent</struct>
 		<data type="struct J9VMThread*" name="vmThread" description="current thread" />
 	</event>
+
+	<event>
+		<name>J9HOOK_SYSTEM_GC_CALLED</name>
+		<description>Triggered after GC is done</description>
+		<struct>J9VMSystemGCEvent</struct>
+		<data type="struct J9VMThread*" name="currentThread" description="current thread" />
+		<data type="I_64" name="startTicks" description="current ticks when GC began" />
+	</event>
 </interface>

runtime/sunvmi/sunvmi.c

@@ -614,9 +614,12 @@ getClassContextIterator(J9VMThread * currentThread, J9StackWalkState * walkState
 JNIEXPORT void JNICALL
 JVM_GC_Impl(void)
 {
-	J9InternalVMFunctions *vmFuncs = VM.javaVM->internalVMFunctions;
-	J9VMThread *currentThread = vmFuncs->currentVMThread(VM.javaVM);
-	J9MemoryManagerFunctions *mmFuncs = VM.javaVM->memoryManagerFunctions;
+	J9JavaVM *vm = VM.javaVM;
+	J9InternalVMFunctions *vmFuncs = vm->internalVMFunctions;
+	J9VMThread *currentThread = vmFuncs->currentVMThread(vm);
+	J9MemoryManagerFunctions *mmFuncs = vm->memoryManagerFunctions;
+	I_64 startTicks = 0;
+	PORT_ACCESS_FROM_JAVAVM(vm);
 
 	Trc_SunVMI_GC_Entry(currentThread);
 
@@ -626,9 +629,14 @@ JVM_GC_Impl(void)
 	vmFuncs->internalAcquireVMAccess(currentThread);
 #endif /* J9VM_INTERP_ATOMIC_FREE_JNI */
 
+	if (J9_EVENT_IS_HOOKED(vm->hookInterface, J9HOOK_SYSTEM_GC_CALLED)) {
+		startTicks = j9time_nano_time();
+	}
+
 	/* Two GC requests are required to guarantee a GC actually occurs. */
 	mmFuncs->j9gc_modron_global_collect(currentThread);
 	mmFuncs->j9gc_modron_global_collect(currentThread);
+	TRIGGER_J9HOOK_SYSTEM_GC_CALLED(vm->hookInterface, currentThread, startTicks);
 
 	/* make sure we actually release VMAccess as finalization cannot be run with it */
 	vmFuncs->internalReleaseVMAccess(currentThread);

runtime/vm/JFRChunkWriter.cpp

@@ -1367,4 +1367,35 @@ VM_JFRChunkWriter::writeSystemProcessEvent(void *anElement, void *userData)
 	entry->commandLine = NULL;
 }
 
+void
+VM_JFRChunkWriter::writeSystemGCEvent(void *anElement, void *userData)
+{
+	SystemGCEntry *entry = (SystemGCEntry *)anElement;
+	VM_BufferWriter *bufferWriter = (VM_BufferWriter *)userData;
+
+	/* Reserve size field */
+	U_8 *dataStart = reserveEventSize(bufferWriter);
+
+	/* Write event type */
+	bufferWriter->writeLEB128(SystemGCID);
+
+	/* Write start time */
+	bufferWriter->writeLEB128(entry->ticks);
+
+	/* Write duration time which is always in ticks, in our case nanos */
+	bufferWriter->writeLEB128(entry->duration);
+
+	/* Write event thread index */
+	bufferWriter->writeLEB128(entry->eventThreadIndex);
+
+	/* Wtacktrace index */
+	bufferWriter->writeLEB128(entry->stackTraceIndex);
+
+	/* Write invokedConcurrent which is always false for OpenJ9 */
+	bufferWriter->writeBoolean(false);
+
+	/* Write size */
+	writeEventSize(bufferWriter, dataStart);
+}
+
 #endif /* defined(J9VM_OPT_JFR) */

runtime/vm/JFRChunkWriter.hpp

@@ -72,6 +72,7 @@ enum MetadataTypeID {
 	ThreadParkID = 5,
 	MonitorEnterID = 6,
 	MonitorWaitID = 7,
+	SystemGCID = 36,
 	JVMInformationID = 87,
 	OSInformationID = 88,
 	VirtualizationInformationID = 89,
@@ -190,6 +191,7 @@ class VM_JFRChunkWriter {
 	static constexpr int THREAD_DUMP_EVENT_SIZE_PER_THREAD = 1000;
 	static constexpr int SYSTEM_PROCESS_EVENT_SIZE = (4 * sizeof(U_64)) + 32 /* pid string */;
 	static constexpr int NATIVE_LIBRARY_ADDRESS_SIZE = (4 * sizeof(U_64)) + (2 * sizeof(UDATA)) + sizeof(U_8);
+	static constexpr int SYSTEM_GC_EVENT_SIZE = (2 * LEB128_64_SIZE) + (3 * LEB128_32_SIZE) + sizeof(U_8);
 
 	static constexpr int METADATA_ID = 1;
 
@@ -402,6 +404,8 @@ class VM_JFRChunkWriter {
 
 			pool_do(_constantPoolTypes.getThreadStatisticsTable(), &writeThreadStatisticsEvent, _bufferWriter);
 
+			pool_do(_constantPoolTypes.getSystemGCTable(), &writeSystemGCEvent, _bufferWriter);
+
 			/* Only write constant events in first chunk */
 			if (0 == _vm->jfrState.jfrChunkCount) {
 				writeJVMInformationEvent();
@@ -842,6 +846,8 @@ class VM_JFRChunkWriter {
 
 	static void writeNativeLibraryEvent(void *anElement, void *userData);
 
+	static void writeSystemGCEvent(void *anElement, void *userData);
+
 	UDATA
 	calculateRequiredBufferSize()
 	{
@@ -920,6 +926,8 @@ class VM_JFRChunkWriter {
 		requiredBufferSize += (_constantPoolTypes.getNativeLibraryCount() * NATIVE_LIBRARY_ADDRESS_SIZE)
 				+ _constantPoolTypes.getNativeLibraryPathSizeTotal();
 
+		requiredBufferSize += (_constantPoolTypes.getsystemGCCount() * SYSTEM_GC_EVENT_SIZE);
+
 		return requiredBufferSize;
 	}
 

runtime/vm/JFRConstantPoolTypes.cpp

@@ -1272,6 +1272,32 @@ VM_JFRConstantPoolTypes::addThreadStatisticsEntry(J9JFRThreadStatistics *threadS
 	return;
 }
 
+void
+VM_JFRConstantPoolTypes::addSystemGCEntry(J9JFRSystemGC *systemGCData)
+{
+	SystemGCEntry *entry = (SystemGCEntry *)pool_newElement(_systemGCTable);
+
+	if (NULL == entry) {
+		_buildResult = OutOfMemory;
+		goto done;
+	}
+
+	entry->ticks = systemGCData->startTicks;
+	entry->duration = systemGCData->duration;
+
+	entry->eventThreadIndex = addThreadEntry(systemGCData->vmThread);
+	if (isResultNotOKay()) goto done;
+
+	entry->stackTraceIndex = consumeStackTrace(systemGCData->vmThread, J9JFRSYSTEMGC_STACKTRACE(systemGCData), systemGCData->stackTraceSize);
+	if (isResultNotOKay()) goto done;
+
+	_systemGCCount += 1;
+
+done:
+	return;
+
+}
+
 void
 VM_JFRConstantPoolTypes::printTables()
 {

runtime/vm/JFRConstantPoolTypes.hpp

@@ -275,6 +275,13 @@ struct ThreadStatisticsEntry {
 	U_64 peakThreadCount;
 };
 
+struct SystemGCEntry {
+	I_64 ticks;
+	I_64 duration;
+	U_32 eventThreadIndex;
+	U_32 stackTraceIndex;
+};
+
 struct JVMInformationEntry {
 	const char *jvmName;
 	const char *jvmVersion;
@@ -402,6 +409,8 @@ class VM_JFRConstantPoolTypes {
 	J9Pool *_nativeLibrariesTable;
 	UDATA _nativeLibrariesCount;
 	UDATA _nativeLibraryPathSizeTotal;
+	J9Pool *_systemGCTable;
+	UDATA _systemGCCount;
 
 	/* Processing buffers */
 	StackFrame *_currentStackFrameBuffer;
@@ -679,6 +688,8 @@ class VM_JFRConstantPoolTypes {
 
 	void addThreadStatisticsEntry(J9JFRThreadStatistics *threadStatisticsData);
 
+	void addSystemGCEntry(J9JFRSystemGC *systemGCData);
+
 	J9Pool *getExecutionSampleTable()
 	{
 		return _executionSampleTable;
@@ -754,6 +765,16 @@ class VM_JFRConstantPoolTypes {
 		return _executionSampleCount;
 	}
 
+	J9Pool *getSystemGCTable()
+	{
+		return _systemGCTable;
+	}
+
+	UDATA getsystemGCCount()
+	{
+		return _systemGCCount;
+	}
+
 	UDATA getThreadStartCount()
 	{
 		return _threadStartCount;
@@ -995,6 +1016,9 @@ class VM_JFRConstantPoolTypes {
 			case J9JFR_EVENT_TYPE_THREAD_STATISTICS:
 				addThreadStatisticsEntry((J9JFRThreadStatistics *)event);
 				break;
+			case J9JFR_EVENT_TYPE_SYSTEM_GC:
+				addSystemGCEntry((J9JFRSystemGC *)event);
+				break;
 			default:
 				Assert_VM_unreachable();
 				break;
@@ -1471,6 +1495,8 @@ class VM_JFRConstantPoolTypes {
 		, _nativeLibrariesTable(NULL)
 		, _nativeLibrariesCount(0)
 		, _nativeLibraryPathSizeTotal(0)
+		, _systemGCTable(NULL)
+		, _systemGCCount(0)
 		, _previousStackTraceEntry(NULL)
 		, _firstStackTraceEntry(NULL)
 		, _previousThreadEntry(NULL)
@@ -1629,6 +1655,12 @@ class VM_JFRConstantPoolTypes {
 			goto done;
 		}
 
+		_systemGCTable = pool_new(sizeof(SystemGCEntry), 0, sizeof(U_64), 0, J9_GET_CALLSITE(), OMRMEM_CATEGORY_VM, POOL_FOR_PORT(privatePortLibrary));
+		if (NULL == _systemGCTable) {
+			_buildResult = OutOfMemory;
+			goto done;
+		}
+
 		/* Add reserved index for default entries. For strings zero is the empty or NUll string.
 		 * For package zero is the deafult package, for Module zero is the unnamed module. ThreadGroup
 		 * zero is NULL threadGroup.
@@ -1724,6 +1756,7 @@ class VM_JFRConstantPoolTypes {
 		pool_kill(_threadStatisticsTable);
 		pool_kill(_systemProcessTable);
 		pool_kill(_nativeLibrariesTable);
+		pool_kill(_systemGCTable);
 		j9mem_free_memory(_globalStringTable);
 	}
 

runtime/vm/jfr.cpp

@@ -114,6 +114,9 @@ jfrEventSize(J9JFREvent *jfrEvent)
 	case J9JFR_EVENT_TYPE_THREAD_STATISTICS:
 		size = sizeof(J9JFRThreadStatistics);
 		break;
+	case J9JFR_EVENT_TYPE_SYSTEM_GC:
+		size = sizeof(J9JFRSystemGC) + (((J9JFRSystemGC *)jfrEvent)->stackTraceSize * sizeof(UDATA));
+		break;
 	default:
 		Assert_VM_unreachable();
 		break;
@@ -714,6 +717,27 @@ jfrVMThreadParked(J9HookInterface **hook, UDATA eventNum, void *eventData, void*
 	}
 }
 
+/**
+ * Hook for system GC. Called without VM access.
+ *
+ * @param hook[in] the VM hook interface
+ * @param eventNum[in] the event number
+ * @param eventData[in] the event data
+ * @param userData[in] the registered user data
+ */
+static void
+jfrSystemGC(J9HookInterface **hook, UDATA eventNum, void *eventData, void* userData)
+{
+	J9VMSystemGCEvent *event = (J9VMSystemGCEvent *)eventData;
+	J9VMThread *currentThread = event->currentThread;
+	PORT_ACCESS_FROM_VMC(currentThread);
+
+	J9JFRSystemGC *jfrEvent = (J9JFRSystemGC *)reserveBufferWithStackTrace(currentThread, currentThread, J9JFR_EVENT_TYPE_SYSTEM_GC, sizeof(*jfrEvent));
+	if (NULL != jfrEvent) {
+		jfrEvent->startTicks = event->startTicks;
+		jfrEvent->duration = j9time_nano_time() - event->startTicks;
+	}
+}
 
 jint
 initializeJFR(J9JavaVM *vm, BOOLEAN lateInit)
@@ -773,6 +797,9 @@ initializeJFR(J9JavaVM *vm, BOOLEAN lateInit)
 	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_UNPARKED, jfrVMThreadParked, OMR_GET_CALLSITE(), NULL)) {
 		goto fail;
 	}
+	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_SYSTEM_GC_CALLED, jfrSystemGC, OMR_GET_CALLSITE(), NULL)) {
+		goto fail;
+	}
 
 	/* Allocate constantEvents. */
 	vm->jfrState.constantEvents = j9mem_allocate_memory(sizeof(JFRConstantEvents), J9MEM_CATEGORY_VM);
@@ -906,6 +933,7 @@ tearDownJFR(J9JavaVM *vm)
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_MONITOR_WAITED, jfrVMMonitorWaited, NULL);
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_MONITOR_CONTENDED_ENTERED, jfrVMMonitorEntered, NULL);
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_UNPARKED, jfrVMThreadParked, NULL);
+	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_SYSTEM_GC_CALLED, jfrSystemGC, NULL);
 
 	/* Free global data */
 	VM_JFRConstantPoolTypes::freeJFRConstantEvents(vm);

test/functional/cmdLineTests/jfr/jfrevents.xml

@@ -104,4 +104,11 @@ SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0-only WITH Classpath-ex
 		<output type="required" caseSensitive="yes" regex="no">topAddress</output>
 		<output type="failure" caseSensitive="yes" regex="no">jfr print: could not read recording</output>
 	</test>
+	<test id="test jfr SystemGC - approx 30 seconds">
+		<command>$JFR_EXE$ print --xml --events "SystemGC" defaultJ9recording.jfr</command>
+		<output type="required" caseSensitive="yes" regex="no">http://www.w3.org/2001/XMLSchema-instance</output>
+		<output type="success" caseSensitive="yes" regex="no">jdk.SystemGC</output>
+		<output type="required" caseSensitive="yes" regex="no">invokedConcurrent</output>
+		<output type="failure" caseSensitive="yes" regex="no">jfr print: could not read recording</output>
+	</test>
 </suite>