From 02738487a2f8395a28ed49e5064a5480dfc76c2f Mon Sep 17 00:00:00 2001 From: tajila Date: Thu, 22 Aug 2024 12:15:09 -0400 Subject: [PATCH] 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 --- runtime/oti/j9nonbuilder.h | 7 +++--- runtime/oti/j9vm.hdf | 11 ++++++---- runtime/vm/BufferWriter.hpp | 34 ++++++++++++++++++++++++++++- runtime/vm/JFRChunkWriter.cpp | 4 ++-- runtime/vm/JFRChunkWriter.hpp | 9 +++----- runtime/vm/JFRConstantPoolTypes.cpp | 5 +++-- runtime/vm/JFRConstantPoolTypes.hpp | 5 +++-- runtime/vm/JFRUtils.hpp | 3 ++- runtime/vm/jfr.cpp | 22 ++++++++++++------- runtime/vm/threadhelp.cpp | 27 ++++++++++++++--------- 10 files changed, 88 insertions(+), 39 deletions(-) diff --git a/runtime/oti/j9nonbuilder.h b/runtime/oti/j9nonbuilder.h index 8ae6c498441..d21ce28bced 100644 --- 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 index fd67b034ee6..4af5de549b9 100644 --- a/runtime/oti/j9vm.hdf +++ b/runtime/oti/j9vm.hdf @@ -278,7 +278,7 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread, J9VMAcquireVMAccessEvent - + J9HOOK_VM_RELEASEVMACCESS @@ -287,13 +287,13 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread, J9VMReleaseVMAccessEvent - + J9HOOK_VM_ACQUIRING_EXCLUSIVE_IN_NATIVE 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. J9VMAcquringExclusiveInNativeEvent @@ -608,7 +608,7 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread, 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. J9VMGetFieldEvent @@ -1216,6 +1216,9 @@ typedef UDATA (* lookupNativeAddressCallback)(struct J9VMThread *currentThread, J9VMSleptEvent + + + diff --git a/runtime/vm/BufferWriter.hpp b/runtime/vm/BufferWriter.hpp index fc149d4f475..990774985c5 100644 --- 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 index 083fd7853db..8b4f7f68675 100644 --- 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 index 5d8b7339ea0..7e4f3eeae41 100644 --- 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 index 84e41d4b3e9..380244efa2e 100644 --- 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 index 50e757b8ada..4e1a8999126 100644 --- 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 index 3b852aa2056..4baafa96d95 100644 --- 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 index 12a44961de9..b087e263a06 100644 --- 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 index 3b28f2ba306..a47a8ee3623 100644 --- 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,17 +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); + /* Trc_JCL_sleep_Exit(vmThread); */ /* omrthread_sleep_interruptable returned on success */ } else if (J9THREAD_INTERRUPTED == rc) { @@ -225,7 +232,7 @@ getMonitorForWait(J9VMThread* vmThread, j9object_t object) return NULL; } lockEA = &objectMonitor->alternateLockword; - } + } else { lockEA = J9OBJECT_MONITOR_EA(vmThread, object); } @@ -233,7 +240,7 @@ getMonitorForWait(J9VMThread* vmThread, j9object_t object) if (J9_LOCK_IS_INFLATED(lock)) { objectMonitor = J9_INFLLOCK_OBJECT_MONITOR(lock); - + monitor = objectMonitor->monitor; // Trc_JCL_foundMonitorInLockword(vmThread, monitor, object);