From c5fd5dcd4854006410b5760c672ee86730fff84d Mon Sep 17 00:00:00 2001 From: Gregory LEOCADIE Date: Thu, 14 Nov 2024 23:28:13 +0100 Subject: [PATCH] Rewrite LOG_GC_EVENT --- .../ClrEventsParser.cpp | 140 ++++++++---------- .../Datadog.Profiler.Native/ClrEventsParser.h | 2 + 2 files changed, 66 insertions(+), 76 deletions(-) diff --git a/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.cpp b/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.cpp index de36b3eb3aac..f06075af286c 100644 --- a/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.cpp +++ b/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.cpp @@ -13,23 +13,26 @@ #include "ManagedThreadInfo.h" #include "OpSysTools.h" - // set to true for debugging purpose -const bool LogGcEvents = false; - -#define LOG_GC_EVENT(x) \ -{ \ - if (LogGcEvents) \ - { \ - std::stringstream builder; \ - builder << OpSysTools::GetThreadId() \ - << " " << ((_gcInProgress.Number != -1) ? "F" : ((_currentBGC.Number != -1) ? "B" : "")) \ - << GetCurrentGC().Number \ - << " | " << x << std::endl; \ - std::cout << builder.str(); \ - } \ -} \ +constexpr bool LogGcEvents = false; + +template +void ClrEventsParser::LogGcEvent( + Args const&... args) +{ + if constexpr (!LogGcEvents) + { + return; + } + std::cout + << OpSysTools::GetThreadId() + << " " << ((_gcInProgress.Number != -1) ? "F" : ((_currentBGC.Number != -1) ? "B" : "")) + << GetCurrentGC().Number + << " | "; + ((std::cout << args << ' '), ...); + std::cout << std::endl; +} ClrEventsParser::ClrEventsParser( IAllocationsListener* pAllocationListener, @@ -54,15 +57,13 @@ void ClrEventsParser::Register(IGarbageCollectionsListener* pGarbageCollectionsL _pGarbageCollectionsListeners.push_back(pGarbageCollectionsListener); } - void ClrEventsParser::ParseEvent( uint64_t timestamp, DWORD version, INT64 keywords, DWORD id, ULONG cbEventData, - LPCBYTE eventData - ) + LPCBYTE eventData) { if (KEYWORD_GC == (keywords & KEYWORD_GC)) { @@ -106,17 +107,17 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG return; } - //template tid = "GCAllocationTick_V4" > - // - // - // - // - // - // - // - // - // - //DumpBuffer(pEventData, cbEventData); + // template tid = "GCAllocationTick_V4" > + // + // + // + // + // + // + // + // + // + // DumpBuffer(pEventData, cbEventData); AllocationTickV4Payload payload{0}; ULONG offset = 0; @@ -174,7 +175,7 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG // if (id == EVENT_GC_TRIGGERED) { - LOG_GC_EVENT("OnGCTriggered"); + LogGcEvent("OnGCTriggered"); OnGCTriggered(); } else if (id == EVENT_GC_START) @@ -186,9 +187,7 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG return; } - std::stringstream buffer; - buffer << "OnGCStart: " << payload.Count << " " << payload.Depth << " " << payload.Reason << " " << payload.Type; - LOG_GC_EVENT(buffer.str()); + LogGcEvent("OnGCStart: ", payload.Count, payload.Depth, payload.Reason, payload.Type); OnGCStart(timestamp, payload); } else if (id == EVENT_GC_END) @@ -200,19 +199,18 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG return; } - std::stringstream buffer; - buffer << "OnGCEnd: " << payload.Count << " " << payload.Depth; - LOG_GC_EVENT(buffer.str()); + LogGcEvent("OnGCEnd: ", payload.Count, payload.Depth); + OnGCEnd(payload); } else if (id == EVENT_GC_SUSPEND_EE_BEGIN) { - LOG_GC_EVENT("OnGCSuspendEEBegin"); + LogGcEvent("OnGCSuspendEEBegin"); OnGCSuspendEEBegin(timestamp); } else if (id == EVENT_GC_RESTART_EE_END) { - LOG_GC_EVENT("OnGCRestartEEEnd"); + LogGcEvent("OnGCRestartEEEnd"); OnGCRestartEEEnd(timestamp); } else if (id == EVENT_GC_HEAP_STAT) @@ -251,7 +249,7 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG pohSize = payload.GenerationSize4; } - LOG_GC_EVENT("OnGCHeapStats"); + LogGcEvent("OnGCHeapStats"); OnGCHeapStats(timestamp, gen2Size, lohSize, pohSize); } else if (id == EVENT_GC_GLOBAL_HEAP_HISTORY) @@ -263,7 +261,7 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG return; } - LOG_GC_EVENT("OnGCGlobalHeapHistory"); + LogGcEvent("OnGCGlobalHeapHistory"); OnGCGlobalHeapHistory(timestamp, payload); } } @@ -282,7 +280,7 @@ void ClrEventsParser::ParseContentionEvent(DWORD id, DWORD version, ULONG cbEven // // // - //DumpBuffer(pEventData, cbEventData); + // DumpBuffer(pEventData, cbEventData); ContentionStopV1Payload payload{0}; ULONG offset = 0; @@ -319,9 +317,7 @@ void ClrEventsParser::NotifyGarbageCollectionStarted(uint64_t timestamp, int32_t { for (auto& pGarbageCollectionsListener : _pGarbageCollectionsListeners) { - std::stringstream buffer; - buffer << "OnGarbageCollectionStart: " << number << " " << generation << " " << reason << " " << type; - LOG_GC_EVENT(buffer.str()); + LogGcEvent("OnGarbageCollectionStart: ", number, generation, reason, type); pGarbageCollectionsListener->OnGarbageCollectionStart(timestamp, number, generation, reason, type); } @@ -338,14 +334,11 @@ void ClrEventsParser::NotifyGarbageCollectionEnd( uint64_t endTimestamp, uint64_t gen2Size, uint64_t lohSize, - uint64_t pohSize - ) + uint64_t pohSize) { for (auto& pGarbageCollectionsListener : _pGarbageCollectionsListeners) { - std::stringstream buffer; - buffer << "OnGarbageCollectionEnd: " << number << " " << generation << " " << reason << " " << type; - LOG_GC_EVENT(buffer.str()); + LogGcEvent("OnGarbageCollectionEnd: ", number, generation, reason, type); pGarbageCollectionsListener->OnGarbageCollectionEnd( number, @@ -415,8 +408,7 @@ void ClrEventsParser::OnGCStart(uint64_t timestamp, GCStartPayload& payload) payload.Count, payload.Depth, static_cast(payload.Reason), - static_cast(payload.Type) - ); + static_cast(payload.Type)); if ((payload.Depth == 2) && (payload.Type == GCType::BackgroundGC)) { @@ -463,16 +455,15 @@ void ClrEventsParser::OnGCRestartEEEnd(uint64_t timestamp) else { // bad luck: a xxxBegin event has been missed - LOG_GC_EVENT("### missing Begin event"); + LogGcEvent("### missing Begin event"); } gc.PauseDuration += suspensionDuration; // could be the end of a gen0/gen1 or of a non concurrent gen2 GC if ((gc.Generation < 2) || (gc.Type == GCType::NonConcurrentGC)) { - std::stringstream buffer; - buffer << " end of GC #" << gc.Number << " - " << (timestamp - gc.StartTimestamp) / 1000000 << "ms"; - LOG_GC_EVENT(buffer.str()); + auto duration = std::chrono::milliseconds(timestamp - gc.StartTimestamp); + LogGcEvent(" end of GC #", gc.Number, "-", duration); NotifyGarbageCollectionEnd( gc.Number, @@ -506,24 +497,22 @@ void ClrEventsParser::OnGCHeapStats(uint64_t timestamp, uint64_t gen2Size, uint6 if (gc.HasGlobalHeapHistoryBeenReceived && (gc.Generation == 2) && (gc.Type == GCType::BackgroundGC)) { - std::stringstream buffer; - buffer << " end of GC #" << gc.Number << " - " << (timestamp - gc.StartTimestamp) / 1000000 << "ms"; - LOG_GC_EVENT(buffer.str()); - - NotifyGarbageCollectionEnd( - gc.Number, - gc.Generation, - gc.Reason, - gc.Type, - gc.IsCompacting, - gc.PauseDuration, - timestamp - gc.StartTimestamp, - timestamp, - gc.gen2Size, - gc.lohSize, - gc.pohSize - ); - ResetGC(gc); + auto duration = std::chrono::milliseconds(timestamp - gc.StartTimestamp); + LogGcEvent(" end of GC #", gc.Number, "-", duration); + + NotifyGarbageCollectionEnd( + gc.Number, + gc.Generation, + gc.Reason, + gc.Type, + gc.IsCompacting, + gc.PauseDuration, + timestamp - gc.StartTimestamp, + timestamp, + gc.gen2Size, + gc.lohSize, + gc.pohSize); + ResetGC(gc); } } @@ -544,9 +533,8 @@ void ClrEventsParser::OnGCGlobalHeapHistory(uint64_t timestamp, GCGlobalHeapPayl if (gc.HasHeapStatsBeenReceived && (gc.Generation == 2) && (gc.Type == GCType::BackgroundGC)) { - std::stringstream buffer; - buffer << " end of GC #" << gc.Number << " - " << (timestamp - gc.StartTimestamp) / 1000000 << "ms"; - LOG_GC_EVENT(buffer.str()); + auto duration = std::chrono::milliseconds(timestamp - gc.StartTimestamp); + LogGcEvent(" end of GC #", gc.Number, "-", duration); NotifyGarbageCollectionEnd( gc.Number, diff --git a/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.h b/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.h index fafe9e8866ce..bd4fe44187b9 100644 --- a/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.h +++ b/profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.h @@ -328,6 +328,8 @@ class ClrEventsParser IGCSuspensionsListener* _pGCSuspensionsListener = nullptr; std::vector _pGarbageCollectionsListeners; + template + void LogGcEvent(Args const&... args); // state for garbage collection details including Stop The World duration private: // set when GCSuspendEEBegin is received (usually no GC is known at that time)