runtime: Missing GC events from EventListener when in Server Mode

With .NET Core 2.2, it is now possible to listen to Clr traces in-process via EventListener derived classes Use IssueEventListener.zip to reproduce the issue (code is based on https://blogs.msdn.microsoft.com/dotnet/2018/12/04/announcing-net-core-2-2/)

If an application runs in Server mode (<ServerGarbageCollection>true</ServerGarbageCollection> in the .csproj) only a few GC related events are received when allocations trigger a GC (or induced GC.Collect()).

EventWrittenEventArgs -- ThreadID = 20708 ID = 35 Name = GCTriggered
        Name = "Reason" Value = "0"
        Name = "ClrInstanceID" Value = "8"
EventWrittenEventArgs -- ThreadID = 5292 ID = 14 Name = GCFinalizersBegin_V1
        Name = "ClrInstanceID" Value = "8"
EventWrittenEventArgs -- ThreadID = 5292 ID = 13 Name = GCFinalizersEnd_V1
        Name = "Count" Value = "1"
        Name = "ClrInstanceID" Value = "8"
EventWrittenEventArgs -- ThreadID = 5292 ID = 14 Name = GCFinalizersBegin_V1
        Name = "ClrInstanceID" Value = "8"
EventWrittenEventArgs -- ThreadID = 5292 ID = 13 Name = GCFinalizersEnd_V1
        Name = "Count" Value = "0"
        Name = "ClrInstanceID" Value = "8"
EventWrittenEventArgs -- ThreadID = 20708 ID = 35 Name = GCTriggered
        Name = "Reason" Value = "10"
        Name = "ClrInstanceID" Value = "8"

If the application runs in workstation mode, all expected events are received.

EventWrittenEventArgs -- ThreadID = 33004 ID = 9 Name = GCSuspendEEBegin_V1
	Name = "Reason" Value = "1"
	Name = "Count" Value = "0"
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 8 Name = GCSuspendEEEnd_V1
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 35 Name = GCTriggered
	Name = "Reason" Value = "0"
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 1 Name = GCStart_V2
	Name = "Count" Value = "1"
	Name = "Depth" Value = "0"
	Name = "Reason" Value = "0"
	Name = "Type" Value = "0"
	Name = "ClrInstanceID" Value = "8"
	Name = "ClientSequenceNumber" Value = "0"

EventWrittenEventArgs -- ThreadID = 33004 ID = 202 Name = GCMarkWithType
	Name = "HeapNum" Value = "0"
	Name = "ClrInstanceID" Value = "8"
	Name = "Type" Value = "0"
	Name = "Bytes" Value = "1053010"

EventWrittenEventArgs -- ThreadID = 33004 ID = 202 Name = GCMarkWithType
	Name = "HeapNum" Value = "0"
	Name = "ClrInstanceID" Value = "8"
	Name = "Type" Value = "1"
	Name = "Bytes" Value = "0"

EventWrittenEventArgs -- ThreadID = 33004 ID = 202 Name = GCMarkWithType
	Name = "HeapNum" Value = "0"
	Name = "ClrInstanceID" Value = "8"
	Name = "Type" Value = "2"
	Name = "Bytes" Value = "53176"

EventWrittenEventArgs -- ThreadID = 33004 ID = 202 Name = GCMarkWithType
	Name = "HeapNum" Value = "0"
	Name = "ClrInstanceID" Value = "8"
	Name = "Type" Value = "3"
	Name = "Bytes" Value = "204911"

EventWrittenEventArgs -- ThreadID = 33004 ID = 205 Name = GCGlobalHeapHistory_V2
	Name = "FinalYoungestDesired" Value = "6291456"
	Name = "NumHeaps" Value = "1"
	Name = "CondemnedGeneration" Value = "0"
	Name = "Gen0ReductionCount" Value = "0"
	Name = "Reason" Value = "0"
	Name = "GlobalMechanisms" Value = "20"
	Name = "ClrInstanceID" Value = "8"
	Name = "PauseMode" Value = "1"
	Name = "MemoryPressure" Value = "0"

EventWrittenEventArgs -- ThreadID = 33004 ID = 204 Name = GCPerHeapHistory_V3
	Name = "ClrInstanceID" Value = "8"
	Name = "FreeListAllocated" Value = "0"
	Name = "FreeListRejected" Value = "0"
	Name = "EndOfSegAllocated" Value = "0"
	Name = "CondemnedAllocated" Value = "0"
	Name = "PinnedAllocated" Value = "0"
	Name = "PinnedAllocatedAdvance" Value = "0"
	Name = "RunningFreeListEfficiency" Value = "0"
	Name = "CondemnReasons0" Value = "0"
	Name = "CondemnReasons1" Value = "0"
	Name = "CompactMechanisms" Value = "0"
	Name = "ExpandMechanisms" Value = "0"
	Name = "HeapIndex" Value = "0"
	Name = "ExtraGen0Commit" Value = "32088"
	Name = "Count" Value = "4"

EventWrittenEventArgs -- ThreadID = 33004 ID = 2 Name = GCEnd_V1
	Name = "Count" Value = "1"
	Name = "Depth" Value = "0"
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 4 Name = GCHeapStats_V1
	Name = "GenerationSize0" Value = "24"
	Name = "TotalPromotedSize0" Value = "1314320"
	Name = "GenerationSize1" Value = "2134648"
	Name = "TotalPromotedSize1" Value = "0"
	Name = "GenerationSize2" Value = "24"
	Name = "TotalPromotedSize2" Value = "0"
	Name = "GenerationSize3" Value = "282528"
	Name = "TotalPromotedSize3" Value = "0"
	Name = "FinalizationPromotedSize" Value = "32"
	Name = "FinalizationPromotedCount" Value = "1"
	Name = "PinnedObjectCount" Value = "1"
	Name = "SinkBlockCount" Value = "10"
	Name = "GCHandleCount" Value = "50"
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 7 Name = GCRestartEEBegin_V1
	Name = "ClrInstanceID" Value = "8"

EventWrittenEventArgs -- ThreadID = 33004 ID = 3 Name = GCRestartEEEnd_V1
	Name = "ClrInstanceID" Value = "8"

Also note that if you run perfview in both cases, all expected events are received via etw by perfview

About this issue

Original URL
State: closed
Created 6 years ago
Reactions: 2
Comments: 20 (16 by maintainers)

Most upvoted comments

What are the chances this will get backported to 2.2? I noticed the current milestone is 3.0. Right now the new metrics aren’t usable on linux servers sadly.

joshgarnett on Feb 27, 2019

This probably explains why some threadpool events are missing as well. I suppose that the threadpool gate thread (that pushes the ThreadPoolWorkerThreadAdjustmentAdjustment event) does not have a Thread object. There could be plenty of other cases like those ones. I agree that the solution should be at the EventPipe level.

kevingosse on Dec 17, 2018

Given the fix for dotnet/coreclr#22502 was merged in May, can this fix be shipped in a 2.2 servicing release? Has it already?

alastairs on Jun 19, 2019

dotnet/coreclr#21817 was merged to master, so you should start seeing events under server GC if you use the runtime from latest master branch. There are still existing issues with EventPipeBuffer works, but that’s a separate issue from this so I filed https://github.com/dotnet/coreclr/issues/22502. Please feel free to reopen if the issue still exists.

sywhang on Feb 10, 2019

one of which is to abstract the per-thread structures needed by the logger to so they can be fetched from the Thread Structure but also on their own

Why not let EventPipe to always manage the buffers on its own? I do not see the value of this abstraction.

jkotas on Dec 17, 2018

thanks for finding this, @chrisnas!

@noahfalk is on vacation, could someone else from @tommcdon’s team take a look?

Maoni0 on Dec 5, 2018