{"id":23183,"date":"2014-12-25T00:42:46","date_gmt":"2014-12-25T00:42:46","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/2014\/12\/25\/gc-etw-events-2\/"},"modified":"2021-09-30T16:10:56","modified_gmt":"2021-09-30T23:10:56","slug":"gc-etw-events-2","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/dotnet\/gc-etw-events-2\/","title":{"rendered":"GC ETW events – 2"},"content":{"rendered":"

GC ETW series –<\/span><\/strong><\/p>\n

GC ETW Events – Part 1<\/span><\/a><\/p>\n

GC ETW Events – Part 2<\/span><\/a> (this post)<\/span><\/p>\n

GC ETW Events – Part 3<\/span><\/a><\/p>\n

GC ETW Events – Part 4<\/span><\/a><\/p>\n

Processing GC ETW Events Programmatically with the GLAD Library<\/span><\/a><\/p>\n

\n

Before we continue from where we left off in the last blog entry I wanted to give a performance tip on managed memory analysis. As some of you who have already tried out Perfview you probably noticed it has a Heap Snapshot feature (in the PerfView UI, if you click on Memory\\Take Heap Snapshot) which displays you the snapshot of the managed heap, ie, types in the heap and how many instances there are of each type and how they refer to each other. Unless you have done some other analysis that gives you a good reason to start from here you normally don\u2019t start from here (yes, even if you know heap size is the problem you still shouldn\u2019t start from here unless you have other supporting evidence, such as you are getting OOM). Let me explain why.<\/span><\/p>\n

Normally when someone wants to look at managed memory, he does so due to one or both of the following reasons:<\/span><\/p>\n

1) pause time issue (eg, he probably noticed that his process is running slow and has looked at perf counters and noticed % time in GC is high; or his request is timing out because it\u2019s not processed in a sufficient amount of time);<\/span><\/p>\n

2) memory issue (eg, he probably noticed that his process\u2019s private bytes perf counter shows a high value);<\/span><\/p>\n

Now, before we dive into the reason why I said looking at the heap snapshot shouldn\u2019t be the place to start normally, let\u2019s refresh a few things about the .NET GC as they will be essential in understanding them.<\/span><\/p>\n

.NET GC is a generational GC. The managed heap is divided into 3 generations \u2013 gen0, gen1 and gen2. Gen2 is the oldest generation meant for long lived data whereas gen0 and gen1 are what we call \u201cephemeral generations\u201d. The youngest generation, gen0, is to accommodate newly allocated objects (I am leaving out large objects for now) and gen1 acts like the buffer between gen0 and gen2 to accommodate the inflight data when we do a GC.<\/span><\/p>\n

This means we do 2 types of GCs \u2013 ephemeral GCs and full GCs, the former collects only ephemeral generations and the latter collects the whole heap, ie, gen0, 1 and 2. So the GC pause time is contributed by these GCs, not just the full GCs. So when you have a pause time issue, it doesn\u2019t mean you only need to look at full GCs \u2013 you need to look at what kind of GCs you did and what their pause times were. It doesn\u2019t even mean for the longest individual GC pauses you should always look at full GCs because full GCs can be done concurrently, which means you could have gen2 GCs whose pauses are shorter than ephemeral GCs. And even if full GCs did have longest individual pauses, it still doesn\u2019t necessarily mean you should only look at them because you might be doing these GCs very infrequently, and ephemeral GCs actually contribute to most of the GC pause time if the total GC pauses are your problem. So instead of assuming which GCs to look at, since we provide PerfView for you to collect GC ETW events which accurately tell you what kind of GCs you did, their pause times, and other relevant info, why not use it, right? \ud83d\ude42<\/span><\/p>\n

When you look at the heap snapshot you will see all the objects on the heap (well, actually not all but all that\u2019re representitive) and you might see one type of objects that take up the biggest percentage on the heap so you might then be trying to reduce that type of objects. But that might not be your problem because that may only reduce full blocking GC pauses but not necessarily other types of GCs. There are other possibilities \u2013 it could be that GCs are triggered too often (and most of which are gen0 GCs); it could be that gen2 objects do contribute to the ephemeral GC collection time but not the type that takes up the biggest percentage. Again, you should figure out what is causing problems before immediately trying to reduce the # of some objects.<\/span><\/p>\n

Hopefully by now I have convinced you that you should be taking the look at GCStats, let\u2019s look at it in more detail.<\/span><\/p>\n

The first table is \u201cGC Rollup By Generation\u201d. The first thing jumping out at us about this table is the Induced column:<\/span><\/p>\n

<\/span>\"img\" <\/span><\/a><\/p>\n

Most of time we\u2019d expect to see all 0\u2019s in this column but in this case this is not true! Not only is it not true, out of the 30 GCs a big percentage, 23%, is induced GCs! This means we should at least take a look at these GCs see if they are also taking up a big chunk of the pause time. If that is the case, and pause time is a problem, that means we should figure out how these GCs were induced. In our case I am seeing<\/span><\/p>\n

% Time paused for Garbage Collection: 7.1%<\/span><\/p>\n

which means if we cared about this process\u2019s performance GC seems like something interesting to look at. So let\u2019s take a look at the \u201cAll GC Events\u201d table and pay attention to the GCs whose \u201cTrigger Reason\u201d column says Induced*. InducedNotForced means someone asked to trigger a GC, and it\u2019s up to GC to decide how it\u2019s done \u2013 for gen0 and gen1 GCs it makes no difference to say it\u2019s forced or not as they are always done as blocking. For gen2 it\u2019s up to GC to decide to do them as background GCs or full blocking GCs.<\/span><\/p>\n

In our case the induced GCs, even though their pause times don\u2019t seem particularly long, but since the average pauses aren\u2019t that long, these GCs do add up. So it does make sense to take a closer look. So let\u2019s figure out who induced these GCs. Because this requires call stack info we\u2019ll need to take another trace, repeating what we just ran while running perfview to collect more info. A simple way to get callstacks is to just run perfview with this commandline:<\/span><\/p>\n

perfview collect<\/span><\/p>\n

after we run this, I verified I am still seeing as many induced GC. I then open the trace in perfview, now I see there are a lot more options under the file name. This is because we have a lot more types of events and perfview can provide much more different types of analysis.<\/span><\/p>\n

The easiest way to get to the bottom of induced GCs is to get the stacks for this event called GC\/Triggered which is fired every time a GC is triggered. Let\u2019s click on the Events view and in the Filter textbox we type in tri which says to show us any events with \u201ctri\u201d in their names and that\u2019s enough to easily see the GC\/Triggered events. If you don\u2019t have this event, it means you are not running on a new enough version of the runtime. With the older version of the runtime you can still figure this out for workstation GC (which WDExpress process is using), however for server GC this is not really the right tool (which was the reason why we added the GC\/Triggered event).<\/span><\/p>\n

I\u2019ll use the GC\/Triggered event whose timestamp I highlighted as an example.<\/span><\/p>\n

\"img\" <\/span><\/a><\/p>\n

If I right click on it I see an option called Any stacks. Clicking on that shows me the stack for this event:<\/span><\/p>\n

<\/span>\"img\" <\/span><\/a><\/p>\n

It turned out that WPF (presentation core) calls Add\/RemoveMemoryPressure. The implementation of this API would trigger a non forced GC. Obviously calling A\/RMP too often could trigger too many GCs. Another way to trigger a non forced GC is if someone called the GC.Collect API that takes the following args:<\/span><\/p>\n

public static void Collect(int generation, GCCollectionMode mode, bool blocking);<\/code><\/p>\n

and passed false for the last arg.<\/span><\/p>\n

That\u2019s all for today and we will continue next time.<\/span><\/p>\n

Edited on 03\/01\/2020 to add the indices to GC ETW Event blog entries<\/span><\/em><\/p>\n","protected":false},"excerpt":{"rendered":"

GC ETW series – GC ETW Events – Part 1 GC ETW Events – Part 2 (this post) GC ETW Events – Part 3 GC ETW Events – Part 4 Processing GC ETW Events Programmatically with the GLAD Library Before we continue from where we left off in the last blog entry I wanted to […]<\/p>\n","protected":false},"author":3542,"featured_media":58792,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[685],"tags":[3011,108],"class_list":["post-23183","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-dotnet","tag-maoniposts","tag-performance"],"acf":[],"blog_post_summary":"

GC ETW series – GC ETW Events – Part 1 GC ETW Events – Part 2 (this post) GC ETW Events – Part 3 GC ETW Events – Part 4 Processing GC ETW Events Programmatically with the GLAD Library Before we continue from where we left off in the last blog entry I wanted to […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23183","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=23183"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23183\/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=23183"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=23183"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=23183"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}