Unable to accurately capture GC start and end timestamps - EventListener GC event monitoring issues

[Liangjia0411]

Description

Problem Overview

I'm experiencing difficulties trying to precisely measure the start and end times of .NET garbage collection. I need accurate GC duration measurements, but the events currently available through EventListener don't seem to provide complete information about the GC lifecycle.

Questions

1. Is there a more accurate event to represent the start of GC, rather than GCSuspendEEBegin_V1?
2. Does the current EventListener API provide sufficient information to accurately measure GC duration?
3. Is there a recommended approach to measure the complete GC duration?

Reproduction Steps

Reproduction Code

using System;
using System.Diagnostics.Tracing;

public class GCEventListener : EventListener
{
    private long _gcStartTime;
    private DateTime _case9SystemTime;

    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name != "Microsoft-Windows-DotNETRuntime")
            return;

        EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)1);
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        switch (eventData.EventId)
        {
            case 2: /* GCEnd_V1 */
                {
                    DateTime case2SystemTime = DateTime.Now;
                    var intervalMs = (case2SystemTime - _case9SystemTime).TotalMilliseconds;
                    Console.WriteLine($"Time interval between case 2 and case 9: {intervalMs:F2}ms");

                    var cost = TimeSpan.FromTicks(eventData.TimeStamp.Ticks - _gcStartTime).TotalMilliseconds;
                    Console.WriteLine($"GC ended, time from suspension to end: {cost:F2}ms");
                    break;
                }
            case 9: /* GCSuspendEEBegin_V1 */
                {
                    _case9SystemTime = DateTime.Now;
                    _gcStartTime = eventData.TimeStamp.Ticks;
                    break;
                }
        }
    }
}

class Program
{
    public class ClassA
    { }

    static void Main(string[] args)
    {
        var gcEventListener = new GCEventListener();

        for (int i = 0; i < 10000 * 100; i++)
        {
            var a = new ClassA();
        }

        GC.Collect();

        Console.WriteLine("Press Enter to exit...");
        Console.ReadLine();
    }
}

Expected behavior

I'm looking to capture events that identify the complete GC lifecycle, including:

1. The event or timestamp when GC truly begins
2. The event or timestamp when GC ends

Actual behavior

Looking at the output logs, the time difference between eventData.TimeStamp values seems to be the actual GC duration, but I'm not sure if there are more accurate events to identify the true start time of GC. Currently, I'm using GCSuspendEEBegin_V1 (case 9), but this might only be part of the GC process rather than the starting point.

Time interval between case 2 and case 9: 18.96ms
GC ended, time from suspension to end: 23.25ms
Time interval between case 2 and case 9: 0.01ms
GC ended, time from suspension to end: 1.38ms

Regression?

No response

Known Workarounds

No response

Configuration

.NET version: 9.0.2

Other information

I've noticed that the timestamps in EventData seem to reflect the actual GC duration more accurately than system time measured using DateTime.Now. How can I correctly utilize these timestamps to precisely measure GC performance?

[mdh1418]

Hi @Liangjia0411, instead of using the GCSuspendEEBegin, there is also the GCStart event which I think you can add case 1: to your switch. I think this example is similar https://devblogs.microsoft.com/dotnet/a-portable-way-to-get-gc-events-in-process-and-no-admin-privilege-with-10-lines-of-code-and-ability-to-dynamically-enable-disable-events/.

Another way to capture GC statistics is through dotnet-trace - https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-trace
When your .NET App is running, you can use dotnet-trace ps to grab the PID of the process, and then dotnet-trace collect -p <pid> --profile gc-collect which should generate a trace containing some general GC stats. And afterwards you can open the *.nettrace in PerfView: https://github.com/microsoft/perfview and look at the GC stats of the trace.

[Liangjia0411]

@mdh1418 I have tried using GCStart event, but unfortunately, it cannot obtain real-time of GC start

[mdh1418]

Hi @Liangjia0411, to clarify, I think the order of GC events fired in the runtime is along the lines of:
GCSuspendEEBegin* - Start suspending managed threads
GCSuspendEEEnd* - Managed threads have been suspended
GCStart* - GC Work starts
Other GC events
GCEnd* - GC Work ends
GCRestartEEBegin* - Start resuming managed threads
GCRestartEEEnd* - Managed threads have resumed

Also to note, the timestamps of the events will differ from any timing mechanisms done in the managed side because there is a perf overhead between the event firing, and the event reaching the OnEventWritten callback, in addition to the perf overhead of invoking DateTime.Now.

I don't know the overall details of what you're trying to accomplish, but if capturing GC stats out of process works for you, dotnet-trace and PerfView are diagnostics tools that can report GC statistics. Viewing the traces in PerfView will handle event ordering and timestamps for you, so you don't need to manually coordinate pairing the right Begin/End events.

For example, I ran your console app and traced using dotnet-trace collect -p <pid> --profile gc-collect, and opening the trace in PerfView, the GCStop events detail the duration of GC (GCStop - GCStart).
 

There are many GC related events fired in the runtime, if you're interested, they're associated with the GCKeyword in the CLR event manifest like GCStart_V2.