Skip to content

Commit c681c62

Browse files
dev-koandev-koan
committed
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 <dev.agarwal@ibm.com>
1 parent 7d59d0f commit c681c62

4 files changed

Lines changed: 122 additions & 0 deletions

File tree

‎runtime/compiler/control/CompilationRuntime.hpp‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -512,6 +512,8 @@ class CompilationInfo {
512512
}
513513
}; // CompilationStatsPerInterval
514514

515+
typedef J9JITSyncCompilationStatistics SyncCompilationStatistics;
516+
515517
static bool createCompilationInfo(J9JITConfig *jitConfig);
516518
static void freeCompilationInfo(J9JITConfig *jitConfig);
517519

@@ -1508,6 +1510,7 @@ class CompilationInfo {
15081510

15091511
struct CompilationStatistics _stats;
15101512
struct CompilationStatsPerInterval _intervalStats;
1513+
SyncCompilationStatistics _syncCompStats;
15111514
TR_PersistentArray<TR_SignatureCountPair *> *_persistedMethods;
15121515

15131516
// Must be less than 16 at the JITClient or non-JITServer mode because

‎runtime/compiler/control/CompilationThread.cpp‎

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -807,6 +807,7 @@ bool TR::CompilationInfo::createCompilationInfo(J9JITConfig *jitConfig)
807807
memset(alloc, 0, sizeof(TR::CompilationInfo));
808808
_compilationRuntime = new (alloc) TR::CompilationInfo(jitConfig);
809809
jitConfig->compilationRuntime = (void *)_compilationRuntime;
810+
jitConfig->syncCompStats = &_compilationRuntime->_syncCompStats;
810811
#ifdef DEBUG
811812
if (debug("traceThreadCompile"))
812813
_compilationRuntime->_traceCompiling = true;
@@ -857,6 +858,12 @@ void TR::CompilationInfo::freeAllResources()
857858
}
858859

859860
freeAllCompilationThreads();
861+
862+
if (_syncCompStats.longestWaitMethod != NULL) {
863+
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
864+
j9mem_free_memory(_syncCompStats.longestWaitMethod);
865+
_syncCompStats.longestWaitMethod = NULL;
866+
}
860867
}
861868

862869
void TR::CompilationInfo::freeCompilationInfo(J9JITConfig *jitConfig)
@@ -6162,6 +6169,14 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG
61626169
//
61636170
entry->_numThreadsWaiting++;
61646171

6172+
uint64_t waitStart = 0;
6173+
uint64_t waitStartElapsedTime = 0;
6174+
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
6175+
if (!async) {
6176+
waitStart = j9time_hires_clock();
6177+
waitStartElapsedTime = getPersistentInfo()->getElapsedTime();
6178+
}
6179+
61656180
// Release the compilation monitor
61666181
//
61676182
debugPrint(vmThread, "\tapplication thread releasing compilation monitor\n");
@@ -6259,6 +6274,41 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG
62596274

62606275
entry->_numThreadsWaiting--;
62616276

6277+
if (!async) {
6278+
uint64_t waitEnd = j9time_hires_clock();
6279+
uint64_t duration = j9time_hires_delta(waitStart, waitEnd, J9PORT_TIME_DELTA_IN_MICROSECONDS);
6280+
6281+
_syncCompStats.totalCount++;
6282+
_syncCompStats.totalWaitTime += duration;
6283+
6284+
if (duration > _syncCompStats.longestWaitTime) {
6285+
_syncCompStats.longestWaitTime = duration;
6286+
_syncCompStats.longestWaitTimeStart = waitStartElapsedTime * 1000;
6287+
_syncCompStats.longestWaitTimeEnd = (waitStartElapsedTime * 1000) + duration;
6288+
6289+
J9UTF8 *className;
6290+
J9UTF8 *name;
6291+
J9UTF8 *signature;
6292+
getClassNameSignatureFromMethod(method, className, name, signature);
6293+
6294+
if (_syncCompStats.longestWaitMethod != NULL) {
6295+
j9mem_free_memory(_syncCompStats.longestWaitMethod);
6296+
_syncCompStats.longestWaitMethod = NULL;
6297+
}
6298+
6299+
uint32_t totalLen = J9UTF8_LENGTH(className) + J9UTF8_LENGTH(name) + J9UTF8_LENGTH(signature) + 2;
6300+
char *templongestWaitMethod = (char *)j9mem_allocate_memory(totalLen, J9MEM_CATEGORY_JIT);
6301+
6302+
if (templongestWaitMethod != NULL) {
6303+
snprintf(templongestWaitMethod, totalLen, "%.*s.%.*s%.*s", J9UTF8_LENGTH(className),
6304+
J9UTF8_DATA(className), J9UTF8_LENGTH(name), J9UTF8_DATA(name), J9UTF8_LENGTH(signature),
6305+
J9UTF8_DATA(signature));
6306+
}
6307+
6308+
_syncCompStats.longestWaitMethod = templongestWaitMethod;
6309+
}
6310+
}
6311+
62626312
TR_ASSERT_FATAL(!(entry->_freeTag & (ENTRY_DEALLOCATED | ENTRY_IN_POOL_FREE)),
62636313
"Java thread waking up with a freed entry");
62646314

‎runtime/oti/j9nonbuilder.h‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4334,6 +4334,16 @@ typedef struct J9ClassCastParms {
43344334
struct J9Class* castClass;
43354335
} J9ClassCastParms;
43364336

4337+
typedef struct J9JITSyncCompilationStatistics {
4338+
/* All times are in microseconds (us) */
4339+
uint32_t totalCount;
4340+
uint64_t totalWaitTime;
4341+
uint64_t longestWaitTime;
4342+
uint64_t longestWaitTimeStart;
4343+
uint64_t longestWaitTimeEnd;
4344+
char* longestWaitMethod;
4345+
} J9JITSyncCompilationStatistics;
4346+
43374347
/* @ddr_namespace: map_to_type=J9JITConfig */
43384348

43394349
typedef struct J9JITConfig {
@@ -4607,6 +4617,7 @@ typedef struct J9JITConfig {
46074617
IDATA verboseOutputLevel;
46084618
omrthread_monitor_t compilationMonitor;
46094619
void* compilationInfo;
4620+
J9JITSyncCompilationStatistics* syncCompStats;
46104621
void* aotCompilationInfo;
46114622
void* pseudoTOC;
46124623
void* i2jTransition;

‎runtime/rasdump/javadump.cpp‎

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -307,6 +307,7 @@ private :
307307
void writeMonitorSection(void);
308308
void writeThreadSection(void);
309309
void writeClassSection(void);
310+
void writeSynchronousCompilationSection(void);
310311
#if defined(OMR_OPT_CUDA)
311312
void writeCudaSection(void);
312313
#endif /* defined(OMR_OPT_CUDA) */
@@ -556,6 +557,7 @@ JavaCoreDumpWriter::JavaCoreDumpWriter(
556557
CALL_PROTECT(writeSharedClassSection, _Error);
557558
#endif
558559
CALL_PROTECT(writeClassSection, _Error);
560+
CALL_PROTECT(writeSynchronousCompilationSection, _Error);
559561
CALL_PROTECT(writeTrailer, _Error);
560562

561563
/* Record the status of the operation */
@@ -2915,6 +2917,62 @@ JavaCoreDumpWriter::writeHookSection(void)
29152917
_OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n");
29162918
}
29172919

2920+
void
2921+
JavaCoreDumpWriter::writeSynchronousCompilationSection(void)
2922+
{
2923+
J9JITConfig *jitConfig = _VirtualMachine->jitConfig;
2924+
if (NULL == jitConfig || NULL == jitConfig->syncCompStats) {
2925+
return;
2926+
}
2927+
2928+
J9JITSyncCompilationStatistics *stats = jitConfig->syncCompStats;
2929+
2930+
_OutputStream.writeCharacters("0SECTION Synchronous compilations info dump routine\n");
2931+
_OutputStream.writeCharacters("NULL ==============================\n");
2932+
_OutputStream.writeCharacters("1NOTE This data is reset after each javacore file is written\n");
2933+
_OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n");
2934+
_OutputStream.writeCharacters("1JITSYNCSTATS Synchronous Compilation Statistics\n");
2935+
_OutputStream.writeCharacters("NULL ------------------------------------------------------------------------\n");
2936+
_OutputStream.writeCharacters("2JITSYNCCOUNT Total synchronous compilations: ");
2937+
_OutputStream.writeInteger(stats->totalCount, "%u");
2938+
_OutputStream.writeCharacters("\n");
2939+
_OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time (JVM uptime us): ");
2940+
_OutputStream.writeInteger(stats->totalWaitTime, "%llu");
2941+
_OutputStream.writeCharacters("us\n");
2942+
if (stats->longestWaitTime != 0) {
2943+
_OutputStream.writeCharacters("2JITLONGEST Longest Synchronous Compilation\n");
2944+
_OutputStream.writeCharacters("3JITWAITTIME Wait time: ");
2945+
_OutputStream.writeInteger(stats->longestWaitTime, "%llu");
2946+
_OutputStream.writeCharacters("us\n");
2947+
2948+
_OutputStream.writeCharacters("3JITSTARTTIME Wait time start (JVM uptime us): ");
2949+
_OutputStream.writeInteger64(stats->longestWaitTimeStart, "%llu");
2950+
_OutputStream.writeCharacters("us\n");
2951+
2952+
_OutputStream.writeCharacters("3JITENDTIME Wait time end (JVM uptime us): ");
2953+
_OutputStream.writeInteger64(stats->longestWaitTimeEnd, "%llu");
2954+
_OutputStream.writeCharacters("us\n");
2955+
2956+
if (stats->longestWaitMethod != NULL) {
2957+
_OutputStream.writeCharacters("3JITMETHOD Method: ");
2958+
_OutputStream.writeCharacters(stats->longestWaitMethod);
2959+
_OutputStream.writeCharacters("\n");
2960+
}
2961+
2962+
}
2963+
2964+
stats->totalCount = 0;
2965+
stats->totalWaitTime = 0;
2966+
stats->longestWaitTime = 0;
2967+
stats->longestWaitTimeStart = 0;
2968+
stats->longestWaitTimeEnd = 0;
2969+
if (stats->longestWaitMethod != NULL) {
2970+
PORT_ACCESS_FROM_PORT(_PortLibrary);
2971+
j9mem_free_memory(stats->longestWaitMethod);
2972+
stats->longestWaitMethod = NULL;
2973+
}
2974+
}
2975+
29182976
#if defined(OMR_OPT_CUDA)
29192977

29202978
/**

0 commit comments

Comments
 (0)