Add contextid in concurrent-collection-start

eclipse-openj9/openj9#11237

Added attribute `contextid` to `concurrent-collection-start` stanza.
Changed name of `concurrent-collection-start` stanza
to `conurrent-global-final` to show its relation to
`cycle-end` stanza which follows it.
Removed `concurrent-collection-end` to reduce redundancy with
`exclusive` stanza that follows it.
Overloaded `MM_VerboseHandlerOutput::getTagTemplate()` to take `contextid`.

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

gc/base/omrmmprivate.hdf

@@ -335,6 +335,7 @@ SPDX-License-Identifier: EPL-2.0 OR Apache-2.0 OR GPL-2.0 WITH Classpath-excepti
 		<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="uintptr_t" name="contextid" description="unique identifier of the associated event this is associated with (parent/sibling relationship)" />
 		<data type="struct MM_CommonGCStartData*" name="gcStartData" description="common data for GC start events" />
 		<data type="uintptr_t" name="traceTarget" description="the targetted number of bytes to be concurrently traced" />
 		<data type="uintptr_t" name="tracedTotal" description="the number of bytes concurrently traced" />

gc/base/standard/ConcurrentGC.cpp

@@ -365,6 +365,7 @@ MM_ConcurrentGC::reportConcurrentCollectionStart(MM_EnvironmentBase *env)
 			env->getOmrVMThread(),
 			omrtime_hires_clock(),
 			J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_START,
+			_concurrentCycleState._verboseContextID,
 			&commonData,
 			_stats.getTraceSizeTarget(),
 			_stats.getTotalTraced(),
@@ -384,8 +385,6 @@ MM_ConcurrentGC::reportConcurrentCollectionStart(MM_EnvironmentBase *env)
 void
 MM_ConcurrentGC::reportConcurrentCollectionEnd(MM_EnvironmentBase *env, uint64_t duration)
 {
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
-
 	Trc_MM_ConcurrentCollectionEnd(env->getLanguageVMThread(),
 		_extensions->heap->getApproximateActiveFreeMemorySize(MEMORY_TYPE_NEW),
 		_extensions->heap->getActiveMemorySize(MEMORY_TYPE_NEW),
@@ -394,21 +393,6 @@ MM_ConcurrentGC::reportConcurrentCollectionEnd(MM_EnvironmentBase *env, uint64_t
 		(_extensions-> largeObjectArea ? _extensions->heap->getApproximateActiveFreeLOAMemorySize(MEMORY_TYPE_OLD) : 0 ),
 		(_extensions-> largeObjectArea ? _extensions->heap->getActiveLOAMemorySize(MEMORY_TYPE_OLD) : 0 )
 	);
-
-	if (J9_EVENT_IS_HOOKED(_extensions->privateHookInterface, J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_END)) {
-		MM_CommonGCEndData commonData;
-		_extensions->heap->initializeCommonGCEndData(env, &commonData);
-
-		ALWAYS_TRIGGER_J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_END(
-				_extensions->privateHookInterface,
-				env->getOmrVMThread(),
-				omrtime_hires_clock(),
-				J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_END,
-				duration,
-				env->getExclusiveAccessTime(),
-				&commonData
-		);
-	}
 }
 
 void

gc/verbose/VerboseHandlerOutput.cpp

@@ -161,6 +161,17 @@ 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, uintptr_t contextId, uint64_t wallTimeMs)
+{
+	OMRPORT_ACCESS_FROM_OMRVM(_omrVM);
+	uintptr_t bufPos = 0;
+	bufPos += getTagTemplate(buf, bufsize, id, wallTimeMs);
+	bufPos += omrstr_printf(buf + bufPos, bufsize - bufPos, " contextid=\"%zu\"", contextId);
+
+	return bufPos;
+}
+
 uintptr_t
 MM_VerboseHandlerOutput::getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t id, const char *type, uintptr_t contextId, uint64_t wallTimeMs)
 {

gc/verbose/VerboseHandlerOutput.hpp

@@ -296,6 +296,19 @@ class MM_VerboseHandlerOutput : public MM_Base
 	 */
 	uintptr_t getTagTemplate(char *buf, uintptr_t bufsize, uintptr_t id, 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 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.
+	 * @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, uintptr_t contextId, uint64_t wallTimeMs);
+
 	/**
 	 * Build the standard top level tag template.
 	 * @param buf character buffer in which to create to tag template.

gc/verbose/handler_standard/VerboseHandlerOutputStandard.cpp

@@ -70,7 +70,6 @@ static void verboseHandlerConcurrentTracingEnd(J9HookInterface** hook, uintptr_t
 static void verboseHandlerConcurrentKickoff(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData);
 static void verboseHandlerConcurrentHalted(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData);
 static void verboseHandlerConcurrentCollectionStart(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData);
-static void verboseHandlerConcurrentCollectionEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData);
 static void verboseHandlerConcurrentAborted(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData);
 #endif /* defined(OMR_GC_MODRON_CONCURRENT_MARK) */
 
@@ -150,7 +149,6 @@ MM_VerboseHandlerOutputStandard::enableVerbose()
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_KICKOFF, verboseHandlerConcurrentKickoff, OMR_GET_CALLSITE(), (void *)this);
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_HALTED, verboseHandlerConcurrentHalted, OMR_GET_CALLSITE(), (void *)this);
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_START, verboseHandlerConcurrentCollectionStart, OMR_GET_CALLSITE(), (void *)this);
-	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_END, verboseHandlerConcurrentCollectionEnd, OMR_GET_CALLSITE(), (void *)this);
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_ABORTED, verboseHandlerConcurrentAborted, OMR_GET_CALLSITE(), (void *)this);
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_REMEMBERED_SET_SCAN_END, verboseHandlerConcurrentRememberedSetScanEnd, OMR_GET_CALLSITE(), (void *)this);
 	(*_mmPrivateHooks)->J9HookRegisterWithCallSite(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COMPLETE_TRACING_END, verboseHandlerConcurrentTracingEnd, OMR_GET_CALLSITE(), (void *)this);
@@ -210,7 +208,6 @@ MM_VerboseHandlerOutputStandard::disableVerbose()
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_KICKOFF, verboseHandlerConcurrentKickoff, NULL);
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_HALTED, verboseHandlerConcurrentHalted, NULL);
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_START, verboseHandlerConcurrentCollectionStart, NULL);
-	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COLLECTION_END, verboseHandlerConcurrentCollectionEnd, NULL);
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_ABORTED, verboseHandlerConcurrentAborted, NULL);
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_REMEMBERED_SET_SCAN_END, verboseHandlerConcurrentRememberedSetScanEnd, NULL);
 	(*_mmPrivateHooks)->J9HookUnregister(_mmPrivateHooks, J9HOOK_MM_PRIVATE_CONCURRENT_COMPLETE_TRACING_END, verboseHandlerConcurrentTracingEnd, NULL);
@@ -748,12 +745,12 @@ MM_VerboseHandlerOutputStandard::handleConcurrentCollectionStart(J9HookInterface
 
 	char tagTemplate[200];
 	enterAtomicReportingBlock();
-	getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
-	writer->formatAndOutput(env, 0, "<concurrent-collection-start %s intervalms=\"%llu.%03llu\" >",
+	getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), event->contextid, omrtime_current_time_millis());
+	writer->formatAndOutput(env, 0, "<concurrent-global-final %s intervalms=\"%llu.%03llu\" >",
 		tagTemplate, deltaTime / 1000, deltaTime % 1000);
 	writer->formatAndOutput(env, 1, "<concurrent-trace-info reason=\"%s\" tracedByMutators=\"%zu\" tracedByHelpers=\"%zu\" cardsCleaned=\"%zu\" workStackOverflowCount=\"%zu\" />",
 		cardCleaningReasonString, event->tracedByMutators, event->tracedByHelpers, event->cardsCleaned, event->workStackOverflowCount);
-  	writer->formatAndOutput(env, 0, "</concurrent-collection-start>");
+  	writer->formatAndOutput(env, 0, "</concurrent-global-final>");
 
 	writer->flush(env);
 
@@ -768,31 +765,6 @@ MM_VerboseHandlerOutputStandard::handleConcurrentCollectionStartInternal(MM_Envi
 	/* Empty stub */
 }
 
-void
-MM_VerboseHandlerOutputStandard::handleConcurrentCollectionEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
-{
-	MM_ConcurrentCollectionEndEvent* event = (MM_ConcurrentCollectionEndEvent*)eventData;
-	MM_VerboseManager* manager = getManager();
-	MM_VerboseWriterChain* writer = manager->getWriterChain();
-	MM_EnvironmentBase* env = MM_EnvironmentBase::getEnvironment(event->currentThread);
-	OMRPORT_ACCESS_FROM_ENVIRONMENT(env);
-	char tagTemplate[200];
-	enterAtomicReportingBlock();
-	getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), omrtime_current_time_millis());
-	writer->formatAndOutput(env, 0, "<concurrent-collection-end %s />", tagTemplate);
-	writer->flush(env);
-
-	handleConcurrentCollectionEndInternal(env, eventData);
-
-	exitAtomicReportingBlock();
-}
-
-void
-MM_VerboseHandlerOutputStandard::handleConcurrentCollectionEndInternal(MM_EnvironmentBase *env, void* eventData)
-{
-	/* Empty stub */
-}
-
 void
 MM_VerboseHandlerOutputStandard::handleConcurrentAborted(J9HookInterface** hook, uintptr_t eventNum, void* eventData)
 {
@@ -1111,12 +1083,6 @@ verboseHandlerConcurrentCollectionStart(J9HookInterface** hook, uintptr_t eventN
 	((MM_VerboseHandlerOutputStandard *)userData)->handleConcurrentCollectionStart(hook, eventNum, eventData);
 }
 
-void
-verboseHandlerConcurrentCollectionEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData)
-{
-	((MM_VerboseHandlerOutputStandard *)userData)->handleConcurrentCollectionEnd(hook, eventNum, eventData);
-}
-
 void
 verboseHandlerConcurrentAborted(J9HookInterface** hook, uintptr_t eventNum, void* eventData, void* userData)
 {

gc/verbose/handler_standard/VerboseHandlerOutputStandard.hpp

@@ -79,7 +79,6 @@ class MM_VerboseHandlerOutputStandard : public MM_VerboseHandlerOutput
 	virtual const char* getConcurrentKickoffReason(void *eventData);
 	virtual void handleConcurrentHaltedInternal(MM_EnvironmentBase *env, void* eventData);
 	virtual void handleConcurrentCollectionStartInternal(MM_EnvironmentBase *env, void* eventData);
-	virtual void handleConcurrentCollectionEndInternal(MM_EnvironmentBase *env, void* eventData);
 	virtual void handleConcurrentAbortedInternal(MM_EnvironmentBase *env, void* eventData);
 #endif /* defined(OMR_GC_MODRON_CONCURRENT_MARK) */
 
@@ -193,14 +192,6 @@ class MM_VerboseHandlerOutputStandard : public MM_VerboseHandlerOutput
 	 */
 	void handleConcurrentCollectionStart(J9HookInterface** hook, uintptr_t eventNum, void* eventData);
 
-	/**
-	 * Write verbose stanza for concurrent collection end event.
-	 * @param hook Hook interface used by the JVM.
-	 * @param eventNum The hook event number.
-	 * @param eventData hook specific event data.
-	 */
-	void handleConcurrentCollectionEnd(J9HookInterface** hook, uintptr_t eventNum, void* eventData);
-
 	/**
 	 * Write verbose stanza for concurrent aborted event.
 	 * @param hook Hook interface used by the JVM.

gc/verbose/schema.xsd

@@ -47,9 +47,8 @@ xmlns:vgc="http://www.ibm.com/j9/verbosegc">
 	<element name="af-start" type="vgc:af-start" />
 	<element name="af-end" type="vgc:af-end" />
 	<element name="allocation-taxation" type="vgc:allocation-taxation" />
-	<element name="concurrent-collection-start" type="vgc:concurrent-collection-start" />
+	<element name="concurrent-global-final" type="vgc:concurrent-global-final" />
 	<element name="concurrent-trace-info" type="vgc:concurrent-trace-info" />
-	<element name="concurrent-collection-end" type="vgc:concurrent-collection-end" />
 	<element name="cycle-start" type="vgc:cycle-start" />
 	<element name="cycle-continue" type="vgc:cycle-continue" />
 	<element name="cycle-end" type="vgc:cycle-end" />
@@ -133,8 +132,7 @@ xmlns:vgc="http://www.ibm.com/j9/verbosegc">
 				<element ref="vgc:af-start" maxOccurs="1" minOccurs="1" />
 				<element ref="vgc:af-end" maxOccurs="1" minOccurs="1" />
 				<element ref="vgc:allocation-taxation" maxOccurs="1" minOccurs="1" />
-				<element ref="vgc:concurrent-collection-start" maxOccurs="1" minOccurs="1" />
-				<element ref="vgc:concurrent-collection-end" maxOccurs="1" minOccurs="1" />
+				<element ref="vgc:concurrent-global-final" maxOccurs="1" minOccurs="1" />
 				<element ref="vgc:cycle-start" maxOccurs="1" minOccurs="1" />
 				<element ref="vgc:cycle-continue" maxOccurs="1" minOccurs="1" />
 				<element ref="vgc:cycle-end" maxOccurs="1" minOccurs="1" />
@@ -296,11 +294,12 @@ xmlns:vgc="http://www.ibm.com/j9/verbosegc">
 		<attribute name="intervalms" type="float" use="required" />
 	</complexType>	
 
-	<complexType name="concurrent-collection-start">
+	<complexType name="concurrent-global-final">
 		<sequence maxOccurs="1" minOccurs="1">
 			<element ref="vgc:concurrent-trace-info" maxOccurs="1" minOccurs="1" />
 		</sequence>
 		<attribute name="id" type="integer" use="required" />
+		<attribute name="contextid" type="integer" use="required" />
 		<attribute name="timestamp" type="dateTime" use="required" />
 		<attribute name="intervalms" type="float" use="required" />
 	</complexType>
@@ -313,11 +312,6 @@ xmlns:vgc="http://www.ibm.com/j9/verbosegc">
 		<attribute name="workStackOverflowCount" type="integer" use="required" />
 	</complexType>
 
-	<complexType name="concurrent-collection-end">
-		<attribute name="id" type="integer" use="required" />
-		<attribute name="timestamp" type="dateTime" use="required" />
-	</complexType>
-
 	<complexType name="cycle-start">
 		<attribute name="id" type="integer" use="required" />
 		<attribute name="type" type="string" use="required" />