diff --git a/gc/verbose/VerboseHandlerOutput.cpp b/gc/verbose/VerboseHandlerOutput.cpp index a5f5645c24b..e6af07b6f70 100644 --- a/gc/verbose/VerboseHandlerOutput.cpp +++ b/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, "", 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, "", tagTemplate); handleConcurrentEndInternal(hook, eventNum, eventData); - handleConcurrentGCOpEnd(hook, eventNum, eventData); writer->formatAndOutput(env, 0, "\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, ""); + } + + char tagTemplate[200]; + getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), type ,contextID, duration, omrtime_current_time_millis()); + writer->formatAndOutput(env, 0, "", tagTemplate); +} + +void +MM_VerboseHandlerOutput::handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env) +{ + MM_VerboseManager* manager = getManager(); + MM_VerboseWriterChain* writer = manager->getWriterChain(); + writer->formatAndOutput(env, 0, ""); +} diff --git a/gc/verbose/VerboseHandlerOutput.hpp b/gc/verbose/VerboseHandlerOutput.hpp index 09d7756eac7..275befc3c3c 100644 --- a/gc/verbose/VerboseHandlerOutput.hpp +++ b/gc/verbose/VerboseHandlerOutput.hpp @@ -30,6 +30,7 @@ #include "modronbase.h" +#include "ConcurrentPhaseStatsBase.hpp" #include "LightweightNonReentrantLock.hpp" class MM_CollectionStatistics; @@ -331,6 +332,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. @@ -378,6 +394,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. @@ -496,11 +519,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); diff --git a/gc/verbose/handler_standard/VerboseHandlerOutputStandard.cpp b/gc/verbose/handler_standard/VerboseHandlerOutputStandard.cpp index 63f6edc59a2..927efecbf7c 100644 --- a/gc/verbose/handler_standard/VerboseHandlerOutputStandard.cpp +++ b/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, ""); - } - - char tagTemplate[200]; - getTagTemplate(tagTemplate, sizeof(tagTemplate), manager->getIdAndIncrement(), type ,contextID, duration, omrtime_current_time_millis()); - writer->formatAndOutput(env, 0, "", tagTemplate); -} - -void -MM_VerboseHandlerOutputStandard::handleGCOPOuterStanzaEnd(MM_EnvironmentBase* env) -{ - MM_VerboseManager* manager = getManager(); - MM_VerboseWriterChain* writer = manager->getWriterChain(); - writer->formatAndOutput(env, 0, ""); -} - 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; diff --git a/gc/verbose/handler_standard/VerboseHandlerOutputStandard.hpp b/gc/verbose/handler_standard/VerboseHandlerOutputStandard.hpp index ccda8088328..3392ce342ab 100644 --- a/gc/verbose/handler_standard/VerboseHandlerOutputStandard.hpp +++ b/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)