Skip to content

Commit

Permalink
Rewrite LOG_GC_EVENT
Browse files Browse the repository at this point in the history
  • Loading branch information
@gleocadie
gleocadie committed Nov 14, 2024
1 parent 58409d1 commit b70b8c9
Show file tree
Hide file tree
Showing 2 changed files with 66 additions and 76 deletions.
140 changes: 64 additions & 76 deletions profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 <bool shouldLog = LogGcEvents, typename... Args>
void ClrEventsParser::LogGcEvent(
Args const&... args)
{
if constexpr (!shouldLog)
{
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,
Expand All @@ -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))
{
Expand Down Expand Up @@ -106,17 +107,17 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG
return;
}

//template tid = "GCAllocationTick_V4" >
// <data name = "AllocationAmount" inType = "win:UInt32" />
// <data name = "AllocationKind" inType = "win:UInt32" />
// <data name = "ClrInstanceID" inType = "win:UInt16" />
// <data name = "AllocationAmount64" inType = "win:UInt64"/>
// <data name = "TypeID" inType = "win:Pointer" />
// <data name = "TypeName" inType = "win:UnicodeString" />
// <data name = "HeapIndex" inType = "win:UInt32" />
// <data name = "Address" inType = "win:Pointer" />
// <data name = "ObjectSize" inType = "win:UInt64" />
//DumpBuffer(pEventData, cbEventData);
// template tid = "GCAllocationTick_V4" >
// <data name = "AllocationAmount" inType = "win:UInt32" />
// <data name = "AllocationKind" inType = "win:UInt32" />
// <data name = "ClrInstanceID" inType = "win:UInt16" />
// <data name = "AllocationAmount64" inType = "win:UInt64"/>
// <data name = "TypeID" inType = "win:Pointer" />
// <data name = "TypeName" inType = "win:UnicodeString" />
// <data name = "HeapIndex" inType = "win:UInt32" />
// <data name = "Address" inType = "win:Pointer" />
// <data name = "ObjectSize" inType = "win:UInt64" />
// DumpBuffer(pEventData, cbEventData);

AllocationTickV4Payload payload{0};
ULONG offset = 0;
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand All @@ -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("OnGCStart: ", "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)
Expand Down Expand Up @@ -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)
Expand All @@ -263,7 +261,7 @@ ClrEventsParser::ParseGcEvent(uint64_t timestamp, DWORD id, DWORD version, ULONG
return;
}

LOG_GC_EVENT("OnGCGlobalHeapHistory");
LogGcEvent("OnGCGlobalHeapHistory");
OnGCGlobalHeapHistory(timestamp, payload);
}
}
Expand All @@ -282,7 +280,7 @@ void ClrEventsParser::ParseContentionEvent(DWORD id, DWORD version, ULONG cbEven
// <data name="ContentionFlags" inType="win:UInt8" />
// <data name="ClrInstanceID" inType="win:UInt16" />
// <data name="DurationNs" inType="win:Double" />
//DumpBuffer(pEventData, cbEventData);
// DumpBuffer(pEventData, cbEventData);

ContentionStopV1Payload payload{0};
ULONG offset = 0;
Expand Down Expand Up @@ -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);
}
Expand All @@ -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,
Expand Down Expand Up @@ -415,8 +408,7 @@ void ClrEventsParser::OnGCStart(uint64_t timestamp, GCStartPayload& payload)
payload.Count,
payload.Depth,
static_cast<GCReason>(payload.Reason),
static_cast<GCType>(payload.Type)
);
static_cast<GCType>(payload.Type));

if ((payload.Depth == 2) && (payload.Type == GCType::BackgroundGC))
{
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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);
}
}

Expand All @@ -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,
Expand Down
2 changes: 2 additions & 0 deletions profiler/src/ProfilerEngine/Datadog.Profiler.Native/ClrEventsParser.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -328,6 +328,8 @@ class ClrEventsParser
IGCSuspensionsListener* _pGCSuspensionsListener = nullptr;
std::vector<IGarbageCollectionsListener*> _pGarbageCollectionsListeners;

template <bool shouldLog, typename... Args>
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)
Expand Down

0 comments on commit b70b8c9

Please sign in to comment.