{"id":451,"date":"2015-11-20T17:58:00","date_gmt":"2015-11-20T17:58:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/2015\/11\/20\/are-you-glad\/"},"modified":"2021-09-30T14:00:49","modified_gmt":"2021-09-30T21:00:49","slug":"are-you-glad","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/dotnet\/are-you-glad\/","title":{"rendered":"Are you GLAD?"},"content":{"rendered":"

Holidays are almost upon us. Last year around Christmas time I wrote a set of GC ETW blog entries to help with diagnosing GC heap related issues. This year I want to discuss taking that a (big) step further and making an SDK that does the analysis for you using these ETW events – so before I leave for vacation I’d like to share with you the plan I have for the SDK.<\/span><\/p>\n

The SDK is called GLAD<\/span><\/span><\/strong> which stands for <\/span>G<\/span><\/span><\/strong>C <\/span>L<\/span><\/span><\/strong>atency <\/span>A<\/span><\/span><\/strong>nalysis and <\/span>D<\/span><\/span><\/strong>iagnostics. This will essentially be based on the analysis and diagnostics work for the GC we have in PerfView today but I wanted to isolate it out and make it into an SDK so everyone can benefit from it. And it will be open sourced on github – we will continue our development on GLAD there; and everyone else is welcome to contribute to it.<\/span><\/span><\/p>\n

We will start GLAD off by converting our analysis part into this form. The diagnostics will come after. The difference between the two is analysis shows you info on each GC while diagnostics actually looks at the histogram of the GCs and tells you what issues it found.<\/span><\/p>\n

I should note that I am not an API person so I will not take offence if you tell me my API design sucks, but at the same time I am asking you to help me out and suggest something better \ud83d\ude42<\/span><\/span><\/p>\n

I would greatly appreciate your feedback on it so please feel free to comment (or if you are simply GLAD to see it, you can say just that too!). I will look at all the comments around Christmas (seems like an appropriate time to talk about this kind of stuff).<\/span><\/p>\n

Motivation<\/span><\/p>\n

It’s certainly not a trivial task to look at the GC behavior. Historically we’ve built this knowledge in our own tool, PerfView, which takes ETW traces and produces insights in the GC behavior. PerfView is used by many teams internally at Microsoft. However, we recognize that some teams already have or are adding their own ETW processing pipeline. Obviously they would like to add GC pauses as part of their ETW analysis. Interpreting GC ETW events however presents a challenge for them. For example, even accounting for GC pauses, which is a basic and fundamental metric, is often incorrectly done due to the complexity introduced by Background GC. Therefore we would like to make the code available for anyone who would want to incorporate the GC behavior analysis into their own ETW processing.<\/span><\/p>\n

Background<\/span><\/p>\n

For those of you who are not familiar with how the workflow for analysis with ETW events usually look like, let me use PerfView as an example.<\/span><\/p>\n

After you collect a trace (you can do this with PerfView as I mentioned in my ETW blog entries, or you could use WPA which is another Microsoft tool that’s built by the OS folks, or something else of your choice), you need to convert the events from the binary form into a human consumable form. In order for this to happen you need to know the event layout. The GC ETW events’ layout is documented here<\/span><\/span><\/span><\/a>. For example, the GCStart version 1 event has the following fields along with their types and explanation:<\/span><\/span><\/p>\n

Count:         UInt32 (the GC index)<\/span><\/p>\n

Depth:         UInt32 (which generation)<\/span><\/p>\n

Reason:        UInt32 (why was this GC triggered)<\/span><\/p>\n

Type:          UInt32 (is this a non concurrent GC, a foreground or a background GC?)<\/span><\/p>\n

ClrInstanceID: UInt16 (you can ignore this for this discussion)<\/span><\/p>\n

Also for each ETW, by default, there’s a bunch of information already available to you such as the timestamp when this event was fired.<\/span><\/p>\n

We have a library that does exactly that for you – it’s called TraceEvent<\/span><\/span><\/span><\/a> – it knows the event layouts (including a bunch of OS events, CLR events, asp.net events and etc) and as it encounters each event it will convert it to a type that you can consume in your code. So when it sees a GCStart event, it will construct a type that has exactly those fields that you can read; and it also gives you a chance to do some event processing. So let’s say I want to write in my log everytime I see a GC start and end with their timestamps and the process it happened in:<\/span><\/span>
<\/span><\/p>\n

\/\/ ETWTraceEventSource is what knows how to convert a .etl file to<\/span><\/p>\n

\/\/ the human readable event form.<\/span><\/p>\n

ETWTraceEventSource source = new<\/span><\/span><\/span> ETWTraceEventSource(“myTrace.etl”<\/span><\/span><\/span>);<\/span><\/p>\n


\/\/ Clr is a provider that TraceEvent knows about which represents,<\/span><\/span><\/p>\n

\/\/ you guess it, the CLR ETW provider. It has a bunch of events defined<\/span><\/p>\n

\/\/ like GCStart and GCStop.<\/span><\/p>\n

source.Clr.GCStart += delegate<\/span><\/span><\/span>(GCStartTraceData data)<\/span><\/p>\n

{<\/span>
    \/\/ Since GC is per process, we’d like note down the process ID as well.<\/span><\/p>\n

    myLog.WriteLine(“Observed in process {0} GC#{1} started at {2}ms”<\/span><\/span><\/span>, <\/span><\/p>\n

                    data.ProcessID, data.Count, data.TimeStampRelativeMSec);<\/span><\/p>\n

}<\/span><\/p>\n

source.Clr.GCStop +=  delegate<\/span><\/span><\/span>(GCEndTraceData data)<\/span><\/p>\n

{<\/span><\/p>\n

    \/\/ Since GC is per process, we’d like note down the process ID as well<\/span>.<\/span><\/span><\/p>\n

    myLog.WriteLine(“Observed in process {0} GC ended at {1}ms”<\/span><\/span><\/span>, <\/span><\/p>\n

                    data.ProcessID, data.TimeStampRelativeMSec);
<\/strong><\/span>};<\/span><\/p>\n

(note that this code sample is based on the current TraceEvent)<\/span><\/p>\n

GLAD essentially replaces the bold lines with much more interesting processing – it would provide rich info on each GC such as time managed threads were paused, promoted size, reasons why we decided to collect this generation, fragmentation, pinning, time for marking from different sources and etc.<\/span><\/p>\n

Details<\/span><\/p>\n

The SDK will consist of the following:<\/span><\/p>\n

1) The implementation of a set of action delegates that correspond to each event where each delegate takes one parameter which is the event data (that’s what we’ll be processing for that event).<\/span><\/p>\n

2) A list of GCInformation for each GC we processed.<\/span><\/p>\n

Normally we don’t care about partial GCs, ie, a GC that we don’t have the full sequence of events for. There are 2 ways the user can recognize a complete GC:<\/span><\/p>\n

1) via events – when we have processed a full sequence of events for a GC, we fire an event (not to be confused with an ETW event! This is just a c# event);<\/span><\/p>\n

2) via checking for the isComplete field in GCInformation. The user can do this in the last ETW event in the sequence (which is the GCHeapStats event). After he invoked our delegate to process this event<\/em>, isComplete is set to true unless we did not see the full sequence. Not seeing the full sequence usually happens at the beginning of the trace. Occasionally I’ve also seen that we miss an event in this sequence.<\/span><\/p>\n

User could use this for real-time or post processing. During real-time processing, the user could choose to perform some action when he sees an “interesting” GC, eg, when a GC is just completed, he checks and sees that the duration is >1s, he then stops his ETW collection and saves the events to a file for someone to investigate.<\/span><\/p>\n

Input<\/span><\/p>\n

Users will provide the SDK with the event data to interpret. If you use TraceEvent you automatically get the event data; if you choose to implement your own you need to implement the interfaces that are defined in the contracts. So I would strongly encourage you to just use TraceEvent.<\/span><\/p>\n

The following events are mandatory<\/span><\/p>\n

Process Start\/Stop\/DCStart\/DCStop events from the Kernel provider<\/span><\/p>\n

GC is per process which means there’s per process state we’d like to keep. These events give us the process info such as their PIDs and names.<\/span><\/p>\n

GC informational level events from CLR public\/private providers<\/span><\/p>\n

The following events are optional<\/span><\/p>\n

GC verbose level events from CLR public\/private providers<\/span><\/p>\n

If these events are present, more analysis will light up.<\/span><\/p>\n

API<\/span><\/p>\n

Contracts <\/span><\/strong><\/span>(gc-event-contracts.dll (name is subject to change))<\/span><\/span><\/p>\n

The event layout definition<\/span><\/p>\n

interface<\/span> IGCStartTraceData<\/span><\/p>\n

{<\/span><\/p>\n

    int<\/span><\/span> Count { get; }<\/span><\/p>\n

    GCReason Reason { get; }<\/span><\/p>\n

    int<\/span><\/span> Depth { get; }<\/span>
<\/span><\/p>\n

    \/\/ …<\/span><\/p>\n

}<\/span><\/p>\n

interface <\/span>IGCEndTraceData<\/span><\/p>\n

{<\/span><\/p>\n

    int<\/span><\/span> Count { get; }<\/span><\/p>\n

    int<\/span><\/span> Depth { get; }<\/span>
<\/span><\/p>\n

    \/\/ …<\/span><\/p>\n

}<\/span><\/p>\n

Currently the layout definitions are in TraceEvent. In order to have both TraceEvent.dll (or some other tool that listens to ETW events) and the GLAD SDK refer to these event layouts, we need a common definition. TraceEvent.dll will implement getting the fields of events and GLAD will refer to these fields in order to calculate the GC information.<\/span><\/p>\n

The event handlers in the parser<\/span><\/p>\n

We need to expose the definition of event handlers to allow GLAD to hook up all the events it processes (we don’t want users to get a partially processed set which causes the GC information to not be filled in fully).<\/span><\/p>\n

interface <\/span>IGCEventParser<\/span><\/p>\n

{<\/span><\/p>\n

    event Action<IGCStartTraceData> GCStart;<\/span><\/p>\n

    event Action<IGCEndTraceData> GCEnd;<\/span><\/p>\n

    \/\/ other event handlers.<\/span><\/p>\n

\u3000   \/\/ this invokes the actual processing of the events<\/span><\/p>\n

         bool<\/span><\/span> Process(); <\/span><\/p>\n

}<\/span><\/p>\n

These are in its own dll so TraceEvent.dll and glad.dll can both reference it.<\/span><\/p>\n

Implementation <\/span><\/strong><\/span>(glad.dll (name is subject to change))<\/span><\/p>\n

The following sections are for implementation and will be in glad.dll.<\/span><\/p>\n

1) Delegates for ETW event processing<\/span><\/strong><\/p>\n

\/\/ GC*Data describes the ETW event layout.<\/span><\/p>\n

delegate <\/span>void<\/span><\/span> OnGCStart(IGCStartTraceData data);<\/span><\/p>\n

delegate <\/span>void<\/span><\/span> OnGCEnd(IGCEndTraceData data);<\/span>
<\/span><\/p>\n

\/\/ delegates for other events.<\/span>
<\/span><\/span><\/span><\/p>\n

class <\/span>GCProcessor<\/span><\/p>\n

{<\/span><\/p>\n

    \/\/ user can overwrite this.<\/span>    <\/span><\/span><\/p>\n

    public <\/span><\/span>virtual<\/span><\/span> OnGCStartHandler(IGCStartTraceData data);<\/span><\/p>\n

    public <\/span><\/span>virtual<\/span><\/span> OnGCEndHandler(IGCEndTraceData data);<\/span>
<\/span><\/p>\n

    \/\/ other events.<\/span><\/p>\n

}<\/span><\/p>\n

2) The list of GCInformation <\/span><\/strong>that describes the processed info for all the GCs in a particular process.<\/span><\/p>\n

GCInformation allows the user to attach additional info for each GC. This is useful internally for us to experiment with certain things before we publish it in GLAD. Eg, we are doing some additional processing, we can iterate on that some on our side; when it’s all tested we take it out of userData and publish it.<\/span><\/p>\n

\/\/ This is the info for a particular GC<\/span><\/p>\n

class <\/span>GCInformation<\/span><\/p>\n

{<\/span> <\/p>\n

    public <\/span><\/span>bool<\/span><\/span> isComplete;<\/span>   <\/p>\n

    public <\/span><\/span>int<\/span><\/span> gcIndex;<\/span><\/p>\n

    public <\/span><\/span>double<\/span><\/span> durationMSec;<\/span>
<\/span><\/p>\n

    \/\/ other GC fields<\/span><\/p>\n

    \/\/ User might want to hang some info off of each GC.<\/span><\/span><\/p>\n

    public<\/span><\/span> object userData;<\/span><\/p>\n

}<\/span><\/p>\n

\/\/ This is the GCs for that particular process<\/span><\/p>\n

class<\/span> GCInformationPerProcess<\/span><\/p>\n

{<\/span><\/p>\n

    public <\/span><\/span>int<\/span><\/span> processID;<\/span><\/p>\n

    public <\/span><\/span>int<\/span><\/span> currentGCIndex;<\/span><\/p>\n

    public<\/span><\/span> List<GCInformation> listGCInfo;<\/span>
<\/span><\/p>\n

    \/\/ …<\/span><\/p>\n

}<\/span>
<\/span><\/span><\/strong><\/strong><\/span><\/p>\n

3) The class for the user to invoke GLAD’s processing.<\/strong><\/span><\/p>\n

class <\/span>GCProcessor<\/span><\/p>\n

{<\/span><\/p>\n

    public <\/span><\/span>virtual<\/span><\/span> OnGCStartHandler(IGCStartTraceData data);<\/span><\/p>\n

    public <\/span><\/span>virtual<\/span><\/span> OnGCEndHandler(IGCEndTraceData data);<\/span>
<\/span><\/p>\n

    \/\/ event handers for other events.<\/span><\/p>\n

\u3000<\/p>\n

    \/\/ hooks up all events that we process.<\/span><\/p>\n

    public<\/span><\/span> GCProcessor(IGCEventParser p)<\/span><\/p>\n

    {<\/span><\/p>\n

        p.GCStart += OnGCStartHandler;<\/span><\/p>\n

        p.GCEnd += OnGCEndHandler;<\/span><\/p>\n

        \/\/ other events.<\/span><\/p>\n

    }<\/span><\/p>\n

    \/\/ If you are not interested in processing any of the GC events, you<\/span><\/p>\n

    \/\/ can simply get the results after processing.<\/span><\/p>\n

    public<\/span><\/span> List<GCInformationPerProcess> GetResults()<\/span><\/p>\n

    {<\/span><\/p>\n

        \/\/ return the list of processes with their GC info.<\/span><\/p>\n

    }<\/span><\/p>\n

    \/\/ If you are interested in additional processing, you can get the<\/span><\/p>\n

    \/\/ current GC and do your processing there.<\/span><\/p>\n

    public<\/span><\/span> GCInformation GetCurrentGC(int<\/span><\/span> ProcessID)<\/span><\/p>\n

    {<\/span><\/p>\n

        \/\/ returns the current GC in this process.<\/span><\/p>\n

    }<\/span><\/p>\n

}<\/span><\/p>\n

4) Event to notify users of a GC sequence processing completion<\/strong><\/span><\/p>\n

\/\/ When we have processed the full sequence for a GC, we fire an event.<\/span><\/p>\n

\/\/ sender would be of type GCInformationPerProcess.<\/span><\/p>\n

delegate<\/span> void<\/span><\/span><\/span> GCCompletionEventHandler(object<\/span><\/span><\/span> sender, EventArgs<\/span><\/span><\/span> e);<\/span>
<\/span><\/p>\n

class <\/span>GCProcessor<\/span><\/span><\/span>
<\/span><\/span><\/span><\/span><\/p>\n

{<\/span>   <\/p>\n

    public <\/span><\/span><\/span>event <\/span><\/span><\/span>EventHandler<\/span><\/span><\/span> OnGCSequenceCompletedHandler;<\/span><\/p>\n

}<\/span><\/p>\n

User scenarios<\/span><\/p>\n

1) User doesn’t do any processing of GC events on his own. But he’s interested in getting the GC completion notification via our event.<\/span><\/p>\n

\/\/ ****in GLAD implementation****<\/span><\/p>\n

\/\/ in the GCHeapStats ETW event processor<\/span><\/p>\n

currentGC.isComplete = <\/span>true<\/span><\/span>;<\/span><\/p>\n

OnGCSequenceCompletedHandler (GCInformationPerProcess, null);<\/span><\/p>\n

\/\/ ****in user code****<\/span><\/p>\n

void <\/span>GCCompletionEventHandler(object sender, EventArgs e)<\/span><\/p>\n

{<\/span><\/p>\n

    GCInformationPerProcess gcProcess = sender as GCInformationPerProcess;<\/span><\/p>\n

    GCInformation currentGC = gcProcess.listGCInfo[currentGCIndex];<\/span><\/p>\n

    myLog.WriteLine(“Process {0}: GC {1} took {2}ms”, gcProcess.processID, currentGC.gcIndex, currentGC.durationMSec);<\/span><\/p>\n

 <\/p>\n

    if<\/span><\/span> (current.durationMSec > 1000)<\/span><\/p>\n

    {<\/span><\/p>\n

        \/\/ stop collecting.<\/span><\/p>\n

    }<\/span><\/p>\n

}<\/span><\/p>\n

\/\/ source is the event parser.<\/span><\/p>\n

GCProcessor gcProcessor = <\/span>new<\/span><\/span> GCProcessor(source);<\/span><\/p>\n

gcProcessor.OnGCSequenceCompletedHandler += GCCompletionEventHandler;<\/span><\/p>\n

source.Process();<\/span><\/p>\n

2) User wants to do some processing with selected GC events.<\/span><\/p>\n

\/\/ ****in user code****<\/span><\/p>\n

class<\/span> MyGCProcessor : GCProcessor<\/span><\/p>\n

{<\/span><\/p>\n

    public<\/span><\/span> MyGCProcessor (IGCEventParser p) : base (p)<\/span><\/p>\n

    {<\/span><\/p>\n

    }<\/span><\/p>\n

    public<\/span><\/span> override void<\/span><\/span> OnGCStart(IGCStartTraceData data)<\/span><\/p>\n

    {<\/span><\/p>\n

        \/\/ Note for doing additional processing, you always need to call<\/span><\/p>\n

        \/\/ base event handler first. This is important.<\/span><\/p>\n

        base.OnGCStart(data);<\/span><\/p>\n

        GCInformation gcInfo = GetCurrentGC(data.ProcessID);<\/span><\/p>\n

        gcInfo.userData = <\/span>new<\/span><\/span> MyGCInformation();<\/span>
<\/span><\/p>\n

        \/\/ do some additional processing here.<\/span><\/p>\n

    }<\/span><\/p>\n

}<\/span><\/p>\n

 <\/p>\n

 <\/p>\n","protected":false},"excerpt":{"rendered":"

Holidays are almost upon us. Last year around Christmas time I wrote a set of GC ETW blog entries to help with diagnosing GC heap related issues. This year I want to discuss taking that a (big) step further and making an SDK that does the analysis for you using these ETW events – so […]<\/p>\n","protected":false},"author":3542,"featured_media":58792,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[685],"tags":[3011,108],"class_list":["post-451","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-dotnet","tag-maoniposts","tag-performance"],"acf":[],"blog_post_summary":"

Holidays are almost upon us. Last year around Christmas time I wrote a set of GC ETW blog entries to help with diagnosing GC heap related issues. This year I want to discuss taking that a (big) step further and making an SDK that does the analysis for you using these ETW events – so […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/451","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/users\/3542"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/comments?post=451"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/451\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/media\/58792"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/media?parent=451"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=451"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=451"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}