Skip to content

Commit 1ca1fb1

Browse files
dev-koandev-koan
committed
using abosulte time stamp for endtime, storing top3 longest sync compilations, and also storing thread name
1 parent c681c62 commit 1ca1fb1

3 files changed

Lines changed: 103 additions & 45 deletions

File tree

‎runtime/compiler/control/CompilationThread.cpp‎

Lines changed: 45 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -859,10 +859,16 @@ void TR::CompilationInfo::freeAllResources()
859859

860860
freeAllCompilationThreads();
861861

862-
if (_syncCompStats.longestWaitMethod != NULL) {
863-
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
864-
j9mem_free_memory(_syncCompStats.longestWaitMethod);
865-
_syncCompStats.longestWaitMethod = NULL;
862+
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
863+
for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) {
864+
if (_syncCompStats.longestWaitMethods[i].method != NULL) {
865+
j9mem_free_memory(_syncCompStats.longestWaitMethods[i].method);
866+
_syncCompStats.longestWaitMethods[i].method = NULL;
867+
}
868+
if (_syncCompStats.longestWaitMethods[i].thread != NULL) {
869+
j9mem_free_memory(_syncCompStats.longestWaitMethods[i].thread);
870+
_syncCompStats.longestWaitMethods[i].thread = NULL;
871+
}
866872
}
867873
}
868874

@@ -6170,11 +6176,9 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG
61706176
entry->_numThreadsWaiting++;
61716177

61726178
uint64_t waitStart = 0;
6173-
uint64_t waitStartElapsedTime = 0;
61746179
PORT_ACCESS_FROM_JITCONFIG(_jitConfig);
61756180
if (!async) {
61766181
waitStart = j9time_hires_clock();
6177-
waitStartElapsedTime = getPersistentInfo()->getElapsedTime();
61786182
}
61796183

61806184
// Release the compilation monitor
@@ -6281,31 +6285,55 @@ void *TR::CompilationInfo::compileOnSeparateThread(J9VMThread *vmThread, TR::IlG
62816285
_syncCompStats.totalCount++;
62826286
_syncCompStats.totalWaitTime += duration;
62836287

6284-
if (duration > _syncCompStats.longestWaitTime) {
6285-
_syncCompStats.longestWaitTime = duration;
6286-
_syncCompStats.longestWaitTimeStart = waitStartElapsedTime * 1000;
6287-
_syncCompStats.longestWaitTimeEnd = (waitStartElapsedTime * 1000) + duration;
6288+
/* Obtain index to insert */
6289+
int idx = -1;
6290+
for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) {
6291+
if (_syncCompStats.longestWaitMethods[i].waitTime < duration) {
6292+
idx = i;
6293+
break;
6294+
}
6295+
}
6296+
6297+
if (idx >= 0) {
6298+
/* Remove the shortest wait-time */
6299+
J9JITLongestSyncComp &lastMethod = _syncCompStats.longestWaitMethods[J9_LONGEST_SYNC_COMP - 1];
6300+
if (lastMethod.method != NULL) {
6301+
j9mem_free_memory(lastMethod.method);
6302+
lastMethod.method = NULL;
6303+
}
6304+
if (lastMethod.thread != NULL) {
6305+
j9mem_free_memory(lastMethod.thread);
6306+
lastMethod.thread = NULL;
6307+
}
6308+
for (int i = J9_LONGEST_SYNC_COMP - 1; i > idx; i--) {
6309+
_syncCompStats.longestWaitMethods[i] = _syncCompStats.longestWaitMethods[i - 1];
6310+
}
6311+
6312+
_syncCompStats.longestWaitMethods[idx].waitTime = duration;
6313+
_syncCompStats.longestWaitMethods[idx].waitTimeEnd = j9time_current_time_millis();
62886314

62896315
J9UTF8 *className;
62906316
J9UTF8 *name;
62916317
J9UTF8 *signature;
62926318
getClassNameSignatureFromMethod(method, className, name, signature);
62936319

6294-
if (_syncCompStats.longestWaitMethod != NULL) {
6295-
j9mem_free_memory(_syncCompStats.longestWaitMethod);
6296-
_syncCompStats.longestWaitMethod = NULL;
6297-
}
6298-
62996320
uint32_t totalLen = J9UTF8_LENGTH(className) + J9UTF8_LENGTH(name) + J9UTF8_LENGTH(signature) + 2;
63006321
char *templongestWaitMethod = (char *)j9mem_allocate_memory(totalLen, J9MEM_CATEGORY_JIT);
6301-
63026322
if (templongestWaitMethod != NULL) {
63036323
snprintf(templongestWaitMethod, totalLen, "%.*s.%.*s%.*s", J9UTF8_LENGTH(className),
63046324
J9UTF8_DATA(className), J9UTF8_LENGTH(name), J9UTF8_DATA(name), J9UTF8_LENGTH(signature),
63056325
J9UTF8_DATA(signature));
63066326
}
6327+
_syncCompStats.longestWaitMethods[idx].method = templongestWaitMethod;
63076328

6308-
_syncCompStats.longestWaitMethod = templongestWaitMethod;
6329+
char *threadName = getOMRVMThreadName(vmThread->omrVMThread);
6330+
uint32_t len = strlen(threadName) + 1;
6331+
char *tempThread = (char *)j9mem_allocate_memory(len, J9MEM_CATEGORY_JIT);
6332+
if (tempThread != NULL) {
6333+
memcpy(tempThread, threadName, len);
6334+
}
6335+
_syncCompStats.longestWaitMethods[idx].thread = tempThread;
6336+
releaseOMRVMThreadName(vmThread->omrVMThread);
63096337
}
63106338
}
63116339

‎runtime/oti/j9nonbuilder.h‎

Lines changed: 12 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -295,6 +295,9 @@
295295
#define J9_CATCHTYPE_VALUE_FOR_SYNTHETIC_HANDLER_4BYTES 0xFFFFFFFF
296296
#define J9_CATCHTYPE_VALUE_FOR_SYNTHETIC_HANDLER_2BYTES 0xFFFF
297297

298+
/* Constant for information regarding longest synchronous compilations */
299+
#define J9_LONGEST_SYNC_COMP 3
300+
298301
#if JAVA_SPEC_VERSION >= 19
299302
#define J9JVMTI_MAX_TLS_KEYS 124
300303
typedef void(*j9_tls_finalizer_t)(void *);
@@ -4334,14 +4337,17 @@ typedef struct J9ClassCastParms {
43344337
struct J9Class* castClass;
43354338
} J9ClassCastParms;
43364339

4340+
typedef struct J9JITLongestSyncComp {
4341+
uint64_t waitTime; // microseconds (us)
4342+
uint64_t waitTimeEnd; // absolute Timestamp
4343+
char* method;
4344+
char* thread;
4345+
} J9JITLongestSyncComp;
4346+
43374347
typedef struct J9JITSyncCompilationStatistics {
4338-
/* All times are in microseconds (us) */
43394348
uint32_t totalCount;
4340-
uint64_t totalWaitTime;
4341-
uint64_t longestWaitTime;
4342-
uint64_t longestWaitTimeStart;
4343-
uint64_t longestWaitTimeEnd;
4344-
char* longestWaitMethod;
4349+
uint64_t totalWaitTime; // microseconds (us)
4350+
J9JITLongestSyncComp longestWaitMethods[J9_LONGEST_SYNC_COMP];
43454351
} J9JITSyncCompilationStatistics;
43464352

43474353
/* @ddr_namespace: map_to_type=J9JITConfig */

‎runtime/rasdump/javadump.cpp‎

Lines changed: 46 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -2920,6 +2920,10 @@ JavaCoreDumpWriter::writeHookSection(void)
29202920
void
29212921
JavaCoreDumpWriter::writeSynchronousCompilationSection(void)
29222922
{
2923+
char timeStamp[_MaximumTimeStampLength + 1];
2924+
PORT_ACCESS_FROM_PORT(_PortLibrary);
2925+
OMRPORT_ACCESS_FROM_J9PORT(PORTLIB);
2926+
29232927
J9JITConfig *jitConfig = _VirtualMachine->jitConfig;
29242928
if (NULL == jitConfig || NULL == jitConfig->syncCompStats) {
29252929
return;
@@ -2936,41 +2940,61 @@ JavaCoreDumpWriter::writeSynchronousCompilationSection(void)
29362940
_OutputStream.writeCharacters("2JITSYNCCOUNT Total synchronous compilations: ");
29372941
_OutputStream.writeInteger(stats->totalCount, "%u");
29382942
_OutputStream.writeCharacters("\n");
2939-
_OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time (JVM uptime us): ");
2943+
_OutputStream.writeCharacters("2JITTOTALWAIT Total application wait time: ");
29402944
_OutputStream.writeInteger(stats->totalWaitTime, "%llu");
29412945
_OutputStream.writeCharacters("us\n");
2942-
if (stats->longestWaitTime != 0) {
2943-
_OutputStream.writeCharacters("2JITLONGEST Longest Synchronous Compilation\n");
2946+
for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) {
2947+
if (stats->longestWaitMethods[i].waitTime == 0 || stats->longestWaitMethods[i].method == NULL)
2948+
break;
2949+
_OutputStream.writeCharacters("2JITLONGEST ");
2950+
if (i == 0) {
2951+
_OutputStream.writeCharacters("Longest");
2952+
}
2953+
else if (i == 1) {
2954+
_OutputStream.writeCharacters("2nd Longest");
2955+
}
2956+
else {
2957+
_OutputStream.writeCharacters("3rd Longest");
2958+
}
2959+
_OutputStream.writeCharacters(" Synchronous Compilation\n");
2960+
29442961
_OutputStream.writeCharacters("3JITWAITTIME Wait time: ");
2945-
_OutputStream.writeInteger(stats->longestWaitTime, "%llu");
2962+
_OutputStream.writeInteger(stats->longestWaitMethods[i].waitTime, "%llu");
29462963
_OutputStream.writeCharacters("us\n");
29472964

2948-
_OutputStream.writeCharacters("3JITSTARTTIME Wait time start (JVM uptime us): ");
2949-
_OutputStream.writeInteger64(stats->longestWaitTimeStart, "%llu");
2950-
_OutputStream.writeCharacters("us\n");
2965+
_OutputStream.writeCharacters("3JITENDTIME Wait time end: ");
2966+
omrstr_ftime_ex(timeStamp, _MaximumTimeStampLength, "%Y-%m-%dT%H:%M:%S",
2967+
stats->longestWaitMethods[i].waitTimeEnd, OMRSTR_FTIME_FLAG_LOCAL);
2968+
timeStamp[_MaximumTimeStampLength] = '\0';
2969+
_OutputStream.writeCharacters(timeStamp);
2970+
_OutputStream.writeInteger64(stats->longestWaitMethods[i].waitTimeEnd % 1000, ".%03llu");
2971+
_OutputStream.writeCharacters("\n");
29512972

2952-
_OutputStream.writeCharacters("3JITENDTIME Wait time end (JVM uptime us): ");
2953-
_OutputStream.writeInteger64(stats->longestWaitTimeEnd, "%llu");
2954-
_OutputStream.writeCharacters("us\n");
2973+
_OutputStream.writeCharacters("3JITMETHOD Method: ");
2974+
_OutputStream.writeCharacters(stats->longestWaitMethods[i].method);
2975+
_OutputStream.writeCharacters("\n");
29552976

2956-
if (stats->longestWaitMethod != NULL) {
2957-
_OutputStream.writeCharacters("3JITMETHOD Method: ");
2958-
_OutputStream.writeCharacters(stats->longestWaitMethod);
2977+
if (stats->longestWaitMethods[i].thread != NULL) {
2978+
_OutputStream.writeCharacters("3JITTHREAD Thread: ");
2979+
_OutputStream.writeCharacters(stats->longestWaitMethods[i].thread);
29592980
_OutputStream.writeCharacters("\n");
29602981
}
2961-
29622982
}
29632983

29642984
stats->totalCount = 0;
29652985
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-
}
2986+
for (int i = 0; i < J9_LONGEST_SYNC_COMP; i++) {
2987+
stats->longestWaitMethods[i].waitTime = 0;
2988+
stats->longestWaitMethods[i].waitTimeEnd = 0;
2989+
if (stats->longestWaitMethods[i].method != NULL) {
2990+
j9mem_free_memory(stats->longestWaitMethods[i].method);
2991+
stats->longestWaitMethods[i].method = NULL;
2992+
}
2993+
if (stats->longestWaitMethods[i].thread != NULL) {
2994+
j9mem_free_memory(stats->longestWaitMethods[i].thread);
2995+
stats->longestWaitMethods[i].thread = NULL;
2996+
}
2997+
}
29742998
}
29752999

29763000
#if defined(OMR_OPT_CUDA)

0 commit comments

Comments
 (0)