Move timestamps in ScavengerStats to Collector

Move `_start/_endTime` from `MM_ScavengerStats`
to `MM_Scavenger` and rename to `_cycleStart/End`.

Rename `MM_MemorySubSpaceSemiSpace::_lastScavengeEndTime`
to `_lastGCEndTime`

Rename `MM_ScavengerStats::_workerScavengeStart/EndTime`
to `_start/endTime`

Add `incrementStart/EndTime` to `MM_LocalGCEndEvent`

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

gc/base/MemorySubSpaceSemiSpace.cpp

@@ -26,7 +26,6 @@
 #include "modronopt.h"
 
 #include "AllocateDescription.hpp"
-#include "Collector.hpp"
 #include "EnvironmentBase.hpp"
 #include "GCExtensionsBase.hpp"
 #include "Heap.hpp"
@@ -39,6 +38,7 @@
 #include "MemorySubSpaceSemiSpace.hpp"
 #include "ParallelDispatcher.hpp"
 #include "PhysicalSubArena.hpp"
+#include "Scavenger.hpp"
 
 #if defined(OMR_VALGRIND_MEMCHECK)
 #include "MemcheckWrapper.hpp"
@@ -834,6 +834,7 @@ MM_MemorySubSpaceSemiSpace::checkSubSpaceMemoryPostCollectResize(MM_EnvironmentB
 {
 	MM_GCExtensionsBase *extensions = MM_GCExtensionsBase::getExtensions(env->getOmrVM());
 	uintptr_t regionSize = extensions->getHeap()->getHeapRegionManager()->getRegionSize();
+	MM_Scavenger *scavenger = (MM_Scavenger *)_collector;
 
 	if(extensions->dynamicNewSpaceSizing) {
 		bool doDynamicNewSpaceSizing = true;
@@ -852,23 +853,23 @@ MM_MemorySubSpaceSemiSpace::checkSubSpaceMemoryPostCollectResize(MM_EnvironmentB
 		}
 
 		/* the wall clock might be shifted backwards externally */
-		if (extensions->scavengerStats._startTime < _lastScavengeEndTime) {
+		if (scavenger->_cycleTimes.cycleStart < _lastGCEndTime) {
 			/* clock has been shifted backwards between scavenges */
 			if(debug) {
 				omrtty_printf("\tClock shifted backwards between scavenges - ABORTING\n");
 			}
 			doDynamicNewSpaceSizing = false;
 		}
 
-		if (extensions->scavengerStats._endTime < extensions->scavengerStats._startTime) {
+		if (scavenger->_cycleTimes.cycleEnd < scavenger->_cycleTimes.cycleStart) {
 			/* clock has been shifted backwards at the time of the scavenge */
 			if(debug) {
 				omrtty_printf("\tClock shifted backwards at the time of the scavenge - ABORTING\n");
 			}
 			doDynamicNewSpaceSizing = false;
 		}
 
-		uint64_t intervalTime = omrtime_hires_delta(_lastScavengeEndTime, extensions->scavengerStats._endTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+		uint64_t intervalTime = omrtime_hires_delta(_lastGCEndTime, scavenger->_cycleTimes.cycleEnd, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
 
 		if(0 == intervalTime) {
 			if(debug) {
@@ -877,7 +878,7 @@ MM_MemorySubSpaceSemiSpace::checkSubSpaceMemoryPostCollectResize(MM_EnvironmentB
 			doDynamicNewSpaceSizing = false;
 		}
 
-		uint64_t scavengeTime = omrtime_hires_delta(extensions->scavengerStats._startTime, extensions->scavengerStats._endTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS );
+		uint64_t scavengeTime = omrtime_hires_delta(scavenger->_cycleTimes.cycleStart, scavenger->_cycleTimes.cycleEnd, OMRPORT_TIME_DELTA_IN_MICROSECONDS );
 
 		if(0 == scavengeTime) {
 			if(debug) {
@@ -886,7 +887,7 @@ MM_MemorySubSpaceSemiSpace::checkSubSpaceMemoryPostCollectResize(MM_EnvironmentB
 			doDynamicNewSpaceSizing = false;
 		}
 
-		_lastScavengeEndTime = extensions->scavengerStats._endTime;
+		_lastGCEndTime = scavenger->_cycleTimes.cycleEnd;
 
 		if (doDynamicNewSpaceSizing) {
 			double expectedTimeRatio = (extensions->dnssExpectedTimeRatioMaximum + extensions->dnssExpectedTimeRatioMinimum) / 2;

gc/base/MemorySubSpaceSemiSpace.hpp

@@ -75,7 +75,7 @@ class MM_MemorySubSpaceSemiSpace : public MM_MemorySubSpace
 	uintptr_t _tiltedAverageBytesFlippedDelta;
 
 	double _averageScavengeTimeRatio;
-	uint64_t _lastScavengeEndTime;
+	uint64_t _lastGCEndTime;
 
 	double _desiredSurvivorSpaceRatio;
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)
@@ -187,7 +187,7 @@ class MM_MemorySubSpaceSemiSpace : public MM_MemorySubSpace
 		,_tiltedAverageBytesFlipped(0)
 		,_tiltedAverageBytesFlippedDelta(0)
 		,_averageScavengeTimeRatio(0.0)
-		,_lastScavengeEndTime(0)
+		,_lastGCEndTime(0)
 		,_desiredSurvivorSpaceRatio(0.0)
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)		
 		,_bytesAllocatedDuringConcurrent(0)

gc/base/omrmmprivate.hdf

@@ -162,6 +162,8 @@ SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-excepti
 		<data type="uintptr_t" name="eventid" description="unique identifier for event" />
 		<data type="void*" name="subSpace" description="the subspace which was collected" />
 		<data type="bool" name="cycleEnd" description="true, if last GC increment in a cycle" />
+		<data type="uint64_t" name="incrementStartTime" description="start time of cycle increment" />
+		<data type="uint64_t" name="incrementEndTime" description="end time of cycle increment" />
 	</event>
 
 	<event>

gc/base/standard/Scavenger.cpp

@@ -456,7 +456,7 @@ MM_Scavenger::workerSetupForGC(MM_EnvironmentStandard *env)
 
 	/* This thread just started the scavenge task, record the timestamp.
 	 * This must be done after clearThreadGCStats or else the timestamp will be cleared. */
-	env->_scavengerStats._workerScavengeStartTime = omrtime_hires_clock();
+	env->_scavengerStats._startTime = omrtime_hires_clock();
 
 	/* Clear local language-specific stats */
 	_delegate.workerSetupForGC_clearEnvironmentLangStats(env);
@@ -510,8 +510,8 @@ MM_Scavenger::calculateRecommendedWorkingThreads(MM_EnvironmentStandard *env)
 
 	/* Calculate the average time it takes the worker threads to start collection and avgerage time workers are idle waiting for task cleanup
 	 * Calculated as (Sum_WorkerStartTime(t1 + t2 + ... + tn) - (n * collection_start)) / n  */
-	uint64_t avgTimeToStartCollection =  omrtime_hires_delta((_extensions->scavengerStats._startTime * totalThreads), _extensions->scavengerStats._workerScavengeStartTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS) / totalThreads;
-	uint64_t avgTimeIdleAfterCollection =  omrtime_hires_delta(_extensions->scavengerStats._workerScavengeEndTime, (_extensions->scavengerStats._endTime * totalThreads), OMRPORT_TIME_DELTA_IN_MICROSECONDS) / totalThreads;
+	uint64_t avgTimeToStartCollection =  omrtime_hires_delta((_cycleTimes.cycleStart * totalThreads), _extensions->scavengerStats._startTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS) / totalThreads;
+	uint64_t avgTimeIdleAfterCollection =  omrtime_hires_delta(_extensions->scavengerStats._endTime, (_cycleTimes.cycleEnd * totalThreads), OMRPORT_TIME_DELTA_IN_MICROSECONDS) / totalThreads;
 
 	/* Calculate average stall times */
 	uint64_t avgScanStallTime =  omrtime_hires_delta(0, (_extensions->scavengerStats._workStallTime + _extensions->scavengerStats._completeStallTime), OMRPORT_TIME_DELTA_IN_MICROSECONDS) / totalThreads;
@@ -521,7 +521,7 @@ MM_Scavenger::calculateRecommendedWorkingThreads(MM_EnvironmentStandard *env)
 	Trc_MM_Scavenger_calculateRecommendedWorkingThreads_averageStallBreakDown(env->getLanguageVMThread(), totalThreads, avgTimeToStartCollection, avgTimeIdleAfterCollection, avgScanStallTime, avgSyncStallTime, avgNotifyStallTime);
 
 	uint64_t totalStallTime =  avgTimeToStartCollection + avgTimeIdleAfterCollection + avgScanStallTime + avgSyncStallTime + avgNotifyStallTime;
-	uint64_t scavengeTotalTime = omrtime_hires_delta(_extensions->scavengerStats._startTime, _extensions->scavengerStats._endTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+	uint64_t scavengeTotalTime = omrtime_hires_delta(_cycleTimes.cycleStart, _cycleTimes.cycleEnd, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
 
 	/* This Adaptive Threading Model aims to determine the efficiency of a cycle and predict the optimal GC thread count based on current number of threads,
 	 * directly proportional to busy time and inversely proportional to idle times.
@@ -620,7 +620,9 @@ MM_Scavenger::reportScavengeEnd(MM_EnvironmentStandard *env, bool lastIncrement)
 		omrtime_hires_clock(),
 		J9HOOK_MM_PRIVATE_SCAVENGE_END,
 		env->_cycleState->_activeSubSpace,
-		lastIncrement
+		lastIncrement,
+		_cycleTimes.incrementStart,
+		_cycleTimes.incrementEnd
 	);
 }
 
@@ -729,7 +731,9 @@ MM_Scavenger::reportGCEnd(MM_EnvironmentStandard *env)
 		(_extensions->largeObjectArea ? _extensions->heap->getApproximateActiveFreeLOAMemorySize(MEMORY_TYPE_OLD) : 0),
 		(_extensions->largeObjectArea ? _extensions->heap->getActiveLOAMemorySize(MEMORY_TYPE_OLD) :0),
 		_extensions->incrementScavengerStats._tenureAge,
-		_extensions->heap->getMemorySize()
+		_extensions->heap->getMemorySize(),
+		_cycleTimes.incrementStart,
+		_cycleTimes.incrementEnd
 	);
 }
 
@@ -743,12 +747,18 @@ void
 MM_Scavenger::clearIncrementGCStats(MM_EnvironmentBase *env, bool firstIncrement)
 {
 	_extensions->incrementScavengerStats.clear(firstIncrement);
+
+	/* Increment start time doesn't need to be cleared, it was set prior to calling this method */
+	_cycleTimes.incrementEnd = 0;
 }
 
 void
 MM_Scavenger::clearCycleGCStats(MM_EnvironmentBase *env)
 {
 	_extensions->scavengerStats.clear(true);
+
+	/* Cycle start time doesn't need to be cleared, it was set prior to calling this method */
+	_cycleTimes.cycleEnd = 0;
 }
 
 void
@@ -833,8 +843,8 @@ MM_Scavenger::mergeGCStatsBase(MM_EnvironmentBase *env, MM_ScavengerStats *final
 	_extensions->scavengerStats._syncStallCount += scavStats->_syncStallCount;
 
 	/* Adaptive Threading Stats */
-	finalGCStats->_workerScavengeStartTime += scavStats->_workerScavengeStartTime;
-	finalGCStats->_workerScavengeEndTime += scavStats->_workerScavengeEndTime;
+	finalGCStats->_startTime += scavStats->_startTime;
+	finalGCStats->_endTime += scavStats->_endTime;
 	finalGCStats->_notifyStallTime += scavStats->_notifyStallTime;
 	finalGCStats->_adjustedSyncStallTime += scavStats->_adjustedSyncStallTime;
 }
@@ -852,13 +862,13 @@ MM_Scavenger::mergeThreadGCStats(MM_EnvironmentBase *env)
 
 	/* This thread is just about to complete the scavenge task, record the timestamp.
 	 * This must be done before mergeGCStatsBase or else the timestamp won't be mereged as needed by adaptive threading. */
-	env->_scavengerStats._workerScavengeEndTime = omrtime_hires_clock();
+	env->_scavengerStats._endTime = omrtime_hires_clock();
 	mergeGCStatsBase(env, &_extensions->incrementScavengerStats, scavStats);
 
 	/* Merge language specific statistics. No known interesting data per increment - they are merged directly to aggregate cycle stats */
 	_delegate.mergeGCStats_mergeLangStats(env);
 
-	uint64_t timeToStartCollection =  omrtime_hires_delta(_extensions->scavengerStats._startTime, scavStats->_workerScavengeStartTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
+	uint64_t timeToStartCollection =  omrtime_hires_delta(_cycleTimes.cycleStart, scavStats->_startTime, OMRPORT_TIME_DELTA_IN_MICROSECONDS);
 	uint64_t scanStall =  omrtime_hires_delta(0, (scavStats->_workStallTime + scavStats->_completeStallTime), OMRPORT_TIME_DELTA_IN_MICROSECONDS);
 	uint64_t syncStall = omrtime_hires_delta(0, (scavStats->_adjustedSyncStallTime), OMRPORT_TIME_DELTA_IN_MICROSECONDS);
 	uint64_t notifyStallTime = omrtime_hires_delta(0, (scavStats->_notifyStallTime), OMRPORT_TIME_DELTA_IN_MICROSECONDS);
@@ -4195,14 +4205,14 @@ MM_Scavenger::mainThreadGarbageCollect(MM_EnvironmentBase *envBase, MM_AllocateD
 		}
 
 		reportGCCycleStart(env);
-		_extensions->scavengerStats._startTime = omrtime_hires_clock();
+		_cycleTimes.cycleStart = omrtime_hires_clock();
 		mainSetupForGC(env);
 	}
 	clearIncrementGCStats(env, firstIncrement);
 	reportGCStart(env);
 	reportGCIncrementStart(env);
 	reportScavengeStart(env);
-	_extensions->incrementScavengerStats._startTime = omrtime_hires_clock();
+	_cycleTimes.incrementStart = omrtime_hires_clock();
 
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)
 	if (_extensions->concurrentScavenger) {
@@ -4219,7 +4229,7 @@ MM_Scavenger::mainThreadGarbageCollect(MM_EnvironmentBase *envBase, MM_AllocateD
 	bool lastIncrement = true;
 #endif
 
-	_extensions->incrementScavengerStats._endTime = omrtime_hires_clock();
+	_cycleTimes.incrementEnd = omrtime_hires_clock();
 
 	/* merge stats from this increment/phase to aggregate cycle stats */
 	mergeIncrementGCStats(env, lastIncrement);
@@ -4234,7 +4244,7 @@ MM_Scavenger::mainThreadGarbageCollect(MM_EnvironmentBase *envBase, MM_AllocateD
 		 */
 		_activeSubSpace->setResizable(_cachedSemiSpaceResizableFlag);
 
-		_extensions->scavengerStats._endTime = omrtime_hires_clock();
+		_cycleTimes.cycleEnd = omrtime_hires_clock();
 
 		if(scavengeCompletedSuccessfully(env)) {
 
@@ -5722,14 +5732,16 @@ void MM_Scavenger::preConcurrentInitializeStatsAndReport(MM_EnvironmentBase *env
 			J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_START,
 			stats);
 
-	_extensions->incrementScavengerStats._startTime = omrtime_hires_clock();
+	_cycleTimes.incrementStart = omrtime_hires_clock();
+	stats->_startTime = _cycleTimes.incrementStart;
 }
 
 void MM_Scavenger::postConcurrentUpdateStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentPhaseStatsBase *stats, UDATA bytesConcurrentlyScanned)
 {
 	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
 
-	_extensions->incrementScavengerStats._endTime = omrtime_hires_clock();
+	_cycleTimes.incrementEnd = omrtime_hires_clock();
+	stats->_endTime = _cycleTimes.incrementEnd;
 
 	TRIGGER_J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_END(
 		_extensions->privateHookInterface,

gc/base/standard/Scavenger.hpp

@@ -70,6 +70,15 @@ class MM_Scavenger : public MM_Collector
 	/*
 	 * Data members
 	 */
+public:
+	struct {
+		/* The following start/end times record total cycle and cycle increment durations, done only by main thread. */
+		uint64_t cycleStart;
+		uint64_t cycleEnd;
+		uint64_t incrementStart;
+		uint64_t incrementEnd;
+	} _cycleTimes;
+
 private:
 	MM_ScavengerDelegate _delegate;
 
@@ -899,6 +908,7 @@ class MM_Scavenger : public MM_Collector
 
 	MM_Scavenger(MM_EnvironmentBase *env, MM_HeapRegionManager *regionManager) :
 		MM_Collector()
+		, _cycleTimes()
 		, _delegate(env)
 		, _objectAlignmentInBytes(env->getObjectAlignmentInBytes())
 		, _isRememberedSetInOverflowAtTheBeginning(false)

gc/include/omrmm.hdf

@@ -127,6 +127,8 @@ typedef uintptr_t (*condYieldFromGCFunctionPtr) (OMR_VMThread *omrVMThread, uint
 		<data type="uintptr_t" name="tenureLOATotalBytes" description="total number of bytes in the LOA" />
 		<data type="uintptr_t" name="tenureAge" description="the age at which objects currently get tenured" />
 		<data type="uintptr_t" name="totalMemorySize" description="the total size of all memory spaces" />
+		<data type="uint64_t" name="incrementStartTime" description="start time of increment" />
+		<data type="uint64_t" name="incrementEndTime" description="end time of increment" />
 	</event>
 
 	<event>

gc/stats/ConcurrentMarkPhaseStats.hpp

@@ -40,8 +40,6 @@ class MM_ConcurrentMarkPhaseStats : public MM_ConcurrentPhaseStatsBase
 private:
 protected:
 public:
-	uint64_t _startTime;
-	uint64_t _endTime;
 	MM_ConcurrentCardTableStats *_cardTableStats;
 	MM_ConcurrentGCStats *_collectionStats;
 
@@ -51,16 +49,12 @@ class MM_ConcurrentMarkPhaseStats : public MM_ConcurrentPhaseStatsBase
 public:
 	virtual void clear() {
 		MM_ConcurrentPhaseStatsBase::clear();
-		_startTime = 0;
-		_endTime = 0;
 		_cardTableStats = NULL;
 		_collectionStats = NULL;
 	}
 
 	MM_ConcurrentMarkPhaseStats()
 		: MM_ConcurrentPhaseStatsBase(OMR_GC_CYCLE_TYPE_GLOBAL)
-		, _startTime(0)
-		, _endTime(0)
 		, _cardTableStats(NULL)
 		, _collectionStats(NULL)
 		{}

gc/stats/ConcurrentPhaseStatsBase.hpp

@@ -42,6 +42,8 @@ class MM_ConcurrentPhaseStatsBase : public MM_Base
 private:
 protected:
 public:
+	uint64_t _startTime;
+	uint64_t _endTime;
 	uintptr_t _cycleID;	/**< The "_id" of the corresponding cycle */
 	uintptr_t _scanTargetInBytes;	/**< The number of bytes a given concurrent task was expected to scan before terminating */
 	uintptr_t _bytesScanned;	/**< The number of bytes a given concurrent task did scan before it terminated (can be lower than _scanTargetInBytes if the termination was asynchronously requested) */
@@ -53,7 +55,6 @@ class MM_ConcurrentPhaseStatsBase : public MM_Base
 		terminationRequest_External
 	};
 	TerminationRequestType _terminationRequestType; /**< Reason for concurrent task termination, asynchronous external event or itself GC (work or survivor space exhausted etc). */
-
 	/* Member Functions */
 private:
 protected:
@@ -67,6 +68,8 @@ class MM_ConcurrentPhaseStatsBase : public MM_Base
 	}
 
 	virtual void clear() {
+		_startTime = 0;
+		_endTime = 0;
 		_cycleID = 0;
 		_scanTargetInBytes = 0;
 		_bytesScanned = 0;
@@ -76,6 +79,8 @@ class MM_ConcurrentPhaseStatsBase : public MM_Base
 
 	MM_ConcurrentPhaseStatsBase(uintptr_t concurrentCycleType = OMR_GC_CYCLE_TYPE_DEFAULT)
 		: MM_Base()
+		, _startTime(0)
+		, _endTime(0)
 		, _cycleID(0)
 		, _scanTargetInBytes(0)
 		, _bytesScanned(0)

gc/stats/ScavengerStats.cpp

@@ -44,8 +44,6 @@ MM_ScavengerStats::MM_ScavengerStats()
 	,_failedFlipCount(0)
 	,_failedFlipBytes(0)
 	,_tenureAge(0)
-	,_startTime(0)
-	,_endTime(0)
 #if defined(J9MODRON_TGC_PARALLEL_STATISTICS)
 	,_releaseScanListCount(0)
 	,_acquireFreeListCount(0)
@@ -66,8 +64,8 @@ MM_ScavengerStats::MM_ScavengerStats()
 	,_depthDeepestStructure(0)
 	,_copyScanUpdates(0)
 #endif /* J9MODRON_TGC_PARALLEL_STATISTICS */
-	,_workerScavengeStartTime(0)
-	,_workerScavengeEndTime(0)
+	,_startTime(0)
+	,_endTime(0)
 	,_notifyStallTime(0)
 	,_adjustedSyncStallTime(0)
 	,_avgInitialFree(0)
@@ -201,8 +199,8 @@ MM_ScavengerStats::clear(bool firstIncrement)
 
 	_adjustedSyncStallTime = 0;
 	_notifyStallTime = 0;
-	_workerScavengeEndTime = 0;
-	_workerScavengeStartTime = 0;
+	_startTime = 0;
+	_endTime = 0;
 
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)
 	_readObjectBarrierCopy = 0;

gc/stats/ScavengerStats.hpp

@@ -75,9 +75,6 @@ class MM_ScavengerStats
 	uintptr_t _failedFlipCount;
 	uintptr_t _failedFlipBytes;
 	uintptr_t _tenureAge;
-	/* The following start/end times are not used as thread local, but to record total cycle duration, done only by main thread. Ideally, these should be moved to the collector. */
-	uint64_t _startTime;
-	uint64_t _endTime;
 #if defined(J9MODRON_TGC_PARALLEL_STATISTICS)
 	uintptr_t _releaseScanListCount;
 	uintptr_t _acquireFreeListCount;
@@ -100,8 +97,8 @@ class MM_ScavengerStats
 #endif /* J9MODRON_TGC_PARALLEL_STATISTICS */
 
 	/* Stats Used Specifically for Adaptive Threading */
-	uint64_t _workerScavengeStartTime; /**< Timestamp taken when worker starts the scavenge task */
-	uint64_t _workerScavengeEndTime; /**< Timestamp taken when worker completes the scavenge task */
+	uint64_t _startTime; /**< Timestamp taken when worker starts the scavenge task */
+	uint64_t _endTime; /**< Timestamp taken when worker completes the scavenge task */
 
 	/* The time, in hi-res ticks, the thread spent stalled notifying other
 	 * threads during scavenge. Note: this is not all inclusive, it records notify