Merge pull request #21179 from adpopescu/jfr-monitor

Add JFR monitor enter event

Author: keithc-ca

runtime/oti/j9consts.h

@@ -955,6 +955,7 @@ extern "C" {
 #define J9JFR_EVENT_TYPE_THREAD_CONTEXT_SWITCH_RATE 8
 #define J9JFR_EVENT_TYPE_THREAD_PARK 9
 #define J9JFR_EVENT_TYPE_THREAD_STATISTICS 10
+#define J9JFR_EVENT_TYPE_MONITOR_ENTER 11
 
 /* JFR thread states */
 

runtime/oti/j9nonbuilder.h

@@ -441,6 +441,17 @@ typedef struct J9JFRThreadParked {
 
 #define J9JFRTHREADPARKED_STACKTRACE(jfrEvent) ((UDATA*)(((J9JFRThreadParked*)(jfrEvent)) + 1))
 
+typedef struct J9JFRMonitorEntered {
+	J9JFR_EVENT_WITH_STACKTRACE_FIELDS
+	I_64 duration;
+	struct J9VMThread *thread;
+	struct J9Class *monitorClass;
+	struct J9VMThread *previousOwner;
+	UDATA monitorAddress;
+} J9JFRMonitorEntered;
+
+#define J9JFRMONITORENTERED_STACKTRACE(jfrEvent) ((UDATA *)(((J9JFRMonitorEntered *)(jfrEvent)) + 1))
+
 typedef struct J9JFRCPULoad {
 	J9JFR_EVENT_COMMON_FIELDS
 	float jvmUser;

runtime/oti/j9vm.hdf

@@ -229,6 +229,9 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		<struct>J9VMMonitorContendedEnteredEvent</struct>
 		<data type="struct J9VMThread*" name="currentThread" description="current thread" />
 		<data type="omrthread_monitor_t" name="monitor" description="the contended monitor" />
+		<data type="I_64" name="startTicks" description="current ticks when wait began" />
+		<data type="struct J9Class*" name="monitorClass" description="object monitor class" />
+		<data type="struct J9VMThread*" name="previousOwner" description="previous owner thread" />
 	</event>
 
 	<event>

runtime/vm/JFRChunkWriter.hpp

@@ -66,6 +66,7 @@ enum MetadataTypeID {
 	ThreadEndID = 3,
 	ThreadSleepID = 4,
 	ThreadParkID = 5,
+	MonitorEnterID = 6,
 	MonitorWaitID = 7,
 	JVMInformationID = 87,
 	OSInformationID = 88,
@@ -140,6 +141,8 @@ class VM_JFRChunkWriter {
 	static constexpr int JFR_CHUNK_HEADER_SIZE = 68;
 
 	/* conservative sizing for JFR chunk */
+	static constexpr int LEB128_32_SIZE = 5;
+	static constexpr int LEB128_64_SIZE = 9;
 	static constexpr int STRING_HEADER_LENGTH = sizeof(U_64);
 	static constexpr int CHECKPOINT_EVENT_HEADER_AND_FOOTER = 68;
 	static constexpr int STRING_CONSTANT_SIZE = 128;
@@ -159,6 +162,7 @@ class VM_JFRChunkWriter {
 	static constexpr int THREAD_END_EVENT_SIZE = (4 * sizeof(U_64)) + sizeof(U_32);
 	static constexpr int THREAD_SLEEP_EVENT_SIZE = (7 * sizeof(U_64)) + sizeof(U_32);
 	static constexpr int MONITOR_WAIT_EVENT_SIZE = (9 * sizeof(U_64)) + sizeof(U_32);
+	static constexpr int MONITOR_ENTER_EVENT_SIZE = sizeof(U_32) + (3 * LEB128_64_SIZE) + (5 * LEB128_32_SIZE);
 	static constexpr int THREAD_PARK_EVENT_SIZE = (9 * sizeof(U_64)) + sizeof(U_32);
 	static constexpr int JVM_INFORMATION_EVENT_SIZE = 3000;
 	static constexpr int PHYSICAL_MEMORY_EVENT_SIZE = (4 * sizeof(U_64)) + sizeof(U_32);
@@ -366,6 +370,8 @@ class VM_JFRChunkWriter {
 
 			pool_do(_constantPoolTypes.getMonitorWaitTable(), &writeMonitorWaitEvent, _bufferWriter);
 
+			pool_do(_constantPoolTypes.getMonitorEnterTable(), &writeMonitorEnterEvent, _bufferWriter);
+
 			pool_do(_constantPoolTypes.getThreadParkTable(), &writeThreadParkEvent, _bufferWriter);
 
 			pool_do(_constantPoolTypes.getCPULoadTable(), &writeCPULoadEvent, _bufferWriter);
@@ -583,6 +589,45 @@ class VM_JFRChunkWriter {
 		writeEventSize(_bufferWriter, dataStart);
 	}
 
+	static void
+	writeMonitorEnterEvent(void *anElement, void *userData)
+	{
+		MonitorEnterEntry *entry = (MonitorEnterEntry *)anElement;
+		VM_BufferWriter *_bufferWriter = (VM_BufferWriter *)userData;
+
+		/* reserve size field */
+		U_8 *dataStart = _bufferWriter->getAndIncCursor(sizeof(U_32));
+
+		/* write event type */
+		_bufferWriter->writeLEB128(MonitorEnterID);
+
+		/* write start time - this is when the sleep started not when it ended so we
+		 * need to subtract the duration since the event is emitted when the sleep ends.
+		 */
+		_bufferWriter->writeLEB128(entry->ticks - entry->duration);
+
+		/* write duration time which is always in ticks, in our case nanos */
+		_bufferWriter->writeLEB128(entry->duration);
+
+		/* write event thread index */
+		_bufferWriter->writeLEB128(entry->eventThreadIndex);
+
+		/* stacktrace index */
+		_bufferWriter->writeLEB128(entry->stackTraceIndex);
+
+		/* monitor class index */
+		_bufferWriter->writeLEB128(entry->monitorClass);
+
+		/* notifier thread index */
+		_bufferWriter->writeLEB128(entry->previousOwnerThread);
+
+		/* address of monitor */
+		_bufferWriter->writeLEB128(entry->monitorAddress);
+
+		/* write size */
+		writeEventSize(_bufferWriter, dataStart);
+	}
+
 	static void
 	writeThreadParkEvent(void *anElement, void *userData)
 	{
@@ -797,6 +842,8 @@ class VM_JFRChunkWriter {
 
 		requiredBufferSize += (_constantPoolTypes.getMonitorWaitCount() * MONITOR_WAIT_EVENT_SIZE);
 
+		requiredBufferSize += (_constantPoolTypes.getMonitorEnterCount() * MONITOR_ENTER_EVENT_SIZE);
+
 		requiredBufferSize += (_constantPoolTypes.getThreadParkCount() * THREAD_PARK_EVENT_SIZE);
 
 		requiredBufferSize += JVM_INFORMATION_EVENT_SIZE;

runtime/vm/JFRConstantPoolTypes.cpp

@@ -1086,6 +1086,37 @@ VM_JFRConstantPoolTypes::addMonitorWaitEntry(J9JFRMonitorWaited* threadWaitData)
 	return;
 }
 
+void
+VM_JFRConstantPoolTypes::addMonitorEnterEntry(J9JFRMonitorEntered *monitorEnterData)
+{
+	MonitorEnterEntry *entry = (MonitorEnterEntry *)pool_newElement(_monitorEnterTable);
+
+	if (NULL == entry) {
+		_buildResult = OutOfMemory;
+		goto done;
+	}
+	entry->ticks = monitorEnterData->startTicks;
+	entry->duration = monitorEnterData->duration;
+	entry->monitorAddress = monitorEnterData->monitorAddress;
+
+	entry->threadIndex = addThreadEntry(monitorEnterData->vmThread);
+	if (isResultNotOKay()) goto done;
+
+	entry->eventThreadIndex = addThreadEntry(monitorEnterData->vmThread);
+	if (isResultNotOKay()) goto done;
+
+	entry->stackTraceIndex = consumeStackTrace(monitorEnterData->vmThread, J9JFRMONITORENTERED_STACKTRACE(monitorEnterData), monitorEnterData->stackTraceSize);
+	if (isResultNotOKay()) goto done;
+
+	entry->monitorClass = getClassEntry(monitorEnterData->monitorClass);
+	if (isResultNotOKay()) goto done;
+
+	_monitorEnterCount += 1;
+
+done:
+	return;
+}
+
 void
 VM_JFRConstantPoolTypes::addThreadParkEntry(J9JFRThreadParked* threadParkData)
 {

runtime/vm/JFRConstantPoolTypes.hpp

@@ -204,6 +204,17 @@ struct MonitorWaitEntry {
 	BOOLEAN timedOut;
 };
 
+struct MonitorEnterEntry {
+	I_64 ticks;
+	I_64 duration;
+	I_64 monitorAddress;
+	U_32 monitorClass;
+	U_32 previousOwnerThread;
+	U_32 threadIndex;
+	U_32 eventThreadIndex;
+	U_32 stackTraceIndex;
+};
+
 struct ThreadParkEntry {
 	I_64 ticks;
 	I_64 duration;
@@ -336,6 +347,8 @@ class VM_JFRConstantPoolTypes {
 	UDATA _threadSleepCount;
 	J9Pool *_monitorWaitTable;
 	UDATA _monitorWaitCount;
+	J9Pool *_monitorEnterTable;
+	UDATA _monitorEnterCount;
 	J9Pool *_threadParkTable;
 	UDATA _threadParkCount;
 	J9Pool *_cpuLoadTable;
@@ -611,6 +624,8 @@ class VM_JFRConstantPoolTypes {
 
 	void addMonitorWaitEntry(J9JFRMonitorWaited* threadWaitData);
 
+	void addMonitorEnterEntry(J9JFRMonitorEntered *monitorEnterData);
+
 	void addThreadParkEntry(J9JFRThreadParked* threadParkData);
 
 	void addCPULoadEntry(J9JFRCPULoad *cpuLoadData);
@@ -648,6 +663,11 @@ class VM_JFRConstantPoolTypes {
 		return _monitorWaitTable;
 	}
 
+	J9Pool *getMonitorEnterTable()
+	{
+		return _monitorEnterTable;
+	}
+
 	J9Pool *getThreadParkTable()
 	{
 		return _threadParkTable;
@@ -703,6 +723,11 @@ class VM_JFRConstantPoolTypes {
 		return _monitorWaitCount;
 	}
 
+	UDATA getMonitorEnterCount()
+	{
+		return _monitorEnterCount;
+	}
+
 	UDATA getThreadParkCount()
 	{
 		return _threadParkCount;
@@ -876,6 +901,9 @@ class VM_JFRConstantPoolTypes {
 			case J9JFR_EVENT_TYPE_OBJECT_WAIT:
 				addMonitorWaitEntry((J9JFRMonitorWaited*) event);
 				break;
+			case J9JFR_EVENT_TYPE_MONITOR_ENTER:
+				addMonitorEnterEntry((J9JFRMonitorEntered *) event);
+				break;
 			case J9JFR_EVENT_TYPE_THREAD_PARK:
 				addThreadParkEntry((J9JFRThreadParked*) event);
 				break;
@@ -1216,6 +1244,8 @@ class VM_JFRConstantPoolTypes {
 		, _threadSleepCount(0)
 		, _monitorWaitTable(NULL)
 		, _monitorWaitCount(0)
+		, _monitorEnterTable(NULL)
+		, _monitorEnterCount(0)
 		, _threadParkTable(NULL)
 		, _threadParkCount(0)
 		, _cpuLoadTable(NULL)
@@ -1330,6 +1360,12 @@ class VM_JFRConstantPoolTypes {
 			goto done;
 		}
 
+		_monitorEnterTable = pool_new(sizeof(MonitorEnterEntry), 0, sizeof(U_64), 0, J9_GET_CALLSITE(), OMRMEM_CATEGORY_VM, POOL_FOR_PORT(privatePortLibrary));
+		if (NULL == _monitorEnterTable) {
+			_buildResult = OutOfMemory;
+			goto done;
+		}
+
 		_threadParkTable = pool_new(sizeof(ThreadParkEntry), 0, sizeof(U_64), 0, J9_GET_CALLSITE(), OMRMEM_CATEGORY_VM, POOL_FOR_PORT(privatePortLibrary));
 		if (NULL == _threadParkTable) {
 			_buildResult = OutOfMemory;
@@ -1452,6 +1488,7 @@ class VM_JFRConstantPoolTypes {
 		pool_kill(_threadEndTable);
 		pool_kill(_threadSleepTable);
 		pool_kill(_monitorWaitTable);
+		pool_kill(_monitorEnterTable);
 		pool_kill(_threadParkTable);
 		pool_kill(_cpuLoadTable);
 		pool_kill(_threadCPULoadTable);

runtime/vm/ObjectMonitor.cpp

@@ -140,6 +140,9 @@ objectMonitorEnterBlocking(J9VMThread *currentThread)
 	UDATA result = 0;
 	j9object_t object = J9VMTHREAD_BLOCKINGENTEROBJECT(currentThread, currentThread);
 	J9Class *ramClass = J9OBJECT_CLAZZ(currentThread, object);
+	J9JavaVM *vm = currentThread->javaVM;
+	PORT_ACCESS_FROM_JAVAVM(vm);
+	I_64 startTicks = j9time_nano_time();
 	/* Throughout this function, note that inlineGetLockAddress cannot run into out of memory case because
 	 * an entry in monitor table will have been created by the earlier call in objectMonitorEnterNonBlocking.
 	 */
@@ -159,7 +162,6 @@ objectMonitorEnterBlocking(J9VMThread *currentThread)
 	}
 #endif /* J9VM_THR_LOCK_RESERVATION */
 	{
-		J9JavaVM *vm = currentThread->javaVM;
 		J9ObjectMonitor *objectMonitor = monitorTableAt(currentThread, object);
 		/* Table entry was created by the nonblocking case, so this peek cannot fail */
 		Assert_VM_notNull(objectMonitor);
@@ -289,8 +291,9 @@ objectMonitorEnterBlocking(J9VMThread *currentThread)
 		((J9ThreadMonitor*)monitor)->flags &= ~(UDATA)J9THREAD_MONITOR_SUPPRESS_CONTENDED_EXIT;
 		VM_AtomicSupport::subtract(&monitor->pinCount, 1);
 		if (J9_EVENT_IS_HOOKED(vm->hookInterface, J9HOOK_VM_MONITOR_CONTENDED_ENTERED)) {
+			J9VMThread *ownerThread = getVMThreadFromOMRThread(vm, ((J9ThreadMonitor *)monitor)->owner);
 			bool frameBuilt = saveBlockingEnterObject(currentThread);
-			ALWAYS_TRIGGER_J9HOOK_VM_MONITOR_CONTENDED_ENTERED(vm->hookInterface, currentThread, monitor);
+			ALWAYS_TRIGGER_J9HOOK_VM_MONITOR_CONTENDED_ENTERED(vm->hookInterface, currentThread, monitor, startTicks, ramClass, ownerThread);
 			restoreBlockingEnterObject(currentThread, frameBuilt);
 		}
 	}

runtime/vm/jfr.cpp

@@ -93,6 +93,9 @@ jfrEventSize(J9JFREvent *jfrEvent)
 	case J9JFR_EVENT_TYPE_OBJECT_WAIT:
 		size = sizeof(J9JFRMonitorWaited) + (((J9JFRMonitorWaited*)jfrEvent)->stackTraceSize * sizeof(UDATA));
 		break;
+	case J9JFR_EVENT_TYPE_MONITOR_ENTER:
+		size = sizeof(J9JFRMonitorEntered) + (((J9JFRMonitorEntered *)jfrEvent)->stackTraceSize * sizeof(UDATA));
+		break;
 	case J9JFR_EVENT_TYPE_THREAD_PARK:
 		size = sizeof(J9JFRThreadParked) + (((J9JFRThreadParked*)jfrEvent)->stackTraceSize * sizeof(UDATA));
 		break;
@@ -650,6 +653,35 @@ jfrVMMonitorWaited(J9HookInterface **hook, UDATA eventNum, void *eventData, void
 	}
 }
 
+/**
+ * Hook for VM monitor entered. 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
+jfrVMMonitorEntered(J9HookInterface **hook, UDATA eventNum, void *eventData, void *userData)
+{
+	J9VMMonitorContendedEnteredEvent *event = (J9VMMonitorContendedEnteredEvent *)eventData;
+	J9VMThread *currentThread = event->currentThread;
+	PORT_ACCESS_FROM_VMC(currentThread);
+
+#if defined(DEBUG)
+	j9tty_printf(PORTLIB, "\n!!! VM monitor entered %p\n", currentThread);
+#endif /* defined(DEBUG) */
+
+	J9JFRMonitorEntered *jfrEvent = (J9JFRMonitorEntered *)reserveBufferWithStackTrace(currentThread, currentThread, J9JFR_EVENT_TYPE_MONITOR_ENTER, sizeof(*jfrEvent));
+	if (NULL != jfrEvent) {
+		initializeEventFields(currentThread, (J9JFREvent *)jfrEvent, J9JFR_EVENT_TYPE_MONITOR_ENTER);
+
+		jfrEvent->duration = j9time_nano_time() - event->startTicks;
+		jfrEvent->monitorClass = event->monitorClass;
+		jfrEvent->monitorAddress = (UDATA)event->monitor;
+	}
+}
+
 /**
  * Hook for VM thread parked. Called without VM access.
  *
@@ -732,7 +764,9 @@ initializeJFR(J9JavaVM *vm, BOOLEAN lateInit)
 	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_MONITOR_WAITED, jfrVMMonitorWaited, OMR_GET_CALLSITE(), NULL)) {
 		goto fail;
 	}
-
+	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_MONITOR_CONTENDED_ENTERED, jfrVMMonitorEntered, OMR_GET_CALLSITE(), NULL)) {
+		goto fail;
+	}
 	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_UNPARKED, jfrVMThreadParked, OMR_GET_CALLSITE(), NULL)) {
 		goto fail;
 	}
@@ -867,6 +901,7 @@ tearDownJFR(J9JavaVM *vm)
 	/* Unregister it anyway even it wasn't registered for initializeJFR(vm, TRUE). */
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_INITIALIZED, jfrVMInitialized, NULL);
 	(*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);
 
 	/* Free global data */