Merge pull request eclipse-openj9#20312 from tajila/jfr4

Update jfr time calculations
thallium · Oct 8, 2024 · 69d16bb · 69d16bb
2 parents 595107b + d334354
commit 69d16bb
Show file tree

Hide file tree

Showing 6 changed files with 47 additions and 32 deletions.
diff --git a/runtime/oti/j9nonbuilder.h b/runtime/oti/j9nonbuilder.h
@@ -360,7 +360,7 @@ typedef struct J9JFRBuffer {
 /* JFR event structures */
 
 #define J9JFR_EVENT_COMMON_FIELDS \
-	I_64 startTime; \
+	I_64 startTicks; \
 	UDATA eventType; \
 	struct J9VMThread *vmThread;
 
@@ -5635,6 +5635,8 @@ typedef struct JFRState {
 	IDATA blobFileDescriptor;
 	void *jfrWriter;
 	UDATA jfrChunkCount;
+	I_64 chunkStartTime;
+	I_64 chunkStartTicks;
 	void *constantEvents;
 	BOOLEAN isConstantEventsInitialized;
 	omrthread_monitor_t isConstantEventsInitializedMutex;

diff --git a/runtime/vm/JFRChunkWriter.cpp b/runtime/vm/JFRChunkWriter.cpp
@@ -49,13 +49,13 @@ VM_JFRChunkWriter::writeJFRHeader()
 	_bufferWriter->writeU64(_bufferWriter->getFileOffsetFromStart(_metadataOffset)); // 24
 
 	/* start time */
-	_bufferWriter->writeU64(VM_JFRUtils::getCurrentTimeNanos(privatePortLibrary, _buildResult)); // 32
+	_bufferWriter->writeU64(_vm->jfrState.chunkStartTime); // 32
 
 	/* duration */
 	_bufferWriter->writeU64(0); // 40
 
 	/* start ticks */
-	_bufferWriter->writeU64(0); // 48
+	_bufferWriter->writeU64(_vm->jfrState.chunkStartTicks); // 48
 
 	/* ticks per second - 1000_000_000 ticks per second means that we are reporting nanosecond timestamps */
 	_bufferWriter->writeU64(1000000000); // 56
@@ -138,7 +138,7 @@ VM_JFRChunkWriter::writeCheckpointEventHeader(CheckpointTypeMask typeMask, U_32
 	_bufferWriter->writeU8(EventCheckpoint);
 
 	/* start time */
-	_bufferWriter->writeLEB128(VM_JFRUtils::getCurrentTimeNanos(privatePortLibrary, _buildResult));
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	/* duration */
 	_bufferWriter->writeLEB128((U_64)0);
@@ -649,7 +649,7 @@ VM_JFRChunkWriter::writeJVMInformationEvent()
 	_bufferWriter->writeLEB128(JVMInformationID);
 
 	/* write start time */
-	_bufferWriter->writeLEB128(j9time_current_time_millis());
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	/* write JVM name */
 	writeStringLiteral(jvmInfo->jvmName);
@@ -687,7 +687,7 @@ VM_JFRChunkWriter::writePhysicalMemoryEvent()
 	_bufferWriter->writeLEB128(PhysicalMemoryID);
 
 	/* write start time */
-	_bufferWriter->writeLEB128(j9time_current_time_millis());
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	J9MemoryInfo memInfo = {0};
 	I_32 rc = j9sysinfo_get_memory_info(&memInfo);
@@ -717,7 +717,7 @@ VM_JFRChunkWriter::writeCPUInformationEvent()
 	_bufferWriter->writeLEB128(CPUInformationID);
 
 	/* write start time */
-	_bufferWriter->writeLEB128(j9time_current_time_millis());
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	/* write CPU type */
 	writeStringLiteral(cpuInfo->cpu);
@@ -752,7 +752,7 @@ VM_JFRChunkWriter::writeVirtualizationInformationEvent()
 	_bufferWriter->writeLEB128(VirtualizationInformationID);
 
 	/* write start time */
-	_bufferWriter->writeLEB128(j9time_current_time_millis());
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	/* write virtualization name */
 	writeStringLiteral(virtualizationInfo->name);
@@ -775,7 +775,7 @@ VM_JFRChunkWriter::writeOSInformationEvent()
 	_bufferWriter->writeLEB128(OSInformationID);
 
 	/* write start time */
-	_bufferWriter->writeLEB128(j9time_current_time_millis());
+	_bufferWriter->writeLEB128(j9time_nano_time());
 
 	/* write OS version */
 	writeStringLiteral(osInfo->osVersion);
@@ -800,7 +800,7 @@ VM_JFRChunkWriter::writeInitialSystemPropertyEvents(J9JavaVM *vm)
 		_bufferWriter->writeLEB128(InitialSystemPropertyID);
 
 		/* write start time */
-		_bufferWriter->writeLEB128(j9time_current_time_millis());
+		_bufferWriter->writeLEB128(j9time_nano_time());
 
 		/* write key */
 		writeStringLiteral(property->name);

diff --git a/runtime/vm/JFRChunkWriter.hpp b/runtime/vm/JFRChunkWriter.hpp
@@ -348,6 +348,8 @@ class VM_JFRChunkWriter {
 			writeJFRChunkToFile();
 
 			_vm->jfrState.jfrChunkCount += 1;
+			_vm->jfrState.chunkStartTime = VM_JFRUtils::getCurrentTimeNanos(privatePortLibrary, _buildResult);
+			_vm->jfrState.chunkStartTicks = j9time_nano_time();
 
 freeBuffer:
 			_bufferWriter = NULL;
@@ -371,7 +373,7 @@ class VM_JFRChunkWriter {
 		_bufferWriter->writeLEB128(ExecutionSampleID);
 
 		/* write start time */
-		_bufferWriter->writeLEB128(entry->time);
+		_bufferWriter->writeLEB128(entry->ticks);
 
 		/* write sampling thread index */
 		_bufferWriter->writeLEB128(entry->threadIndex);
@@ -399,7 +401,7 @@ class VM_JFRChunkWriter {
 		_bufferWriter->writeLEB128(ThreadStartID);
 
 		/* write start time */
-		_bufferWriter->writeLEB128(entry->time);
+		_bufferWriter->writeLEB128(entry->ticks);
 
 		/* write event thread index */
 		_bufferWriter->writeLEB128(entry->eventThreadIndex);
@@ -430,7 +432,7 @@ class VM_JFRChunkWriter {
 		_bufferWriter->writeLEB128(ThreadEndID);
 
 		/* write start time */
-		_bufferWriter->writeLEB128(entry->time);
+		_bufferWriter->writeLEB128(entry->ticks);
 
 		/* write event thread index */
 		_bufferWriter->writeLEB128(entry->eventThreadIndex);
@@ -454,8 +456,10 @@ class VM_JFRChunkWriter {
 		/* write event type */
 		_bufferWriter->writeLEB128(ThreadSleepID);
 
-		/* write start time */
-		_bufferWriter->writeLEB128(entry->time);
+		/* 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);

diff --git a/runtime/vm/JFRConstantPoolTypes.cpp b/runtime/vm/JFRConstantPoolTypes.cpp
@@ -118,7 +118,7 @@ VM_JFRConstantPoolTypes::stackTraceHashFn(void *key, void *userData)
 {
 	StackTraceEntry *entry = (StackTraceEntry*) key;
 
-	return (U_64)(UDATA)entry->vmThread ^ (U_64)entry->time;
+	return (U_64)(UDATA)entry->vmThread ^ (U_64)entry->ticks;
 }
 
 UDATA
@@ -127,7 +127,7 @@ VM_JFRConstantPoolTypes::stackTraceHashEqualFn(void *tableNode, void *queryNode,
 	StackTraceEntry *tableEntry = (StackTraceEntry *) tableNode;
 	StackTraceEntry *queryEntry = (StackTraceEntry *) queryNode;
 
-	return tableEntry->vmThread == queryEntry->vmThread && tableEntry->time == queryEntry->time;
+	return tableEntry->vmThread == queryEntry->vmThread && tableEntry->ticks == queryEntry->ticks;
 }
 
 UDATA
@@ -303,7 +303,7 @@ VM_JFRConstantPoolTypes::walkStackTraceTablePrint(void *entry, void *userData)
 	J9VMThread *currentThread = (J9VMThread *)userData;
 	PORT_ACCESS_FROM_VMC(currentThread);
 
-	j9tty_printf(PORTLIB, "%u) time=%li numOfFrames=%u frames=%p curr=%p next=%p \n", tableEntry->index, tableEntry->time, tableEntry->numOfFrames, tableEntry->frames, tableEntry, tableEntry->next);
+	j9tty_printf(PORTLIB, "%u) time=%li numOfFrames=%u frames=%p curr=%p next=%p \n", tableEntry->index, tableEntry->ticks, tableEntry->numOfFrames, tableEntry->frames, tableEntry, tableEntry->next);
 
 	return FALSE;
 }
@@ -866,15 +866,15 @@ VM_JFRConstantPoolTypes::addThreadGroupEntry(j9object_t threadGroup)
 }
 
 U_32
-VM_JFRConstantPoolTypes::addStackTraceEntry(J9VMThread *vmThread, I_64 time, U_32 numOfFrames)
+VM_JFRConstantPoolTypes::addStackTraceEntry(J9VMThread *vmThread, I_64 ticks, U_32 numOfFrames)
 {
 	U_32 index = U_32_MAX;
 	StackTraceEntry *entry = NULL;
 	StackTraceEntry entryBuffer = {0};
 
 	entry = &entryBuffer;
 	entry->vmThread = vmThread;
-	entry->time = time;
+	entry->ticks = ticks;
 	_buildResult = OK;
 
 	entry = (StackTraceEntry *) hashTableFind(_stackTraceTable, entry);
@@ -929,7 +929,7 @@ VM_JFRConstantPoolTypes::addExecutionSampleEntry(J9JFRExecutionSample *execution
 	}
 
 	entry->vmThread = executionSampleData->vmThread;
-	entry->time = executionSampleData->startTime;
+	entry->ticks = executionSampleData->startTicks;
 	entry->state = RUNNABLE; //TODO
 
 	entry->threadIndex = addThreadEntry(entry->vmThread);
@@ -956,7 +956,7 @@ VM_JFRConstantPoolTypes::addThreadStartEntry(J9JFRThreadStart *threadStartData)
 		goto done;
 	}
 
-	entry->time = threadStartData->startTime;
+	entry->ticks = threadStartData->startTicks;
 
 	entry->threadIndex = addThreadEntry(threadStartData->thread);
 	if (isResultNotOKay()) goto done;
@@ -987,7 +987,7 @@ VM_JFRConstantPoolTypes::addThreadEndEntry(J9JFREvent *threadEndData)
 		goto done;
 	}
 
-	entry->time = threadEndData->startTime;
+	entry->ticks = threadEndData->startTicks;
 
 	entry->threadIndex = addThreadEntry(threadEndData->vmThread);
 	if (isResultNotOKay()) goto done;
@@ -1012,7 +1012,7 @@ VM_JFRConstantPoolTypes::addThreadSleepEntry(J9JFRThreadSlept *threadSleepData)
 		goto done;
 	}
 
-	entry->time = threadSleepData->startTime;
+	entry->ticks = threadSleepData->startTicks;
 	entry->duration = threadSleepData->duration;
 	entry->sleepTime = threadSleepData->time;
 

diff --git a/runtime/vm/JFRConstantPoolTypes.hpp b/runtime/vm/JFRConstantPoolTypes.hpp
@@ -159,29 +159,29 @@ struct StackFrame {
 
 struct ExecutionSampleEntry {
 	J9VMThread *vmThread;
-	I_64 time;
+	I_64 ticks;
 	ThreadState state;
 	U_32 stackTraceIndex;
 	U_32 threadIndex;
 	U_32 index;
 };
 
 struct ThreadStartEntry {
-	I_64 time;
+	I_64 ticks;
 	U_32 stackTraceIndex;
 	U_32 threadIndex;
 	U_32 eventThreadIndex;
 	U_32 parentThreadIndex;
 };
 
 struct ThreadEndEntry {
-	I_64 time;
+	I_64 ticks;
 	U_32 threadIndex;
 	U_32 eventThreadIndex;
 };
 
 struct ThreadSleepEntry {
-	I_64 time;
+	I_64 ticks;
 	I_64 duration;
 	I_64 sleepTime;
 	U_32 threadIndex;
@@ -191,7 +191,7 @@ struct ThreadSleepEntry {
 
 struct StackTraceEntry {
 	J9VMThread *vmThread;
-	I_64 time;
+	I_64 ticks;
 	U_32 numOfFrames;
 	U_32 index;
 	StackFrame *frames;
@@ -417,7 +417,7 @@ class VM_JFRConstantPoolTypes {
 
 	U_32 addThreadGroupEntry(j9object_t threadGroup);
 
-	U_32 addStackTraceEntry(J9VMThread *vmThread, I_64 time, U_32 numOfFrames);
+	U_32 addStackTraceEntry(J9VMThread *vmThread, I_64 ticks, U_32 numOfFrames);
 
 	void printMergedStringTables();
 
@@ -726,7 +726,7 @@ class VM_JFRConstantPoolTypes {
 
 		iterateStackTraceImpl(_currentThread, (j9object_t*)walkStateCache, &stackTraceCallback, this, FALSE, FALSE, numberOfFrames, FALSE);
 
-		index = addStackTraceEntry(walkThread, VM_JFRUtils::getCurrentTimeNanos(privatePortLibrary, _buildResult), _currentFrameCount);
+		index = addStackTraceEntry(walkThread, j9time_nano_time(), _currentFrameCount);
 		_stackFrameCount += expandedStackTraceCount;
 		_currentStackFrameBuffer = NULL;
 

diff --git a/runtime/vm/jfr.cpp b/runtime/vm/jfr.cpp
@@ -551,6 +551,7 @@ initializeJFR(J9JavaVM *vm)
 	jint rc = JNI_ERR;
 	J9HookInterface **vmHooks = getVMHookInterface(vm);
 	U_8 *buffer = NULL;
+	UDATA timeSuccess = 0;
 
 	/* Register async handler for execution samples */
 	vm->jfrAsyncKey = J9RegisterAsyncEvent(vm, jfrExecutionSampleCallback, NULL);
@@ -600,6 +601,14 @@ initializeJFR(J9JavaVM *vm)
 	vm->jfrBuffer.bufferRemaining = J9JFR_GLOBAL_BUFFER_SIZE;
 	vm->jfrState.jfrChunkCount = 0;
 	vm->jfrState.isConstantEventsInitialized = FALSE;
+
+	vm->jfrState.chunkStartTime = (I_64) j9time_current_time_nanos(&timeSuccess);
+	vm->jfrState.chunkStartTicks = j9time_nano_time();
+
+	if (0 == timeSuccess) {
+		goto fail;
+	}
+
 	if (omrthread_monitor_init_with_name(&vm->jfrBufferMutex, 0, "JFR global buffer mutex")) {
 		goto fail;
 	}
@@ -694,7 +703,7 @@ static void
 initializeEventFields(J9VMThread *currentThread, J9JFREvent *event, UDATA eventType)
 {
 	PORT_ACCESS_FROM_VMC(currentThread);
-	event->startTime = j9time_current_time_millis();
+	event->startTicks = j9time_nano_time();
 	event->eventType = eventType;
 	event->vmThread = currentThread;
 }