Skip to content

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.

Sign up for GitHub

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

Open
dev-koan wants to merge 4 commits into
base: master
Choose a base branch
from
+174 −0
Open

Add information regarding synchronous compilations in javacore #24236

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
88e217d
Add information regarding synchronous compilations in javacore
dev-koan Jun 24, 2026
5052e90
recent review updates
dev-koan Jul 23, 2026
a89e375
review update
dev-koan Jul 24, 2026
a3b6534
review updates
dev-koan Jul 24, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions runtime/compiler/control/CompilationRuntime.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -512,6 +512,8 @@ class CompilationInfo {
}
}; // CompilationStatsPerInterval

typedef J9JITSyncCompilationStatistics SyncCompilationStatistics;

@keithc-ca keithc-ca Jul 29, 2026

Copy link
Copy Markdown
Contributor

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.


static bool createCompilationInfo(J9JITConfig *jitConfig);
static void freeCompilationInfo(J9JITConfig *jitConfig);

Expand Down
80 changes: 80 additions & 0 deletions runtime/compiler/control/CompilationThread.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -857,6 +857,20 @@ void TR::CompilationInfo::freeAllResources()
}

freeAllCompilationThreads();

PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
J9JITSyncCompilationStatistics &syncCompStats = _jitConfig->syncCompStats;
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)
Expand Down Expand Up @@ -6182,6 +6196,12 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG
//
entry->_numThreadsWaiting++;

uint64_t waitStart = 0;
Comment thread
mpirvu marked this conversation as resolved.
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);

@keithc-ca keithc-ca Jul 29, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The 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");
Expand Down Expand Up @@ -6279,6 +6299,66 @@ 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);
J9JITSyncCompilationStatistics &syncCompStats = _jitConfig->syncCompStats;

syncCompStats.totalCount++;
syncCompStats.totalWaitTime += duration;

/* Obtain index to insert. */
int32_t idx = -1;
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");

Expand Down
17 changes: 17 additions & 0 deletions runtime/oti/j9nonbuilder.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 *);
Expand Down Expand Up @@ -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 decreasing order */
} J9JITSyncCompilationStatistics;

/* @ddr_namespace: map_to_type=J9JITConfig */

typedef struct J9JITConfig {
Expand Down Expand Up @@ -4649,6 +4665,7 @@ typedef struct J9JITConfig {
IDATA verboseOutputLevel;
omrthread_monitor_t compilationMonitor;
void* compilationInfo;
J9JITSyncCompilationStatistics syncCompStats;
void* aotCompilationInfo;
void* pseudoTOC;
void* i2jTransition;
Expand Down
75 changes: 75 additions & 0 deletions runtime/rasdump/javadump.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) */
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -2915,6 +2917,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) {
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 (UDATA i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) {
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);
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 (UDATA i = 0; i < J9_NUM_LONGEST_SYNC_COMP; i++) {
J9JITLongestSyncComp &longestWaitMethod = stats.longestWaitMethods[i];
Comment on lines +2978 to +2979

@keithc-ca keithc-ca Jul 29, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The race here might best be dealt with by using a flag that signals the data is stale. Then, above, printing would occur only if not stale, and JIT code would be responsible for clearing stale entries (under a suitable lock). Here, we would only mark the data as stale after printing (if it wasn't stale before).

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)

/**
Expand Down