VGC improvements for CS

Verbose GC improvements for Concurrent Scavenger. Now reporting gc-op
for each of 3 phases of CS (2xSTW and one concurrent). Also introducing
a wrapper stanza (concurrent-end) for concurrent scavenge gc-op:

    <concurrent-end id="12169" type="scavenge" contextid="12159"
timestamp="2017-08-18T14:28:44.329">
    <gc-op id="12170" type="scavenge" timems="19.722" contextid="12159"
timestamp="2017-08-18T14:28:44.329">
    <memory-copied type="nursery" objects="9888" bytes="450472"
bytesdiscarded="7816" />
    <memory-copied type="tenure" objects="64" bytes="2256"
bytesdiscarded="4112" />
    </gc-op>
    </concurrent-end>


In future, this wrapper may report some concurrent specific data of
scavenge (that gc-op does not report), like read barrier counts.


Signed-off-by: Aleksandar Micic <amicic@ca.ibm.com>

Author: amicic

gc/base/Collector.hpp

@@ -30,7 +30,7 @@
 class MM_AllocateDescription;
 class MM_AllocationContext;
 class MM_CollectorLanguageInterface;
-class MM_ConcurrentGMPStats;
+class MM_ConcurrentPhaseStatsBase;
 class MM_MemoryPool;
 class MM_ObjectAllocationInterface;
 class MM_MemorySubSpace;
@@ -275,11 +275,15 @@ class MM_Collector : public MM_BaseVirtual
 	virtual void preMasterGCThreadInitialize(MM_EnvironmentBase *env) {}
 	virtual	void masterThreadGarbageCollect(MM_EnvironmentBase *env, MM_AllocateDescription *allocDescription, bool initMarkMap = false, bool rebuildMarkBits = false) {}
 	virtual bool isConcurrentWorkAvailable(MM_EnvironmentBase *env) { return false; }
-	virtual	void preConcurrentInitializeStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentGMPStats *stats) {}
+	virtual	void preConcurrentInitializeStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentPhaseStatsBase *stats) {}
 	virtual uintptr_t masterThreadConcurrentCollect(MM_EnvironmentBase *env) { return 0; }
-	virtual	void postConcurrentUpdateStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentGMPStats *stats, UDATA bytesConcurrentlyScanned) {}
+	virtual	void postConcurrentUpdateStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentPhaseStatsBase *stats, UDATA bytesConcurrentlyScanned) {}
 	virtual void forceConcurrentFinish() {}
 	virtual void completeExternalConcurrentCycle(MM_EnvironmentBase *env) {}
+	/**
+	 * @return pointer to collector/phase specific concurrent stats structure
+	 */
+	virtual MM_ConcurrentPhaseStatsBase *getConcurrentPhaseStats() { return NULL; }
 
 	MM_Collector(MM_CollectorLanguageInterface *cli)
 		: MM_BaseVirtual()

gc/base/MasterGCThread.cpp

@@ -181,6 +181,8 @@ MM_MasterGCThread::masterThreadEntryPoint()
 
 		_collector->preMasterGCThreadInitialize(env);
 
+		MM_ConcurrentPhaseStatsBase *stats = _collector->getConcurrentPhaseStats();
+
 		/* first, notify the thread that started us that we are ready to enter the waiting state */
 		_masterThreadState = STATE_WAITING;
 		_masterGCThread = omrthread_self();
@@ -222,13 +224,12 @@ MM_MasterGCThread::masterThreadEntryPoint()
 				if (_collector->isConcurrentWorkAvailable(env)) {
 					_masterThreadState = STATE_RUNNING_CONCURRENT;
 					// todo: remove this VLHGC specific structure
-					MM_ConcurrentGMPStats stats;
-					_collector->preConcurrentInitializeStatsAndReport(env, &stats);
+					_collector->preConcurrentInitializeStatsAndReport(env, stats);
 					/* ensure that we get out of this monitor so that the mutator can wake up */
 					omrthread_monitor_exit(_collectorControlMutex);
 					uintptr_t bytesConcurrentlyScanned = _collector->masterThreadConcurrentCollect(env);
 					omrthread_monitor_enter(_collectorControlMutex);
-					_collector->postConcurrentUpdateStatsAndReport(env, &stats, bytesConcurrentlyScanned);
+					_collector->postConcurrentUpdateStatsAndReport(env, stats, bytesConcurrentlyScanned);
 					if (STATE_RUNNING_CONCURRENT == _masterThreadState) {
 						/* we are still in the concurrent state (might have changed if a GC was requested) so set it back to waiting */
 						_masterThreadState = STATE_WAITING;

gc/base/omrmmprivate.hdf

@@ -156,6 +156,7 @@
 		<data type="uint64_t" name="timestamp" description="time of event" />
 		<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" />
 	</event>
 
 	<event>
@@ -974,29 +975,29 @@
 	</event>
 
 	<event>
-		<name>J9HOOK_MM_PRIVATE_CONCURRENT_GMP_START</name>
+		<name>J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_START</name>
 		<description>
-			Triggered when concurrent GMP work begins.
+			Triggered when concurrent phase work begins.
 			NOTE:  Only expected to be used by verbose GC output.
 		</description>
-		<struct>MM_ConcurrentGMPStartEvent</struct>
+		<struct>MM_ConcurrentPhaseStartEvent</struct>
 		<data type="struct OMR_VMThread*" name="currentThread" description="current thread" />
 		<data type="uint64_t" name="timestamp" description="time of event" />
 		<data type="uintptr_t" name="eventid" description="unique identifier for event" />
-		<data type="void *" name="concurrentGMPStats" description="internal statistics for concurrent GMP" /> 
+		<data type="void *" name="concurrentStats" description="internal statistics for concurrent phase" /> 
 	</event>
 
-	<event>
-		<name>J9HOOK_MM_PRIVATE_CONCURRENT_GMP_END</name>
+		<event>
+		<name>J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_END</name>
 		<description>
-			Triggered when concurrent GMP work ends.
+			Triggered when concurrent phase work ends.
 			NOTE:  Only expected to be used by verbose GC output.
 		</description>
-		<struct>MM_ConcurrentGMPEndEvent</struct>
+		<struct>MM_ConcurrentPhaseEndEvent</struct>
 		<data type="struct OMR_VMThread*" name="currentThread" description="current thread" />
 		<data type="uint64_t" name="timestamp" description="time of event" />
 		<data type="uintptr_t" name="eventid" description="unique identifier for event" />
-		<data type="void *" name="concurrentGMPStats" description="internal statistics for concurrent GMP" /> 
+		<data type="void *" name="concurrentStats" description="internal statistics for concurrent phase" />
 	</event>
 
 	<event>

gc/base/standard/Scavenger.cpp

@@ -407,7 +407,7 @@ void
 MM_Scavenger::workerSetupForGC(MM_EnvironmentStandard *env)
 {
 	/* Clear local stats */
-	memset((void *)&(env->_scavengerStats), 0, sizeof(MM_ScavengerStats));
+	env->_scavengerStats.clear();
 
 	/* Clear the worker hot field statistics */
 	clearHotFieldStats(env);
@@ -469,7 +469,7 @@ MM_Scavenger::reportScavengeStart(MM_EnvironmentStandard *env)
 }
 
 void
-MM_Scavenger::reportScavengeEnd(MM_EnvironmentStandard *env)
+MM_Scavenger::reportScavengeEnd(MM_EnvironmentStandard *env, bool lastIncrement)
 {
 	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
 
@@ -485,7 +485,8 @@ MM_Scavenger::reportScavengeEnd(MM_EnvironmentStandard *env)
 		env->getOmrVMThread(),
 		omrtime_hires_clock(),
 		J9HOOK_MM_PRIVATE_SCAVENGE_END,
-		env->_cycleState->_activeSubSpace
+		env->_cycleState->_activeSubSpace,
+		lastIncrement
 	);
 }
 
@@ -647,7 +648,7 @@ MM_Scavenger::mergeHotFieldStats(MM_EnvironmentStandard *env)
  * Clear any global stats associated to the scavenger.
  */
 void
-MM_Scavenger::clearGCStats(MM_EnvironmentStandard *env)
+MM_Scavenger::clearGCStats(MM_EnvironmentBase *env)
 {
 	_extensions->scavengerStats.clear();
 }
@@ -656,7 +657,7 @@ MM_Scavenger::clearGCStats(MM_EnvironmentStandard *env)
  * Merge the current threads scavenge stats into the global scavenge stats.
  */
 void
-MM_Scavenger::mergeGCStats(MM_EnvironmentStandard *env)
+MM_Scavenger::mergeGCStats(MM_EnvironmentBase *env)
 {
 	OMRPORT_ACCESS_FROM_OMRVM(_omrVM);
 
@@ -3477,19 +3478,12 @@ MM_Scavenger::masterThreadGarbageCollect(MM_EnvironmentBase *envBase, MM_Allocat
 		}
 
 		reportGCCycleStart(env);
+		masterSetupForGC(env);
 	}
 	reportGCStart(env);
 	reportGCIncrementStart(env);
-#if defined(OMR_GC_CONCURRENT_SCAVENGER)
-	if (!isConcurrentInProgress())
-#endif
-	{
-		reportScavengeStart(env);
-
-		_extensions->scavengerStats._startTime = omrtime_hires_clock();
-
-		masterSetupForGC(env);
-	}
+	reportScavengeStart(env);
+	_extensions->scavengerStats._startTime = omrtime_hires_clock();
 
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)
 	if (_extensions->concurrentScavenger) {
@@ -3500,18 +3494,18 @@ MM_Scavenger::masterThreadGarbageCollect(MM_EnvironmentBase *envBase, MM_Allocat
 		scavenge(env);
 	}
 
+	_extensions->scavengerStats._endTime = omrtime_hires_clock();
 #if defined(OMR_GC_CONCURRENT_SCAVENGER)
-	if (!isConcurrentInProgress())
+	if (isConcurrentInProgress()) {
+		reportScavengeEnd(env, false);
+	} else
 #endif
 	{
+		reportScavengeEnd(env, true);
+
 		/* defer to collector language interface */
 		_cli->scavenger_masterThreadGarbageCollect_scavengeComplete(env);
 
-		/* Record the completion time of the scavenge */
-		_extensions->scavengerStats._endTime = omrtime_hires_clock();
-
-		reportScavengeEnd(env);
-
 		/* Reset the resizable flag of the semi space.
 		 * NOTE: Must be done before we attempt to resize the new space.
 		 */
@@ -3786,19 +3780,28 @@ MM_Scavenger::getCollectorExpandSize(MM_EnvironmentBase *env)
 void
 MM_Scavenger::internalPreCollect(MM_EnvironmentBase *env, MM_MemorySubSpace *subSpace, MM_AllocateDescription *allocDescription, uint32_t gcCode)
 {
-	_cycleState = MM_CycleState();
 	env->_cycleState = &_cycleState;
-	env->_cycleState->_gcCode = MM_GCCode(gcCode);
-	env->_cycleState->_type = _cycleType;
-	env->_cycleState->_collectionStatistics = &_collectionStatistics;
 
-	/* If we are in an excessiveGC level beyond normal then an aggressive GC is
-	 * conducted to free up as much space as possible
+#if defined(OMR_GC_CONCURRENT_SCAVENGER)
+	/* Cycle state is initialized only once at the beginning of a cycle. We do not want, in mid-end cycle phases, to reset some members
+	 * that are initialized at the beginning (such as verboseContextID).
 	 */
-	if (!env->_cycleState->_gcCode.isExplicitGC()) {
-		if(excessive_gc_normal != _extensions->excessiveGCLevel) {
-			/* convert the current mode to excessive GC mode */
-			env->_cycleState->_gcCode = MM_GCCode(J9MMCONSTANT_IMPLICIT_GC_EXCESSIVE);
+	if (!isConcurrentInProgress())
+#endif
+	{
+		_cycleState = MM_CycleState();
+		_cycleState._gcCode = MM_GCCode(gcCode);
+		_cycleState._type = _cycleType;
+		_cycleState._collectionStatistics = &_collectionStatistics;
+
+		/* If we are in an excessiveGC level beyond normal then an aggressive GC is
+		 * conducted to free up as much space as possible
+		 */
+		if (!_cycleState._gcCode.isExplicitGC()) {
+			if(excessive_gc_normal != _extensions->excessiveGCLevel) {
+				/* convert the current mode to excessive GC mode */
+				_cycleState._gcCode = MM_GCCode(J9MMCONSTANT_IMPLICIT_GC_EXCESSIVE);
+			}
 		}
 	}
 
@@ -3814,7 +3817,7 @@ MM_Scavenger::internalPostCollect(MM_EnvironmentBase *env, MM_MemorySubSpace *su
 {
 	calcGCStats((MM_EnvironmentStandard*)env);
 
-	return ;
+	Assert_MM_true(env->_cycleState == &_cycleState);
 }
 
 /**
@@ -4535,6 +4538,8 @@ MM_Scavenger::scavengeComplete(MM_EnvironmentBase *envBase)
 
 	Assert_MM_true(concurrent_state_complete == _concurrentState);
 
+	clearGCStats(env);
+
 	GC_OMRVMThreadListIterator threadIterator(_extensions->getOmrVM());
 	OMR_VMThread *walkThread = NULL;
 
@@ -4597,7 +4602,7 @@ MM_Scavenger::scavengeIncremental(MM_EnvironmentBase *env)
 		case concurrent_state_scan:
 		{
 			/* This is just for corner cases that must be run in STW mode.
-			 * Default main scan phase is done by scavengeConcurrent. */
+			 * Default main scan phase is done within masterThreadConcurrentCollect. */
 
 			timeout = scavengeScan(env);
 
@@ -4639,24 +4644,34 @@ MM_Scavenger::workThreadProcessRoots(MM_EnvironmentStandard *env)
 	rootScanner.scavengeRememberedSet(env);
 
 	rootScanner.scanRoots(env);
+
+	mergeGCStats(env);
 }
 
 void
 MM_Scavenger::workThreadScan(MM_EnvironmentStandard *env)
 {
+	/* Clear thread local stats */
+	env->_scavengerStats.clear();
+
 	completeScan(env);
 	// todo: are these two steps really necessary?
 	// we probably have to clear all things for master since it'll be doing final release/clear on behalf of mutator threads
 	// but is it really needed for slaves as well?
 	addCopyCachesToFreeList(env);
 	abandonTLHRemainders(env);
+
+	mergeGCStats(env);
 }
 
 void
 MM_Scavenger::workThreadComplete(MM_EnvironmentStandard *env)
 {
 	Assert_MM_true(_extensions->concurrentScavenger);
 
+	/* Clear thread local stats */
+	env->_scavengerStats.clear();
+
 	MM_ScavengerRootScanner rootScanner(env, this);
 
 	/* Complete scan loop regardless if we already aborted. If so, the scan operation will just fix up pointers that still point to forwarded objects.
@@ -4703,46 +4718,62 @@ MM_Scavenger::workThreadComplete(MM_EnvironmentStandard *env)
 }
 
 uintptr_t
-MM_Scavenger::scavengeConcurrent(MM_EnvironmentBase *env, UDATA totalBytesToScavenge, volatile bool *forceExit)
+MM_Scavenger::masterThreadConcurrentCollect(MM_EnvironmentBase *env)
 {
 	Assert_MM_true(concurrent_state_scan == _concurrentState);
 
-	MM_ConcurrentScavengeTask scavengeTask(env, _dispatcher, this, MM_ConcurrentScavengeTask::SCAVENGE_SCAN, totalBytesToScavenge, forceExit, env->_cycleState);
+	clearGCStats(env);
+
+	MM_ConcurrentScavengeTask scavengeTask(env, _dispatcher, this, MM_ConcurrentScavengeTask::SCAVENGE_SCAN, UDATA_MAX, &_forceConcurrentTermination, env->_cycleState);
 	/* Concurrent background task will run with different (typically lower) number of threads. */
 	_dispatcher->run(env, &scavengeTask, _extensions->concurrentScavengerBackgroundThreads);
 
-	uintptr_t bytesScanned = scavengeTask.getBytesScanned();
 	/* we can't assert the work queue is empty. some mutator threads could have just flushed their copy caches, after the task terminated */
 	_concurrentState = concurrent_state_complete;
 	/* make allocate space non-allocatable to trigger the final GC phase */
 	_activeSubSpace->flip(env, MM_MemorySubSpaceSemiSpace::disable_allocation);
 
-	return bytesScanned;
+	/* return the number of bytes scanned since the caller needs to pass it into postConcurrentUpdateStatsAndReport for stats reporting */
+	return scavengeTask.getBytesScanned();
 }
 
-uintptr_t
-MM_Scavenger::masterThreadConcurrentCollect(MM_EnvironmentBase *env)
+void MM_Scavenger::preConcurrentInitializeStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentPhaseStatsBase *stats)
 {
-	/* note that we can't check isConcurrentWorkAvailable at this point since another thread could have set _forceConcurrentTermination since the
-	 * master thread calls this outside of the control monitor
-	 */
+	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
 	Assert_MM_true(NULL == env->_cycleState);
-	Assert_MM_true(concurrent_state_scan == _concurrentState);
-
 	env->_cycleState = &_cycleState;
 
-	/* We pass a pointer to _forceConcurrentTermination so that we can cause the concurrent to terminate early by setting the
-	 * flag to true if we want to interrupt it so that the master thread returns to the control mutex in order to receive a
-	 * new GC request.
-	 */
-	uintptr_t bytesConcurrentlyScanned = scavengeConcurrent(env, 100000, &_forceConcurrentTermination);
+	stats->_cycleID = _cycleState._verboseContextID;
 
-	env->_cycleState = NULL;
+	TRIGGER_J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_START(
+			_extensions->privateHookInterface,
+			env->getOmrVMThread(),
+			omrtime_hires_clock(),
+			J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_START,
+			stats);
 
-	/* return the number of bytes scanned since the caller needs to pass it into postConcurrentUpdateStatsAndReport for stats reporting */
-	return bytesConcurrentlyScanned;
+	_extensions->scavengerStats._startTime = omrtime_hires_clock();
 }
 
+void MM_Scavenger::postConcurrentUpdateStatsAndReport(MM_EnvironmentBase *env, MM_ConcurrentPhaseStatsBase *stats, UDATA bytesConcurrentlyScanned)
+{
+	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
+
+	stats->_terminationWasRequested = _forceConcurrentTermination;
+
+	_extensions->scavengerStats._endTime = omrtime_hires_clock();
+
+	TRIGGER_J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_END(
+		_extensions->privateHookInterface,
+		env->getOmrVMThread(),
+		omrtime_hires_clock(),
+		J9HOOK_MM_PRIVATE_CONCURRENT_PHASE_END,
+		stats);
+
+	env->_cycleState = NULL;
+}
+
+
 void
 MM_Scavenger::switchConcurrentForThread(MM_EnvironmentBase *env)
 {