-
Notifications
You must be signed in to change notification settings - Fork 789
Add information regarding synchronous compilations in javacore #24236
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Changes from 3 commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -21,6 +21,7 @@ | |
| * Assisted-by: IBM Bob | ||
| *******************************************************************************/ | ||
|
|
||
| #include <cstdint> | ||
|
mpirvu marked this conversation as resolved.
Outdated
|
||
| #define J9_EXTERNAL_TO_VM | ||
|
|
||
| #if SOLARIS || AIXPPC || LINUX || OSX | ||
|
|
@@ -807,6 +808,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 +859,19 @@ void TR::CompilationInfo::freeAllResources() | |
| } | ||
|
|
||
| freeAllCompilationThreads(); | ||
|
|
||
| PORT_ACCESS_FROM_JITCONFIG(_jitConfig); | ||
| for (int32_t i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) { | ||
| J9JITLongestSyncComp &longestWaitMethod = _syncCompStats.longestWaitMethods[i]; | ||
| if (longestWaitMethod.methodName != NULL) { | ||
| j9mem_free_memory(longestWaitMethod.methodName); | ||
| longestWaitMethod.methodName = NULL; | ||
| } | ||
| if (longestWaitMethod.threadName != NULL) { | ||
| j9mem_free_memory(longestWaitMethod.threadName); | ||
| longestWaitMethod.threadName = NULL; | ||
| } | ||
| } | ||
| } | ||
|
|
||
| void TR::CompilationInfo::freeCompilationInfo(J9JITConfig *jitConfig) | ||
|
|
@@ -6182,6 +6197,12 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG | |
| // | ||
| entry->_numThreadsWaiting++; | ||
|
|
||
| uint64_t waitStart = 0; | ||
|
mpirvu marked this conversation as resolved.
|
||
| PORT_ACCESS_FROM_JITCONFIG(_jitConfig); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. With this, line 6375 provides a duplicate local; that line should be removed. |
||
| if (!async) { | ||
| waitStart = j9time_hires_clock(); | ||
| } | ||
|
|
||
| // Release the compilation monitor | ||
| // | ||
| debugPrint(vmThread, "\tapplication thread releasing compilation monitor\n"); | ||
|
|
@@ -6279,6 +6300,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; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This should use the same type as
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Updated. |
||
| for (int32_t i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) { | ||
| if (_syncCompStats.longestWaitMethods[i].waitTime < duration) { | ||
| idx = i; | ||
| break; | ||
| } | ||
| } | ||
|
|
||
| if (0 <= idx) { | ||
| /* Remove the shortest wait-time. */ | ||
| J9JITLongestSyncComp &lastMethod = _syncCompStats.longestWaitMethods[J9_NUM_LONGEST_SYNC_COMP - 1]; | ||
| if (NULL != lastMethod.methodName) { | ||
| j9mem_free_memory(lastMethod.methodName); | ||
| lastMethod.methodName = NULL; | ||
| } | ||
| if (NULL != lastMethod.threadName) { | ||
| j9mem_free_memory(lastMethod.threadName); | ||
| lastMethod.threadName = NULL; | ||
| } | ||
| for (int32_t i = J9_NUM_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 = NULL; | ||
| J9UTF8 *name = NULL; | ||
| J9UTF8 *signature = NULL; | ||
| 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 (NULL != templongestWaitMethod) { | ||
| j9str_printf(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].methodName = templongestWaitMethod; | ||
|
|
||
| const char *threadName = getOMRVMThreadName(vmThread->omrVMThread); | ||
| uint32_t len = strlen(threadName); | ||
| char *tempThread = (char *)j9mem_allocate_memory(len + 1, J9MEM_CATEGORY_JIT); | ||
| if (NULL != tempThread) { | ||
| memcpy(tempThread, threadName, len + 1); | ||
| } | ||
| _syncCompStats.longestWaitMethods[idx].threadName = tempThread; | ||
| releaseOMRVMThreadName(vmThread->omrVMThread); | ||
| } | ||
| } | ||
|
|
||
| TR_ASSERT_FATAL(!(entry->_freeTag & (ENTRY_DEALLOCATED | ENTRY_IN_POOL_FREE)), | ||
| "Java thread waking up with a freed entry"); | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -297,6 +297,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_NUM_LONGEST_SYNC_COMP 3 | ||
|
|
||
| #if JAVA_SPEC_VERSION >= 19 | ||
| #define J9JVMTI_MAX_TLS_KEYS 124 | ||
| typedef void(*j9_tls_finalizer_t)(void *); | ||
|
|
@@ -4376,6 +4379,19 @@ typedef struct J9ClassCastParms { | |
| struct J9Class* castClass; | ||
| } J9ClassCastParms; | ||
|
|
||
| typedef struct J9JITLongestSyncComp { | ||
| uint64_t waitTime; /* microseconds */ | ||
| uint64_t waitTimeEnd; /* absolute timestamp */ | ||
| char *methodName; | ||
| char *threadName; | ||
| } J9JITLongestSyncComp; | ||
|
|
||
| typedef struct J9JITSyncCompilationStatistics { | ||
| uint32_t totalCount; | ||
| uint64_t totalWaitTime; /* microseconds */ | ||
| J9JITLongestSyncComp longestWaitMethods[J9_NUM_LONGEST_SYNC_COMP]; /* sorted in increasing order */ | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think you mean "decreasing" (the first entry has the longest wait time).
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Updated. |
||
| } J9JITSyncCompilationStatistics; | ||
|
|
||
| /* @ddr_namespace: map_to_type=J9JITConfig */ | ||
|
|
||
| typedef struct J9JITConfig { | ||
|
|
@@ -4649,6 +4665,7 @@ typedef struct J9JITConfig { | |
| IDATA verboseOutputLevel; | ||
| omrthread_monitor_t compilationMonitor; | ||
| void* compilationInfo; | ||
| J9JITSyncCompilationStatistics *syncCompStats; | ||
|
mpirvu marked this conversation as resolved.
Outdated
|
||
| void* aotCompilationInfo; | ||
| void* pseudoTOC; | ||
| void* i2jTransition; | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -21,6 +21,7 @@ | |
| *******************************************************************************/ | ||
|
|
||
| /* Includes */ | ||
| #include <cstdint> | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't think this is necessary.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Updated. |
||
| #if defined(AIXPPC) | ||
| #include <sys/time.h> | ||
| #endif /* defined(AIXPPC) */ | ||
|
|
@@ -307,6 +308,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 +558,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 +2918,79 @@ 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.writeInteger64(stats->totalWaitTime, "%llu"); | ||
| _OutputStream.writeCharacters("us\n"); | ||
| for (int32_t i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) { | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Suggest using
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Updated. |
||
| J9JITLongestSyncComp &longestWaitMethod = stats->longestWaitMethods[i]; | ||
| if ((0 == longestWaitMethod.waitTime) || (NULL == longestWaitMethod.methodName)) { | ||
| break; | ||
| } | ||
| _OutputStream.writeCharacters("2JITLONGEST "); | ||
| _OutputStream.writeInteger(i + 1, "%zu"); | ||
| _OutputStream.writeCharacters(". Longest Synchronous Compilation\n"); | ||
|
|
||
| _OutputStream.writeCharacters("3JITWAITTIME Wait time: "); | ||
| _OutputStream.writeInteger(longestWaitMethod.waitTime, "%llu"); | ||
| _OutputStream.writeCharacters("us\n"); | ||
|
|
||
| _OutputStream.writeCharacters("3JITENDTIME Wait time end: "); | ||
| omrstr_ftime_ex(timeStamp, _MaximumTimeStampLength, "%Y-%m-%dT%H:%M:%S", | ||
| longestWaitMethod.waitTimeEnd, OMRSTR_FTIME_FLAG_LOCAL); | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Excessive indentation: Two tabs more than line 2961 is sufficient.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Updated. |
||
| timeStamp[_MaximumTimeStampLength] = '\0'; | ||
| _OutputStream.writeCharacters(timeStamp); | ||
| _OutputStream.writeInteger64(longestWaitMethod.waitTimeEnd % 1000, ".%03llu"); | ||
| _OutputStream.writeCharacters("\n"); | ||
|
|
||
| _OutputStream.writeCharacters("3JITMETHOD Method: "); | ||
| _OutputStream.writeCharacters(longestWaitMethod.methodName); | ||
| _OutputStream.writeCharacters("\n"); | ||
|
|
||
| _OutputStream.writeCharacters("3JITTHREAD Thread: "); | ||
| _OutputStream.writeCharacters(longestWaitMethod.threadName); | ||
| _OutputStream.writeCharacters("\n"); | ||
| } | ||
|
|
||
| stats->totalCount = 0; | ||
| stats->totalWaitTime = 0; | ||
| for (int32_t i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) { | ||
| J9JITLongestSyncComp &longestWaitMethod = stats->longestWaitMethods[i]; | ||
| longestWaitMethod.waitTime = 0; | ||
| longestWaitMethod.waitTimeEnd = 0; | ||
| if (NULL != longestWaitMethod.methodName) { | ||
| j9mem_free_memory(longestWaitMethod.methodName); | ||
| longestWaitMethod.methodName = NULL; | ||
| } | ||
| if (NULL != longestWaitMethod.threadName) { | ||
| j9mem_free_memory(longestWaitMethod.threadName); | ||
| longestWaitMethod.threadName = NULL; | ||
| } | ||
| } | ||
| } | ||
|
|
||
| #if defined(OMR_OPT_CUDA) | ||
|
|
||
| /** | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This doesn't appear to be used anywhere: Please remove it.