Adding stalltimems in gc-end stanza

- Attribute `stalltimems` is added to `gc-end` to report time spent in stalling (in ms).
- New API `getStallTime()` introduced for `MM_GlobalGCStats`
- Expanded `MM_CollectionStatistics` to `_stallTime`
- New attribute is added in `gc-end` in schema.
- Update `MM_VerboseHandlerOutput::getTagTemplateWithDuration()` to reflect the addition of `stalltimems`

Signed-off-by: Enson Guo <enson.guo@ibm.com>

gc/base/standard/ParallelGlobalGC.cpp

@@ -1667,7 +1667,7 @@ MM_ParallelGlobalGC::reportGCIncrementEnd(MM_EnvironmentBase *env)
 	}
 
 	stats->_endTime = omrtime_hires_clock();
-
+	stats->_stallTime = _extensions->globalGCStats.getStallTime();
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_END(
 		_extensions->privateHookInterface,
 		env->getOmrVMThread(),

gc/base/standard/Scavenger.cpp

@@ -4757,6 +4757,7 @@ MM_Scavenger::reportGCIncrementEnd(MM_EnvironmentStandard *env)
 	}
 
 	stats->_endTime = omrtime_hires_clock();
+	stats->_stallTime = _extensions->scavengerStats.getStallTime();
 
 	TRIGGER_J9HOOK_MM_PRIVATE_GC_INCREMENT_END(
 		_extensions->privateHookInterface,

gc/stats/CollectionStatistics.hpp

@@ -42,6 +42,7 @@ class MM_CollectionStatistics : public MM_Base
 
 	uint64_t  _startTime;		/**< Collection start time */
 	uint64_t  _endTime;			/**< Collection end time */
+	uint64_t  _stallTime;		/**< Collection stall time */
 
 	omrthread_process_time_t _startProcessTimes; /**< Process (Kernel and User) start time(s) */
 	omrthread_process_time_t _endProcessTimes;   /**< Process (Kernel and User) end time(s) */
@@ -58,6 +59,7 @@ class MM_CollectionStatistics : public MM_Base
 		,_totalFreeHeapSize(0)
 		,_startTime(0)
 		,_endTime(0)
+		,_stallTime(0)
 		,_startProcessTimes()
 		,_endProcessTimes()
 	{};

gc/stats/GlobalGCStats.hpp

@@ -77,6 +77,16 @@ class MM_GlobalGCStats {
 		finalizableCount = 0;
 	};
 
+	/**
+	 * Get the total stall time
+	 * @return the time in hi-res ticks
+	 */
+	MMINLINE uint64_t 
+	getStallTime()
+	{
+		return markStats.getStallTime() + workPacketStats.getStallTime() + sweepStats.idleTime;
+	}
+
 	MM_GlobalGCStats()
 		: gcCount(0)
 		, workPacketStats()

gc/verbose/VerboseHandlerOutput.cpp

@@ -204,12 +204,12 @@ MM_VerboseHandlerOutput::getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t
 }
 
 uintptr_t
-MM_VerboseHandlerOutput::getTagTemplateWithDuration(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t durationus, uint64_t usertimeus, uint64_t cputimeus, uint64_t wallTimeMs)
+MM_VerboseHandlerOutput::getTagTemplateWithDuration(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t durationus, uint64_t usertimeus, uint64_t cputimeus, uint64_t wallTimeMs, uint64_t stalltimeus)
 {
 	OMRPORT_ACCESS_FROM_OMRVM(_omrVM);
 	uintptr_t bufPos = 0;
-	bufPos += omrstr_printf(buf, bufsize, "id=\"%zu\" type=\"%s\" contextid=\"%zu\" durationms=\"%llu.%03.3llu\" usertimems=\"%llu.%03.3llu\" systemtimems=\"%llu.%03.3llu\" timestamp=\"",
- 			id, type, contextId, durationus / 1000, durationus % 1000, usertimeus / 1000, usertimeus % 1000, cputimeus / 1000, cputimeus % 1000);
+	bufPos += omrstr_printf(buf, bufsize, "id=\"%zu\" type=\"%s\" contextid=\"%zu\" durationms=\"%llu.%03.3llu\" usertimems=\"%llu.%03.3llu\" systemtimems=\"%llu.%03.3llu\" stalltimems=\"%llu.%03.3llu\" timestamp=\"",
+ 			id, type, contextId, durationus / 1000, durationus % 1000, usertimeus / 1000, usertimeus % 1000, cputimeus / 1000, cputimeus % 1000, stalltimeus / 1000, stalltimeus % 1000);
 	bufPos += omrstr_ftime(buf + bufPos, bufsize - bufPos, VERBOSEGC_DATE_FORMAT_PRE_MS, wallTimeMs);
 	bufPos += omrstr_printf(buf + bufPos, bufsize - bufPos, "%03llu", wallTimeMs % 1000);
 	bufPos += omrstr_ftime(buf + bufPos, bufsize - bufPos, VERBOSEGC_DATE_FORMAT_POST_MS, wallTimeMs);
@@ -834,6 +834,7 @@ MM_VerboseHandlerOutput::handleGCEnd(J9HookInterface** hook, uintptr_t eventNum,
 	uint64_t durationInMicroseconds   = 0;
 	uint64_t userTimeInMicroseconds   = 0;
 	uint64_t systemTimeInMicroseconds = 0;
+	uint64_t stallTimeInMicroseconds  = 0;
 
 	/* convert from nanoseconds to microseconds, compiler should autocast lvalue (int64_t) to rvalue (uint64_t) but just incase */
 	uint64_t startUserTime   =	(uint64_t)stats->_startProcessTimes._userTime   / 1000;
@@ -845,16 +846,18 @@ MM_VerboseHandlerOutput::handleGCEnd(J9HookInterface** hook, uintptr_t eventNum,
 	bool getDurationTimeSuccessful = getTimeDeltaInMicroSeconds(&durationInMicroseconds, stats->_startTime, stats->_endTime);
 	bool getUserTimeSuccessful = getTimeDelta(&userTimeInMicroseconds, startUserTime, endUserTime);
 	bool getSystemTimeSuccessful = getTimeDelta(&systemTimeInMicroseconds, startSystemTime, endSystemTime);
+	bool getStallTimeSuccessful = getTimeDeltaInMicroSeconds(&stallTimeInMicroseconds, 0, stats->_stallTime);
+
 	char tagTemplate[200];
 	getTagTemplateWithDuration(	tagTemplate, sizeof(tagTemplate), _manager->getIdAndIncrement(),
 								getCurrentCycleType(env), env->_cycleState->_verboseContextID,
 								durationInMicroseconds, userTimeInMicroseconds, systemTimeInMicroseconds,
-								omrtime_current_time_millis());
+								omrtime_current_time_millis(), stallTimeInMicroseconds);
 
 	uintptr_t activeThreads = env->getExtensions()->dispatcher->activeThreadCount();
 
 	enterAtomicReportingBlock();
-	if (!getDurationTimeSuccessful || !getUserTimeSuccessful || !getSystemTimeSuccessful) {
+	if (!getDurationTimeSuccessful || !getUserTimeSuccessful || !getSystemTimeSuccessful || !getStallTimeSuccessful) {
 		writer->formatAndOutput(env, 0, "<warning details=\"clock error detected, following timing may be inaccurate\" />");
 	}
 	writer->formatAndOutput(env, 0, "<gc-end %s activeThreads=\"%zu\">", tagTemplate, activeThreads);

gc/verbose/VerboseHandlerOutput.hpp

@@ -346,7 +346,7 @@ class MM_VerboseHandlerOutput : public MM_Base
 	 *
 	 * @note should be moved to protected once all standard usage is converted.
 	 */
-	uintptr_t getTagTemplateWithDuration(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t durationus, uint64_t usertimeus, uint64_t cputimeus, uint64_t wallTimeMs);
+	uintptr_t getTagTemplateWithDuration(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t durationus, uint64_t usertimeus, uint64_t cputimeus, uint64_t wallTimeMs, uint64_t stalltimeus);
 
 	/**
 	 * Handle any output or data tracking for the initialized phase of verbose GC.

gc/verbose/schema.xsd

@@ -380,6 +380,7 @@ xmlns:vgc="http://www.ibm.com/j9/verbosegc">
 		<attribute name="durationms" type="float" use="required" />
 		<attribute name="usertimems" type="float" use="required" />
 		<attribute name="systemtimems" type="float" use="required" />
+		<attribute name="stalltimems" type="float" use="required" />
 		<attribute name="timestamp" type="dateTime" use="required" />
 		<attribute name="activeThreads" type="integer" use="required" />
 	</complexType>