Fix JFR timestamps

Set the ticks/second parameter in the chunk header. This indicates which granularity we report timestamps (millis, micros or nanos). Note, this is not to be confused with the event startime which is always milliseconds. Also, chage threadsleep event to report on after the sleep as concluded which matches RI behaviour. The actual sleep duration must be recorded. Signed-off-by: tajila <atobia@ca.ibm.com>
eclipse-openj9 · Aug 26, 2024 · 53b8bc7 · 53b8bc7
1 parent 110ef95
commit 53b8bc7
Show file tree

Hide file tree

Showing 10 changed files with 89 additions and 38 deletions.
diff --git a/runtime/oti/j9nonbuilder.h b/runtime/oti/j9nonbuilder.h
@@ -393,12 +393,13 @@ typedef struct J9JFRThreadStart {
 #define J9JFRTHREADSTART_STACKTRACE(jfrEvent) ((UDATA*)(((J9JFRThreadStart*)(jfrEvent)) + 1))
 
 /* Variable-size structure - stackTraceSize worth of UDATA follow the fixed portion */
-typedef struct J9JFRThreadSleep {
+typedef struct J9JFRThreadSlept {
 	J9JFR_EVENT_WITH_STACKTRACE_FIELDS
 	I_64 time;
-} J9JFRThreadSleep;
+	I_64 duration;
+} J9JFRThreadSlept;
 
-#define J9JFRTHREADSLEEP_STACKTRACE(jfrEvent) ((UDATA*)(((J9JFRThreadSleep*)(jfrEvent)) + 1))
+#define J9JFRTHREADSLEPT_STACKTRACE(jfrEvent) ((UDATA*)(((J9JFRThreadSlept*)(jfrEvent)) + 1))
 
 #endif /* defined(J9VM_OPT_JFR) */
 

diff --git a/runtime/oti/j9vm.hdf b/runtime/oti/j9vm.hdf
@@ -278,7 +278,7 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		<struct>J9VMAcquireVMAccessEvent</struct>
 		<data type="struct J9VMThread*" name="currentThread" description="current thread" />
 	</event>
-	
+
 	<event>
 		<name>J9HOOK_VM_RELEASEVMACCESS</name>
 		<description>
@@ -287,13 +287,13 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		<struct>J9VMReleaseVMAccessEvent</struct>
 		<data type="struct J9VMThread*" name="currentThread" description="current thread" />
 	</event>
-	
+
 	<event>
 		<name>J9HOOK_VM_ACQUIRING_EXCLUSIVE_IN_NATIVE</name>
 		<description>
 				Triggered during acquire exclusive thread loop, when encountered a thread in native (which we did not count for exclusive).
 				This hook serves similar purpose as J9HOOK_VM_RELEASEVMACCESS, to ensure that required work for thread in native
-				is performed before exclusive access is obtained. 
+				is performed before exclusive access is obtained.
 		</description>
 		<struct>J9VMAcquringExclusiveInNativeEvent</struct>
 		<data type="struct J9VMThread*" name="currentThread" description="calling thread" />
@@ -608,7 +608,7 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		<description>
 			Triggered just before an instance field is read by the bytecode interpreter
 			or JNI.  If the listener allows a GC to occur, the object field in the hook
-			data must be kept up-to-date. 
+			data must be kept up-to-date.
 		</description>
 		<struct>J9VMGetFieldEvent</struct>
 		<data type="struct J9VMThread*" name="currentThread" description="current thread" />
@@ -1216,6 +1216,9 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread,
 		</description>
 		<struct>J9VMSleptEvent</struct>
 		<data type="struct J9VMThread *" name="currentThread" description="current thread" />
+		<data type="I_64" name="millis" description="milliseconds to sleep for" />
+		<data type="IDATA" name="nanos" description="nanoseconds to sleep for" />
+		<data type="IDATA" name="startNanos" description="current time in nanos when sleep began" />
 	</event>
 
 	<event>

diff --git a/runtime/vm/BufferWriter.hpp b/runtime/vm/BufferWriter.hpp
@@ -218,6 +218,33 @@ class VM_BufferWriter {
 		} while (newVal > 0);
 	}
 
+	void
+	writeLEB128PaddedU72(U_8 *cursor, U_64 val)
+	{
+		U_8 *old = _cursor;
+		_cursor = cursor;
+		writeLEB128PaddedU72(val);
+		_cursor = old;
+	}
+
+	void
+	writeLEB128PaddedU72(U_64 val)
+	{
+		U_64 newVal = val;
+		if (!_isLE) {
+			newVal = byteSwap(val);
+		}
+		writeU8((newVal & 0x7F) | 0x80);
+		writeU8(((newVal >> 7) & 0x7F) | 0x80);
+		writeU8(((newVal >> 14) & 0x7F) | 0x80);
+		writeU8(((newVal >> 21) & 0x7F) | 0x80);
+		writeU8(((newVal >> 28) & 0x7F) | 0x80);
+		writeU8(((newVal >> 35) & 0x7F) | 0x80);
+		writeU8(((newVal >> 42) & 0x7F) | 0x80);
+		writeU8(((newVal >> 49) & 0x7F) | 0x80);
+		writeU8(((newVal >> 56) & 0x7F));
+	}
+
 	void
 	writeLEB128PaddedU64(U_8 *cursor, U_64 val)
 	{
@@ -328,7 +355,12 @@ class VM_BufferWriter {
 
 		if (J9_ARE_ALL_BITS_SET(*start, 0x80)) {
 			start++;
-			val |= (U_64)(*start & 0X7F) << 59;
+			val |= (U_64)(*start & 0X7F) << 49;
+		}
+
+		if (J9_ARE_ALL_BITS_SET(*start, 0x80)) {
+			start++;
+			val |= (U_64)(*start & 0X7F) << 56;
 		}
 		if (!_isLE) {
 			val = byteSwap(val);

diff --git a/runtime/vm/JFRChunkWriter.cpp b/runtime/vm/JFRChunkWriter.cpp
@@ -55,8 +55,8 @@ VM_JFRChunkWriter::writeJFRHeader()
 	/* start ticks */
 	_bufferWriter->writeU64(0); // 48
 
-	/* ticks per second */
-	_bufferWriter->writeU64(1); // 56 // TODO ???
+	/* ticks per second - 1000_000_000 ticks per second means that we are reporting nanosecond timestamps */
+	_bufferWriter->writeU64(1000000000); // 56
 
 	/* file state or generation */
 	_bufferWriter->writeU8(0); // 64 // TODO ???

diff --git a/runtime/vm/JFRChunkWriter.hpp b/runtime/vm/JFRChunkWriter.hpp
@@ -408,7 +408,7 @@ class VM_JFRChunkWriter {
 		/* write start time */
 		_bufferWriter->writeLEB128(entry->time);
 
-		/* write duration time */
+		/* write duration time which is always in ticks, in our case nanos */
 		_bufferWriter->writeLEB128(entry->duration);
 
 		/* write event thread index */
@@ -417,11 +417,8 @@ class VM_JFRChunkWriter {
 		/* stacktrace index */
 		_bufferWriter->writeLEB128(entry->stackTraceIndex);
 
-		/* write thread index */
-		_bufferWriter->writeLEB128(entry->threadIndex);
-
-		/* write time */
-		_bufferWriter->writeLEB128(entry->duration);
+		/* write sleep time which is always in millis */
+		_bufferWriter->writeLEB128(entry->sleepTime/1000000);
 
 		/* write size */
 		_bufferWriter->writeLEB128PaddedU32(dataStart, _bufferWriter->getCursor() - dataStart);

diff --git a/runtime/vm/JFRConstantPoolTypes.cpp b/runtime/vm/JFRConstantPoolTypes.cpp
@@ -1002,7 +1002,7 @@ VM_JFRConstantPoolTypes::addThreadEndEntry(J9JFREvent *threadEndData)
 }
 
 U_32
-VM_JFRConstantPoolTypes::addThreadSleepEntry(J9JFRThreadSleep *threadSleepData)
+VM_JFRConstantPoolTypes::addThreadSleepEntry(J9JFRThreadSlept *threadSleepData)
 {
 	ThreadSleepEntry *entry = (ThreadSleepEntry*)pool_newElement(_threadSleepTable);
 	U_32 index = U_32_MAX;
@@ -1013,7 +1013,8 @@ VM_JFRConstantPoolTypes::addThreadSleepEntry(J9JFRThreadSleep *threadSleepData)
 	}
 
 	entry->time = threadSleepData->startTime;
-	entry->duration = threadSleepData->time;
+	entry->duration = threadSleepData->duration;
+	entry->sleepTime = threadSleepData->time;
 
 	entry->threadIndex = addThreadEntry(threadSleepData->vmThread);
 	if (isResultNotOKay()) goto done;

diff --git a/runtime/vm/JFRConstantPoolTypes.hpp b/runtime/vm/JFRConstantPoolTypes.hpp
@@ -180,6 +180,7 @@ struct ThreadEndEntry {
 struct ThreadSleepEntry {
 	I_64 time;
 	I_64 duration;
+	I_64 sleepTime;
 	U_32 threadIndex;
 	U_32 eventThreadIndex;
 	U_32 stackTraceIndex;
@@ -459,7 +460,7 @@ class VM_JFRConstantPoolTypes {
 
 	U_32 addThreadEndEntry(J9JFREvent *threadEndData);
 
-	U_32 addThreadSleepEntry(J9JFRThreadSleep *threadSleepData);
+	U_32 addThreadSleepEntry(J9JFRThreadSlept *threadSleepData);
 
 	J9Pool *getExecutionSampleTable()
 	{
@@ -627,7 +628,7 @@ class VM_JFRConstantPoolTypes {
 				addThreadEndEntry((J9JFREvent*) event);
 				break;
 			case J9JFR_EVENT_TYPE_THREAD_SLEEP:
-				addThreadSleepEntry((J9JFRThreadSleep*) event);
+				addThreadSleepEntry((J9JFRThreadSlept*) event);
 				break;
 			default:
 				Assert_VM_unreachable();

diff --git a/runtime/vm/JFRUtils.hpp b/runtime/vm/JFRUtils.hpp
@@ -57,7 +57,8 @@ class VM_JFRUtils {
 
 public:
 
-	static U_64 getCurrentTimeNanos(J9PortLibrary *privatePortLibrary, BuildResult &buildResult) {
+	static U_64 getCurrentTimeNanos(J9PortLibrary *privatePortLibrary, BuildResult &buildResult)
+	{
 		UDATA success = 0;
 		U_64 result = (U_64) j9time_current_time_nanos(&success);
 

diff --git a/runtime/vm/jfr.cpp b/runtime/vm/jfr.cpp
@@ -75,7 +75,7 @@ jfrEventSize(J9JFREvent *jfrEvent)
 		size = sizeof(J9JFREvent);
 		break;
 	case J9JFR_EVENT_TYPE_THREAD_SLEEP:
-		size = sizeof(J9JFRThreadSleep) + (((J9JFRThreadSleep*)jfrEvent)->stackTraceSize * sizeof(UDATA));
+		size = sizeof(J9JFRThreadSlept) + (((J9JFRThreadSlept*)jfrEvent)->stackTraceSize * sizeof(UDATA));
 		break;
 	default:
 		Assert_VM_unreachable();
@@ -482,20 +482,26 @@ jfrThreadEnd(J9HookInterface **hook, UDATA eventNum, void *eventData, void *user
  * @param userData[in] the registered user data
  */
 static void
-jfrVMSleep(J9HookInterface **hook, UDATA eventNum, void *eventData, void *userData)
+jfrVMSlept(J9HookInterface **hook, UDATA eventNum, void *eventData, void *userData)
 {
-	J9VMSleepEvent *event = (J9VMSleepEvent *)eventData;
+	J9VMSleptEvent *event = (J9VMSleptEvent *)eventData;
 	J9VMThread *currentThread = event->currentThread;
+	PORT_ACCESS_FROM_VMC(currentThread);
 
 #if defined(DEBUG)
-	PORT_ACCESS_FROM_VMC(currentThread);
 	j9tty_printf(PORTLIB, "\n!!! thread sleep %p\n", currentThread);
 #endif /* defined(DEBUG) */
 
-	J9JFRThreadSleep *jfrEvent = (J9JFRThreadSleep*)reserveBufferWithStackTrace(currentThread, currentThread, J9JFR_EVENT_TYPE_THREAD_SLEEP, sizeof(*jfrEvent));
+	J9JFRThreadSlept *jfrEvent = (J9JFRThreadSlept*)reserveBufferWithStackTrace(currentThread, currentThread, J9JFR_EVENT_TYPE_THREAD_SLEEP, sizeof(*jfrEvent));
 	if (NULL != jfrEvent) {
 		// TODO: worry about overflow?
-		jfrEvent->time = (event->millis * 1000) + event->nanos;
+		jfrEvent->time = (event->millis * 1000000) + event->nanos;
+		jfrEvent->duration = 0;
+		UDATA result = 0;
+		I_64 currentNanos = j9time_current_time_nanos(&result);
+		if (0 != result) {
+			jfrEvent->duration = currentNanos - event->startNanos;
+		}
 	}
 }
 
@@ -560,7 +566,7 @@ initializeJFR(J9JavaVM *vm)
 	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_THREAD_END, jfrThreadEnd, OMR_GET_CALLSITE(), NULL)) {
 		goto fail;
 	}
-	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_SLEEP, jfrVMSleep, OMR_GET_CALLSITE(), NULL)) {
+	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_SLEPT, jfrVMSlept, OMR_GET_CALLSITE(), NULL)) {
 		goto fail;
 	}
 	if ((*vmHooks)->J9HookRegisterWithCallSite(vmHooks, J9HOOK_VM_INITIALIZED, jfrVMInitialized, OMR_GET_CALLSITE(), NULL)) {
@@ -631,7 +637,7 @@ tearDownJFR(J9JavaVM *vm)
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_SHUTTING_DOWN, jfrVMShutdown, NULL);
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_THREAD_STARTING, jfrThreadStarting, NULL);
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_THREAD_END, jfrThreadEnd, NULL);
-	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_SLEEP, jfrVMSleep, NULL);
+	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_SLEPT, jfrVMSlept, NULL);
 	(*vmHooks)->J9HookUnregister(vmHooks, J9HOOK_VM_INITIALIZED, jfrVMInitialized, NULL);
 
 	/* Free global data */

diff --git a/runtime/vm/threadhelp.cpp b/runtime/vm/threadhelp.cpp
@@ -49,12 +49,12 @@ validateTimeouts(J9VMThread *vmThread, I_64 millis, I_32 nanos)
 
 	if (millis < 0) {
 		setCurrentExceptionNLS(
-			vmThread, 
+			vmThread,
 			J9VMCONSTANTPOOL_JAVALANGILLEGALARGUMENTEXCEPTION,
 			J9NLS_JCL_TIMEOUT_VALUE_IS_NEGATIVE);
 	} else if (nanos < 0 || nanos >= 1000000) {
 		setCurrentExceptionNLS(
-			vmThread, 
+			vmThread,
 			J9VMCONSTANTPOOL_JAVALANGILLEGALARGUMENTEXCEPTION,
 			J9NLS_JCL_NANOSECOND_TIMEOUT_VALUE_OUT_OF_RANGE);
 	} else {
@@ -162,15 +162,24 @@ threadSleepImpl(J9VMThread *vmThread, I_64 millis, I_32 nanos)
 		/* An IllegalArgumentException has been set. */
 		rc = -1;
 	} else {
+		PORT_ACCESS_FROM_JAVAVM(javaVM);
+		UDATA result = 0;
+		I_64 startNanos = (U_64) j9time_current_time_nanos(&result);
+		if (0 == result){
+			setCurrentException(vmThread, J9VMCONSTANTPOOL_JAVALANGINTERNALERROR, NULL);
+			rc = -1;
+		}
 #ifdef J9VM_OPT_SIDECAR
 		/* Increment the wait count even if the deadline is past. */
 		vmThread->mgmtWaitedCount++;
 #endif
-		TRIGGER_J9HOOK_VM_SLEEP(javaVM->hookInterface, vmThread, millis, nanos);
-		internalReleaseVMAccessSetStatus(vmThread, J9_PUBLIC_FLAGS_THREAD_SLEEPING);
-		rc = timeCompensationHelper(vmThread, HELPER_TYPE_THREAD_SLEEP, NULL, millis, nanos);
-		internalAcquireVMAccessClearStatus(vmThread, J9_PUBLIC_FLAGS_THREAD_SLEEPING);
-		TRIGGER_J9HOOK_VM_SLEPT(javaVM->hookInterface, vmThread);
+		if (0 == rc) {
+			TRIGGER_J9HOOK_VM_SLEEP(javaVM->hookInterface, vmThread, millis, nanos);
+			internalReleaseVMAccessSetStatus(vmThread, J9_PUBLIC_FLAGS_THREAD_SLEEPING);
+			rc = timeCompensationHelper(vmThread, HELPER_TYPE_THREAD_SLEEP, NULL, millis, nanos);
+			internalAcquireVMAccessClearStatus(vmThread, J9_PUBLIC_FLAGS_THREAD_SLEEPING);
+			TRIGGER_J9HOOK_VM_SLEPT(javaVM->hookInterface, vmThread, millis, nanos, startNanos);
+		}
 
 		if (0 == rc) {
 			/* Trc_JCL_sleep_Exit(vmThread); */
@@ -225,15 +234,15 @@ getMonitorForWait(J9VMThread* vmThread, j9object_t object)
 			return NULL;
 		}
 		lockEA = &objectMonitor->alternateLockword;
-	} 
+	}
 	else {
 		lockEA = J9OBJECT_MONITOR_EA(vmThread, object);
 	}
 	lock = J9_LOAD_LOCKWORD(vmThread, lockEA);
 
 	if (J9_LOCK_IS_INFLATED(lock)) {
 		objectMonitor = J9_INFLLOCK_OBJECT_MONITOR(lock);
-		
+
 		monitor = objectMonitor->monitor;
 //		Trc_JCL_foundMonitorInLockword(vmThread, monitor, object);