Merge pull request #5736 from gza060625/concurrent-mark-end

Convert `concurrent-mark-end` to `gc-op` in GMP concurrent increment

gc/verbose/VerboseHandlerOutput.cpp

@@ -188,6 +188,19 @@ MM_VerboseHandlerOutput::getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t
 	return bufPos;
 }
 
+uintptr_t
+MM_VerboseHandlerOutput::getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t wallTimeMs, const char *reasonForTermination)
+{
+	OMRPORT_ACCESS_FROM_OMRVM(_omrVM);
+	uintptr_t bufPos = getTagTemplate(buf, bufsize, id, type, contextId, wallTimeMs);
+
+	if (NULL != reasonForTermination){
+		bufPos += omrstr_printf(buf + bufPos, bufsize - bufPos, " terminationReason=\"%s\"", reasonForTermination);
+	}
+
+	return bufPos;
+}
+
 uintptr_t
 MM_VerboseHandlerOutput::getTagTemplateWithOldType(char *buf, uintptr_t bufsize, uintptr_t id, const char *oldType, const char *newType, uintptr_t contextId, uint64_t wallTimeMs)
 {
@@ -231,6 +244,27 @@ MM_VerboseHandlerOutput::getTagTemplateWithDuration(char *buf, uintptr_t bufsize
 	return bufPos;
 }
 
+const char *
+MM_VerboseHandlerOutput::getConcurrentTerminationReason(MM_ConcurrentPhaseStatsBase *stats)
+{
+	const char *reasonForTermination = NULL;
+	if (stats->isTerminationRequested()) {
+		if (stats->isTerminationRequestExternal()) {
+			/* For example, Java JVMTI and similar. Unfortunately, we could not tell what. */
+			reasonForTermination = "termination requested externally";
+		} else {
+			/* Most interesting reason would be exhausted allocate/survivor, since it could mean that
+			 * tilting is too aggressive (and survival rate is jittery), and suggest tilt tuning/limiting.
+			 * There could be various other reasons, like STW global GC (system, end of concurrent mark etc.),
+			 * or even notorious 'exclusive VM access to satisfy allocate'.
+			 * Either way, the more detailed reason could be deduced from verbose GC.
+			 */
+			reasonForTermination = "termination requested by GC";
+		}
+	}
+	return reasonForTermination;
+}
+
 void
 MM_VerboseHandlerOutput::outputInitializedStanza(MM_EnvironmentBase *env, MM_VerboseBuffer *buffer)
 {
@@ -903,33 +937,6 @@ MM_VerboseHandlerOutput::handleConcurrentStart(J9HookInterface** hook, UDATA eve
 	exitAtomicReportingBlock();
 }
 
-
-void
-MM_VerboseHandlerOutput::handleConcurrentEndInternal(J9HookInterface** hook, UDATA eventNum, void* eventData)
-{
-	MM_ConcurrentPhaseEndEvent *event = (MM_ConcurrentPhaseEndEvent *)eventData;
-	MM_ConcurrentPhaseStatsBase *stats = (MM_ConcurrentPhaseStatsBase *)event->concurrentStats;
-	MM_VerboseWriterChain* writer = _manager->getWriterChain();
-	MM_EnvironmentBase *env = MM_EnvironmentBase::getEnvironment(event->currentThread);
-
-	const char *reasonForTermination = NULL;
-	if (stats->isTerminationRequested()) {
-		if (stats->isTerminationRequestExternal()) {
-			/* For example, Java JVMTI and similar. Unfortunately, we could not tell what. */
-			reasonForTermination = "termination requested externally";
-		} else {
-			/* Most interesting reason would be exhausted allocate/survivor, since it could mean that
-			 * tilting is too aggressive (and survival rate is jittery), and suggest tilt tuning/limiting.
-			 * There could be various other reasons, like STW global GC (system, end of concurrent mark etc.),
-			 * or even notorious 'exclusive VM access to satisfy allocate'.
-			 * Either way, the more detailed reason could be deduced from verbose GC.
-			 */
-			reasonForTermination = "termination requested by GC";
-		}
-		writer->formatAndOutput(env, 0, "<warning details=\"%s\" />", reasonForTermination, _extensions->gcExclusiveAccessThreadId);
-	}
-}
-
 void
 MM_VerboseHandlerOutput::handleConcurrentEnd(J9HookInterface** hook, UDATA eventNum, void* eventData)
 {
@@ -940,12 +947,12 @@ MM_VerboseHandlerOutput::handleConcurrentEnd(J9HookInterface** hook, UDATA event
 	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
 	UDATA contextId = stats->_cycleID;
 	char tagTemplate[200];
-	getTagTemplate(tagTemplate, sizeof(tagTemplate), _manager->getIdAndIncrement(), getConcurrentTypeString(), contextId, omrtime_current_time_millis());
+	const char* reasonForTermination = getConcurrentTerminationReason(stats);
+	getTagTemplate(tagTemplate, sizeof(tagTemplate), _manager->getIdAndIncrement(), getConcurrentTypeString(), contextId, omrtime_current_time_millis(), reasonForTermination);
 
 	enterAtomicReportingBlock();
 	writer->formatAndOutput(env, 0, "<concurrent-end %s>", tagTemplate);
 	handleConcurrentEndInternal(hook, eventNum, eventData);
-	handleConcurrentGCOpEnd(hook, eventNum, eventData);
 	writer->formatAndOutput(env, 0, "</concurrent-end>\n");
 	writer->flush(env);
 	exitAtomicReportingBlock();
@@ -1103,3 +1110,27 @@ verboseHandlerHeapResize(J9HookInterface** hook, uintptr_t eventNum, void* event
 {
 	((MM_VerboseHandlerOutput*)userData)->handleHeapResize(hook, eventNum, eventData);
 }
+
+void
+MM_VerboseHandlerOutput::handleGCOPOuterStanzaStart(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess)
+{
+	MM_VerboseManager* manager = getManager();
+	MM_VerboseWriterChain* writer = manager->getWriterChain();
+	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
+
+	if (!deltaTimeSuccess) {
+		writer->formatAndOutput(env, 0, "<warning details=\"clock error detected, following timing may be inaccurate\" />");
+	}
+
+	char tagTemplate[200];
+	getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), type ,contextID, duration, omrtime_current_time_millis());
+	writer->formatAndOutput(env, 0, "<gc-op %s>", tagTemplate);
+}
+
+void
+MM_VerboseHandlerOutput::handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env)
+{
+	MM_VerboseManager* manager = getManager();
+	MM_VerboseWriterChain* writer = manager->getWriterChain();
+	writer->formatAndOutput(env, 0, "</gc-op>");
+}

gc/verbose/VerboseHandlerOutput.hpp

@@ -30,6 +30,7 @@
 
 #include "modronbase.h"
 
+#include "ConcurrentPhaseStatsBase.hpp"
 #include "LightweightNonReentrantLock.hpp"
 
 class MM_CollectionStatistics;
@@ -321,6 +322,21 @@ class MM_VerboseHandlerOutput : public MM_Base
 	 */
 	uintptr_t getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t wallTimeMs);
 
+	/**
+	 * Build the standard top level tag template.
+	 * @param buf character buffer in which to create to tag template.
+	 * @param bufsize maximum size allowed in the character buffer.
+	 * @param id unique id of the tag being built.
+	 * @param type Human readable name for the type of the tag.
+	 * @param contextId unique identifier of the associated event this is associated with (parent/sibling relationship).
+	 * @param wallTimeMs wall clock time to be used as the timestamp for the tag.
+	 * @param reasonForTermination termination reason.
+	 * @return number of bytes consumed in the buffer.
+	 *
+	 * @note should be moved to protected once all standard usage is converted.
+	 */
+	uintptr_t getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t wallTimeMs, const char *reasonForTermination);
+
 	/**
 	 * Build the standard top level tag template.
 	 * @param buf character buffer in which to create to tag template.
@@ -368,6 +384,13 @@ class MM_VerboseHandlerOutput : public MM_Base
 	 */
 	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);
 
+	/**
+	 * Get termination reason for concurrent collection.
+	 * @param stats concurrent stats
+	 * @return string representing the reason for termination
+	 */ 
+	virtual const char *getConcurrentTerminationReason(MM_ConcurrentPhaseStatsBase *stats);
+
 	/**
 	 * Handle any output or data tracking for the initialized phase of verbose GC.
 	 * Called during initialization of GC, stanza printed to all writers via writer chain.
@@ -486,11 +509,13 @@ class MM_VerboseHandlerOutput : public MM_Base
 	void handleConcurrentEnd(J9HookInterface** hook, UDATA eventNum, void* eventData);
 
 	virtual	void handleConcurrentStartInternal(J9HookInterface** hook, UDATA eventNum, void* eventData) {}
-	virtual void handleConcurrentEndInternal(J9HookInterface** hook, UDATA eventNum, void* eventData);
+	virtual void handleConcurrentEndInternal(J9HookInterface** hook, UDATA eventNum, void* eventData) {};
 	virtual const char *getConcurrentTypeString() { return NULL; }
 
 	virtual void handleConcurrentGCOpStart(J9HookInterface** hook, uintptr_t eventNum, void* eventData) {}
-	virtual void handleConcurrentGCOpEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData) {}
+
+	void handleGCOPOuterStanzaStart(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess);
+	void handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env);
 
 	void handleHeapResize(J9HookInterface** hook, uintptr_t eventNum, void* eventData);
 

gc/verbose/handler_standard/VerboseHandlerOutputStandard.cpp

@@ -260,30 +260,6 @@ MM_VerboseHandlerOutputStandard::handleGCOPStanza(MM_EnvironmentBase* env, const
 	writer->flush(env);
 }
 
-void
-MM_VerboseHandlerOutputStandard::handleGCOPOuterStanzaStart(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess)
-{
-	MM_VerboseManager* manager = getManager();
-	MM_VerboseWriterChain* writer = manager->getWriterChain();
-	OMRPORT_ACCESS_FROM_OMRPORT(env->getPortLibrary());
-
-	if (!deltaTimeSuccess) {
-		writer->formatAndOutput(env, 0, "<warning details=\"clock error detected, following timing may be inaccurate\" />");
-	}
-
-	char tagTemplate[200];
-	getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), type ,contextID, duration, omrtime_current_time_millis());
-	writer->formatAndOutput(env, 0, "<gc-op %s>", tagTemplate);
-}
-
-void
-MM_VerboseHandlerOutputStandard::handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env)
-{
-	MM_VerboseManager* manager = getManager();
-	MM_VerboseWriterChain* writer = manager->getWriterChain();
-	writer->formatAndOutput(env, 0, "</gc-op>");
-}
-
 void
 MM_VerboseHandlerOutputStandard::handleMarkEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
 {
@@ -468,7 +444,7 @@ MM_VerboseHandlerOutputStandard::handleScavengeEnd(J9HookInterface** hook, uintp
 }
 
 void
-MM_VerboseHandlerOutputStandard::handleConcurrentGCOpEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
+MM_VerboseHandlerOutputStandard::handleConcurrentEndInternal(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
 {
 	/* convert event from concurrent-end to scavenge-end */
 	MM_ScavengeEndEvent scavengeEndEvent;

gc/verbose/handler_standard/VerboseHandlerOutputStandard.hpp

@@ -53,8 +53,6 @@ class MM_VerboseHandlerOutputStandard : public MM_VerboseHandlerOutput
 	virtual const char *getCycleType(uintptr_t type);
 
 	void handleGCOPStanza(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess);
-	void handleGCOPOuterStanzaStart(MM_EnvironmentBase* env, const char *type, uintptr_t contextID, uint64_t duration, bool deltaTimeSuccess);
-	void handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env);
 
 	virtual bool hasOutputMemoryInfoInnerStanza();
 	virtual void outputMemoryInfoInnerStanzaInternal(MM_EnvironmentBase *env, uintptr_t indent, MM_CollectionStatistics *stats);
@@ -140,7 +138,7 @@ class MM_VerboseHandlerOutputStandard : public MM_VerboseHandlerOutput
 
 	virtual const char *getConcurrentTypeString() { return "scavenge"; }
 
-	virtual void handleConcurrentGCOpEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData);
+	virtual void handleConcurrentEndInternal(J9HookInterface** hook, uintptr_t eventNum, void* eventData);
 #endif /* defined(OMR_GC_MODRON_SCAVENGER) */
 
 #if defined(OMR_GC_MODRON_CONCURRENT_MARK)