Merge pull request #20049 from tajila/jfr

Fix JFR timestamps

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) */
 

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>

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);

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 ???

runtime/vm/JFRChunkWriter.hpp

@@ -412,7 +412,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 */
@@ -421,11 +421,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);

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;

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;
@@ -489,7 +490,7 @@ class VM_JFRConstantPoolTypes {
 
 	U_32 addThreadEndEntry(J9JFREvent *threadEndData);
 
-	U_32 addThreadSleepEntry(J9JFRThreadSleep *threadSleepData);
+	U_32 addThreadSleepEntry(J9JFRThreadSlept *threadSleepData);
 
 	J9Pool *getExecutionSampleTable()
 	{
@@ -657,7 +658,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();

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);
 

runtime/vm/jfr.cpp

@@ -79,7 +79,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();
@@ -497,20 +497,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;
+		}
 	}
 }
 
@@ -581,7 +587,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)) {
@@ -656,7 +662,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 */

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);