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..142de9f7786 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,18 @@ void TR::CompilationInfo::freeAllResources() } freeAllCompilationThreads(); + + 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; + } + } } void TR::CompilationInfo::freeCompilationInfo(J9JITConfig *jitConfig) @@ -6162,6 +6175,12 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG // entry->_numThreadsWaiting++; + uint64_t waitStart = 0; + PORT_ACCESS_FROM_JITCONFIG(_jitConfig); + if (!async) { + waitStart = j9time_hires_clock(); + } + // Release the compilation monitor // debugPrint(vmThread, "\tapplication thread releasing compilation monitor\n"); @@ -6259,6 +6278,65 @@ 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; + + /* 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); + + 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; + + 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); + } + } + 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..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,6 +4337,19 @@ 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 { + uint32_t totalCount; + uint64_t totalWaitTime; // microseconds (us) + J9JITLongestSyncComp longestWaitMethods[J9_LONGEST_SYNC_COMP]; +} J9JITSyncCompilationStatistics; + /* @ddr_namespace: map_to_type=J9JITConfig */ typedef struct J9JITConfig { @@ -4607,6 +4623,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..46b5ae52f5b 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,86 @@ JavaCoreDumpWriter::writeHookSection(void) _OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n"); } +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; + } + + 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: "); + _OutputStream.writeInteger(stats->totalWaitTime, "%llu"); + _OutputStream.writeCharacters("us\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->longestWaitMethods[i].waitTime, "%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("3JITMETHOD Method: "); + _OutputStream.writeCharacters(stats->longestWaitMethods[i].method); + _OutputStream.writeCharacters("\n"); + + 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; + 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) /**