From c681c629f6fb9b6b2fc0d0d8bbf67e519ffc9c3c Mon Sep 17 00:00:00 2001 From: Dev Agarwal Date: Wed, 24 Jun 2026 09:22:17 -0400 Subject: [PATCH 1/2] Add information regarding synchronous compilations in javacore Added a struct in J9JITConfig to store information regarding synchronous compilations and print them in javacore file. Signed-off-by: Dev Agarwal --- .../compiler/control/CompilationRuntime.hpp | 3 + .../compiler/control/CompilationThread.cpp | 50 ++++++++++++++++ runtime/oti/j9nonbuilder.h | 11 ++++ runtime/rasdump/javadump.cpp | 58 +++++++++++++++++++ 4 files changed, 122 insertions(+) diff --git a/runtime/compiler/control/CompilationRuntime.hpp b/runtime/compiler/control/CompilationRuntime.hpp index 8205563ebec..d507a1768b7 100644 --- a/runtime/compiler/control/CompilationRuntime.hpp +++ b/runtime/compiler/control/CompilationRuntime.hpp @@ -512,6 +512,8 @@ class CompilationInfo { } }; // CompilationStatsPerInterval + typedef J9JITSyncCompilationStatistics SyncCompilationStatistics; + static bool createCompilationInfo(J9JITConfig *jitConfig); static void freeCompilationInfo(J9JITConfig *jitConfig); @@ -1508,6 +1510,7 @@ class CompilationInfo { struct CompilationStatistics _stats; struct CompilationStatsPerInterval _intervalStats; + SyncCompilationStatistics _syncCompStats; TR_PersistentArray *_persistedMethods; // Must be less than 16 at the JITClient or non-JITServer mode because diff --git a/runtime/compiler/control/CompilationThread.cpp b/runtime/compiler/control/CompilationThread.cpp index af7c1e7c297..3009f0f8756 100644 --- a/runtime/compiler/control/CompilationThread.cpp +++ b/runtime/compiler/control/CompilationThread.cpp @@ -807,6 +807,7 @@ bool TR::CompilationInfo::createCompilationInfo(J9JITConfig *jitConfig) memset(alloc, 0, sizeof(TR::CompilationInfo)); _compilationRuntime = new (alloc) TR::CompilationInfo(jitConfig); jitConfig->compilationRuntime = (void *)_compilationRuntime; + jitConfig->syncCompStats = &_compilationRuntime->_syncCompStats; #ifdef DEBUG if (debug("traceThreadCompile")) _compilationRuntime->_traceCompiling = true; @@ -857,6 +858,12 @@ void TR::CompilationInfo::freeAllResources() } freeAllCompilationThreads(); + + if (_syncCompStats.longestWaitMethod != NULL) { + PORT_ACCESS_FROM_JITCONFIG(_jitConfig); + j9mem_free_memory(_syncCompStats.longestWaitMethod); + _syncCompStats.longestWaitMethod = NULL; + } } void TR::CompilationInfo::freeCompilationInfo(J9JITConfig *jitConfig) @@ -6162,6 +6169,14 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG // entry->_numThreadsWaiting++; + uint64_t waitStart = 0; + uint64_t waitStartElapsedTime = 0; + PORT_ACCESS_FROM_JITCONFIG(_jitConfig); + if (!async) { + waitStart = j9time_hires_clock(); + waitStartElapsedTime = getPersistentInfo()->getElapsedTime(); + } + // Release the compilation monitor // debugPrint(vmThread, "\tapplication thread releasing compilation monitor\n"); @@ -6259,6 +6274,41 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG entry->_numThreadsWaiting--; + if (!async) { + uint64_t waitEnd = j9time_hires_clock(); + uint64_t duration = j9time_hires_delta(waitStart, waitEnd, J9PORT_TIME_DELTA_IN_MICROSECONDS); + + _syncCompStats.totalCount++; + _syncCompStats.totalWaitTime += duration; + + if (duration > _syncCompStats.longestWaitTime) { + _syncCompStats.longestWaitTime = duration; + _syncCompStats.longestWaitTimeStart = waitStartElapsedTime * 1000; + _syncCompStats.longestWaitTimeEnd = (waitStartElapsedTime * 1000) + duration; + + J9UTF8 *className; + J9UTF8 *name; + J9UTF8 *signature; + getClassNameSignatureFromMethod(method, className, name, signature); + + if (_syncCompStats.longestWaitMethod != NULL) { + j9mem_free_memory(_syncCompStats.longestWaitMethod); + _syncCompStats.longestWaitMethod = NULL; + } + + uint32_t totalLen = J9UTF8_LENGTH(className) + J9UTF8_LENGTH(name) + J9UTF8_LENGTH(signature) + 2; + char *templongestWaitMethod = (char *)j9mem_allocate_memory(totalLen, J9MEM_CATEGORY_JIT); + + if (templongestWaitMethod != NULL) { + snprintf(templongestWaitMethod, totalLen, "%.*s.%.*s%.*s", J9UTF8_LENGTH(className), + J9UTF8_DATA(className), J9UTF8_LENGTH(name), J9UTF8_DATA(name), J9UTF8_LENGTH(signature), + J9UTF8_DATA(signature)); + } + + _syncCompStats.longestWaitMethod = templongestWaitMethod; + } + } + TR_ASSERT_FATAL(!(entry->_freeTag & (ENTRY_DEALLOCATED | ENTRY_IN_POOL_FREE)), "Java thread waking up with a freed entry"); diff --git a/runtime/oti/j9nonbuilder.h b/runtime/oti/j9nonbuilder.h index 2cbe8a70de9..d1afa7fbba7 100644 --- a/runtime/oti/j9nonbuilder.h +++ b/runtime/oti/j9nonbuilder.h @@ -4334,6 +4334,16 @@ typedef struct J9ClassCastParms { struct J9Class* castClass; } J9ClassCastParms; +typedef struct J9JITSyncCompilationStatistics { + /* All times are in microseconds (us) */ + uint32_t totalCount; + uint64_t totalWaitTime; + uint64_t longestWaitTime; + uint64_t longestWaitTimeStart; + uint64_t longestWaitTimeEnd; + char* longestWaitMethod; +} J9JITSyncCompilationStatistics; + /* @ddr_namespace: map_to_type=J9JITConfig */ typedef struct J9JITConfig { @@ -4607,6 +4617,7 @@ typedef struct J9JITConfig { IDATA verboseOutputLevel; omrthread_monitor_t compilationMonitor; void* compilationInfo; + J9JITSyncCompilationStatistics* syncCompStats; void* aotCompilationInfo; void* pseudoTOC; void* i2jTransition; diff --git a/runtime/rasdump/javadump.cpp b/runtime/rasdump/javadump.cpp index 54910325f36..be89ec4cae2 100644 --- a/runtime/rasdump/javadump.cpp +++ b/runtime/rasdump/javadump.cpp @@ -307,6 +307,7 @@ private : void writeMonitorSection(void); void writeThreadSection(void); void writeClassSection(void); + void writeSynchronousCompilationSection(void); #if defined(OMR_OPT_CUDA) void writeCudaSection(void); #endif /* defined(OMR_OPT_CUDA) */ @@ -556,6 +557,7 @@ JavaCoreDumpWriter::JavaCoreDumpWriter( CALL_PROTECT(writeSharedClassSection, _Error); #endif CALL_PROTECT(writeClassSection, _Error); + CALL_PROTECT(writeSynchronousCompilationSection, _Error); CALL_PROTECT(writeTrailer, _Error); /* Record the status of the operation */ @@ -2915,6 +2917,62 @@ JavaCoreDumpWriter::writeHookSection(void) _OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n"); } +void +JavaCoreDumpWriter::writeSynchronousCompilationSection(void) +{ + J9JITConfig *jitConfig = _VirtualMachine->jitConfig; + if (NULL == jitConfig || NULL == jitConfig->syncCompStats) { + return; + } + + J9JITSyncCompilationStatistics *stats = jitConfig->syncCompStats; + + _OutputStream.writeCharacters("0SECTION Synchronous compilations info dump routine\n"); + _OutputStream.writeCharacters("NULL ==============================\n"); + _OutputStream.writeCharacters("1NOTE This data is reset after each javacore file is written\n"); + _OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n"); + _OutputStream.writeCharacters("1JITSYNCSTATS Synchronous Compilation Statistics\n"); + _OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n"); + _OutputStream.writeCharacters("2JITSYNCCOUNT Total synchronous compilations: "); + _OutputStream.writeInteger(stats->totalCount, "%u"); + _OutputStream.writeCharacters("\n"); + _OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time (JVM uptime us): "); + _OutputStream.writeInteger(stats->totalWaitTime, "%llu"); + _OutputStream.writeCharacters("us\n"); + if (stats->longestWaitTime != 0) { + _OutputStream.writeCharacters("2JITLONGEST Longest Synchronous Compilation\n"); + _OutputStream.writeCharacters("3JITWAITTIME Wait time: "); + _OutputStream.writeInteger(stats->longestWaitTime, "%llu"); + _OutputStream.writeCharacters("us\n"); + + _OutputStream.writeCharacters("3JITSTARTTIME Wait time start (JVM uptime us): "); + _OutputStream.writeInteger64(stats->longestWaitTimeStart, "%llu"); + _OutputStream.writeCharacters("us\n"); + + _OutputStream.writeCharacters("3JITENDTIME Wait time end (JVM uptime us): "); + _OutputStream.writeInteger64(stats->longestWaitTimeEnd, "%llu"); + _OutputStream.writeCharacters("us\n"); + + if (stats->longestWaitMethod != NULL) { + _OutputStream.writeCharacters("3JITMETHOD Method: "); + _OutputStream.writeCharacters(stats->longestWaitMethod); + _OutputStream.writeCharacters("\n"); + } + + } + + stats->totalCount = 0; + stats->totalWaitTime = 0; + stats->longestWaitTime = 0; + stats->longestWaitTimeStart = 0; + stats->longestWaitTimeEnd = 0; + if (stats->longestWaitMethod != NULL) { + PORT_ACCESS_FROM_PORT(_PortLibrary); + j9mem_free_memory(stats->longestWaitMethod); + stats->longestWaitMethod = NULL; + } +} + #if defined(OMR_OPT_CUDA) /** From 1ca1fb162ec092a811cef6d57f387e7d652e4d81 Mon Sep 17 00:00:00 2001 From: Dev Agarwal Date: Tue, 14 Jul 2026 11:41:26 -0400 Subject: [PATCH 2/2] using abosulte time stamp for endtime, storing top3 longest sync compilations, and also storing thread name --- .../compiler/control/CompilationThread.cpp | 62 ++++++++++++----- runtime/oti/j9nonbuilder.h | 18 +++-- runtime/rasdump/javadump.cpp | 68 +++++++++++++------ 3 files changed, 103 insertions(+), 45 deletions(-) diff --git a/runtime/compiler/control/CompilationThread.cpp b/runtime/compiler/control/CompilationThread.cpp index 3009f0f8756..142de9f7786 100644 --- a/runtime/compiler/control/CompilationThread.cpp +++ b/runtime/compiler/control/CompilationThread.cpp @@ -859,10 +859,16 @@ void TR::CompilationInfo::freeAllResources() freeAllCompilationThreads(); - if (_syncCompStats.longestWaitMethod != NULL) { - PORT_ACCESS_FROM_JITCONFIG(_jitConfig); - j9mem_free_memory(_syncCompStats.longestWaitMethod); - _syncCompStats.longestWaitMethod = NULL; + PORT_ACCESS_FROM_JITCONFIG(_jitConfig); + for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) { + if (_syncCompStats.longestWaitMethods[i].method != NULL) { + j9mem_free_memory(_syncCompStats.longestWaitMethods[i].method); + _syncCompStats.longestWaitMethods[i].method = NULL; + } + if (_syncCompStats.longestWaitMethods[i].thread != NULL) { + j9mem_free_memory(_syncCompStats.longestWaitMethods[i].thread); + _syncCompStats.longestWaitMethods[i].thread = NULL; + } } } @@ -6170,11 +6176,9 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG entry->_numThreadsWaiting++; uint64_t waitStart = 0; - uint64_t waitStartElapsedTime = 0; PORT_ACCESS_FROM_JITCONFIG(_jitConfig); if (!async) { waitStart = j9time_hires_clock(); - waitStartElapsedTime = getPersistentInfo()->getElapsedTime(); } // Release the compilation monitor @@ -6281,31 +6285,55 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG _syncCompStats.totalCount++; _syncCompStats.totalWaitTime += duration; - if (duration > _syncCompStats.longestWaitTime) { - _syncCompStats.longestWaitTime = duration; - _syncCompStats.longestWaitTimeStart = waitStartElapsedTime * 1000; - _syncCompStats.longestWaitTimeEnd = (waitStartElapsedTime * 1000) + duration; + /* Obtain index to insert */ + int idx = -1; + for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) { + if (_syncCompStats.longestWaitMethods[i].waitTime < duration) { + idx = i; + break; + } + } + + if (idx >= 0) { + /* Remove the shortest wait-time */ + J9JITLongestSyncComp &lastMethod = _syncCompStats.longestWaitMethods[J9_LONGEST_SYNC_COMP - 1]; + if (lastMethod.method != NULL) { + j9mem_free_memory(lastMethod.method); + lastMethod.method = NULL; + } + if (lastMethod.thread != NULL) { + j9mem_free_memory(lastMethod.thread); + lastMethod.thread = NULL; + } + for (int i = J9_LONGEST_SYNC_COMP - 1; i > idx; i--) { + _syncCompStats.longestWaitMethods[i] = _syncCompStats.longestWaitMethods[i - 1]; + } + + _syncCompStats.longestWaitMethods[idx].waitTime = duration; + _syncCompStats.longestWaitMethods[idx].waitTimeEnd = j9time_current_time_millis(); J9UTF8 *className; J9UTF8 *name; J9UTF8 *signature; getClassNameSignatureFromMethod(method, className, name, signature); - if (_syncCompStats.longestWaitMethod != NULL) { - j9mem_free_memory(_syncCompStats.longestWaitMethod); - _syncCompStats.longestWaitMethod = NULL; - } - uint32_t totalLen = J9UTF8_LENGTH(className) + J9UTF8_LENGTH(name) + J9UTF8_LENGTH(signature) + 2; char *templongestWaitMethod = (char *)j9mem_allocate_memory(totalLen, J9MEM_CATEGORY_JIT); - if (templongestWaitMethod != NULL) { snprintf(templongestWaitMethod, totalLen, "%.*s.%.*s%.*s", J9UTF8_LENGTH(className), J9UTF8_DATA(className), J9UTF8_LENGTH(name), J9UTF8_DATA(name), J9UTF8_LENGTH(signature), J9UTF8_DATA(signature)); } + _syncCompStats.longestWaitMethods[idx].method = templongestWaitMethod; - _syncCompStats.longestWaitMethod = templongestWaitMethod; + char *threadName = getOMRVMThreadName(vmThread->omrVMThread); + uint32_t len = strlen(threadName) + 1; + char *tempThread = (char *)j9mem_allocate_memory(len, J9MEM_CATEGORY_JIT); + if (tempThread != NULL) { + memcpy(tempThread, threadName, len); + } + _syncCompStats.longestWaitMethods[idx].thread = tempThread; + releaseOMRVMThreadName(vmThread->omrVMThread); } } diff --git a/runtime/oti/j9nonbuilder.h b/runtime/oti/j9nonbuilder.h index d1afa7fbba7..5706af5e6fb 100644 --- a/runtime/oti/j9nonbuilder.h +++ b/runtime/oti/j9nonbuilder.h @@ -295,6 +295,9 @@ #define J9_CATCHTYPE_VALUE_FOR_SYNTHETIC_HANDLER_4BYTES 0xFFFFFFFF #define J9_CATCHTYPE_VALUE_FOR_SYNTHETIC_HANDLER_2BYTES 0xFFFF +/* Constant for information regarding longest synchronous compilations */ +#define J9_LONGEST_SYNC_COMP 3 + #if JAVA_SPEC_VERSION >= 19 #define J9JVMTI_MAX_TLS_KEYS 124 typedef void(*j9_tls_finalizer_t)(void *); @@ -4334,14 +4337,17 @@ typedef struct J9ClassCastParms { struct J9Class* castClass; } J9ClassCastParms; +typedef struct J9JITLongestSyncComp { + uint64_t waitTime; // microseconds (us) + uint64_t waitTimeEnd; // absolute Timestamp + char* method; + char* thread; +} J9JITLongestSyncComp; + typedef struct J9JITSyncCompilationStatistics { - /* All times are in microseconds (us) */ uint32_t totalCount; - uint64_t totalWaitTime; - uint64_t longestWaitTime; - uint64_t longestWaitTimeStart; - uint64_t longestWaitTimeEnd; - char* longestWaitMethod; + uint64_t totalWaitTime; // microseconds (us) + J9JITLongestSyncComp longestWaitMethods[J9_LONGEST_SYNC_COMP]; } J9JITSyncCompilationStatistics; /* @ddr_namespace: map_to_type=J9JITConfig */ diff --git a/runtime/rasdump/javadump.cpp b/runtime/rasdump/javadump.cpp index be89ec4cae2..46b5ae52f5b 100644 --- a/runtime/rasdump/javadump.cpp +++ b/runtime/rasdump/javadump.cpp @@ -2920,6 +2920,10 @@ JavaCoreDumpWriter::writeHookSection(void) void JavaCoreDumpWriter::writeSynchronousCompilationSection(void) { + char timeStamp[_MaximumTimeStampLength + 1]; + PORT_ACCESS_FROM_PORT(_PortLibrary); + OMRPORT_ACCESS_FROM_J9PORT(PORTLIB); + J9JITConfig *jitConfig = _VirtualMachine->jitConfig; if (NULL == jitConfig || NULL == jitConfig->syncCompStats) { return; @@ -2936,41 +2940,61 @@ JavaCoreDumpWriter::writeSynchronousCompilationSection(void) _OutputStream.writeCharacters("2JITSYNCCOUNT Total synchronous compilations: "); _OutputStream.writeInteger(stats->totalCount, "%u"); _OutputStream.writeCharacters("\n"); - _OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time (JVM uptime us): "); + _OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time: "); _OutputStream.writeInteger(stats->totalWaitTime, "%llu"); _OutputStream.writeCharacters("us\n"); - if (stats->longestWaitTime != 0) { - _OutputStream.writeCharacters("2JITLONGEST Longest Synchronous Compilation\n"); + for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) { + if (stats->longestWaitMethods[i].waitTime == 0 || stats->longestWaitMethods[i].method == NULL) + break; + _OutputStream.writeCharacters("2JITLONGEST "); + if (i == 0) { + _OutputStream.writeCharacters("Longest"); + } + else if (i == 1) { + _OutputStream.writeCharacters("2nd Longest"); + } + else { + _OutputStream.writeCharacters("3rd Longest"); + } + _OutputStream.writeCharacters(" Synchronous Compilation\n"); + _OutputStream.writeCharacters("3JITWAITTIME Wait time: "); - _OutputStream.writeInteger(stats->longestWaitTime, "%llu"); + _OutputStream.writeInteger(stats->longestWaitMethods[i].waitTime, "%llu"); _OutputStream.writeCharacters("us\n"); - _OutputStream.writeCharacters("3JITSTARTTIME Wait time start (JVM uptime us): "); - _OutputStream.writeInteger64(stats->longestWaitTimeStart, "%llu"); - _OutputStream.writeCharacters("us\n"); + _OutputStream.writeCharacters("3JITENDTIME Wait time end: "); + omrstr_ftime_ex(timeStamp, _MaximumTimeStampLength, "%Y-%m-%dT%H:%M:%S", + stats->longestWaitMethods[i].waitTimeEnd, OMRSTR_FTIME_FLAG_LOCAL); + timeStamp[_MaximumTimeStampLength] = '\0'; + _OutputStream.writeCharacters(timeStamp); + _OutputStream.writeInteger64(stats->longestWaitMethods[i].waitTimeEnd % 1000, ".%03llu"); + _OutputStream.writeCharacters("\n"); - _OutputStream.writeCharacters("3JITENDTIME Wait time end (JVM uptime us): "); - _OutputStream.writeInteger64(stats->longestWaitTimeEnd, "%llu"); - _OutputStream.writeCharacters("us\n"); + _OutputStream.writeCharacters("3JITMETHOD Method: "); + _OutputStream.writeCharacters(stats->longestWaitMethods[i].method); + _OutputStream.writeCharacters("\n"); - if (stats->longestWaitMethod != NULL) { - _OutputStream.writeCharacters("3JITMETHOD Method: "); - _OutputStream.writeCharacters(stats->longestWaitMethod); + if (stats->longestWaitMethods[i].thread != NULL) { + _OutputStream.writeCharacters("3JITTHREAD Thread: "); + _OutputStream.writeCharacters(stats->longestWaitMethods[i].thread); _OutputStream.writeCharacters("\n"); } - } stats->totalCount = 0; stats->totalWaitTime = 0; - stats->longestWaitTime = 0; - stats->longestWaitTimeStart = 0; - stats->longestWaitTimeEnd = 0; - if (stats->longestWaitMethod != NULL) { - PORT_ACCESS_FROM_PORT(_PortLibrary); - j9mem_free_memory(stats->longestWaitMethod); - stats->longestWaitMethod = NULL; - } + for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) { + stats->longestWaitMethods[i].waitTime = 0; + stats->longestWaitMethods[i].waitTimeEnd = 0; + if (stats->longestWaitMethods[i].method != NULL) { + j9mem_free_memory(stats->longestWaitMethods[i].method); + stats->longestWaitMethods[i].method = NULL; + } + if (stats->longestWaitMethods[i].thread != NULL) { + j9mem_free_memory(stats->longestWaitMethods[i].thread); + stats->longestWaitMethods[i].thread = NULL; + } + } } #if defined(OMR_OPT_CUDA)