{"id":23182,"date":"2014-12-25T18:46:46","date_gmt":"2014-12-25T18:46:46","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/2014\/12\/25\/gc-etw-events-3\/"},"modified":"2021-09-30T16:10:52","modified_gmt":"2021-09-30T23:10:52","slug":"gc-etw-events-3","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/dotnet\/gc-etw-events-3\/","title":{"rendered":"GC ETW Events – 3"},"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><\/p>\n

GC ETW Events – Part 3<\/span><\/a> (this post)<\/span><\/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

In the last blog entry we looked at a particular GC trigger reason \u2013 <\/span>InducedNotForced<\/span><\/em> GCs. There are 2 other triggered reasons for induced GCs are:<\/span><\/p>\n

InducedLowMemory<\/span><\/em> \u2013 GC subscribes to the low memory notification from the OS and when the OS notifies us that \u201cthe memory is low on the machine\u201d a GC is induced; or if this is a hosted process and the host indicates we are low on memory, we also induce a GC.<\/span><\/p>\n

Induced<\/span><\/em> \u2013 this is your \u201ccommon\u201d case of induced GCs, usually it comes from the user code that calls GC.Collect (as I mentioned in the last blog entry if the user calls GC.Collect and passes false as blocking, it would show up as InducedNotForced).<\/span><\/p>\n

The other types of trigger reasons are because of allocations. In <\/span>Using GC Efficiently \u2013 Part 1<\/span><\/a> I talked about the 3 situations a GC is triggered. The most common situation is managed allocations. Out of those reasons the most common you\u2019d see (and want to see) is <\/span>AllocSmall<\/span><\/em> \u2013 this is saying the gen0 threshold is exceeded. If the most common one you see is say <\/span>AllocLarge<\/span><\/em> it most likely indicates a problem \u2013 it\u2019s saying your GC was triggered because you exceeded the threshold for LOH allocating large objects. And as we know that triggers a full GC and keeping triggering full GCs is usually a recipe for performance problems. Other trigger reasons due to allocations are <\/span>OutOfSpaceSOH<\/span><\/em> and <\/span>OutOfSpaceLOH<\/span><\/em> \u2013 you see these much less frequently than AllocSmall and AllocLarge \u2013 these are for when you are close to physical space limit (eg, if we are getting close to the end of the ephemeral segment).<\/span><\/p>\n

If you looked far enough you\u2019ll notice a table called \u201cCondemned reasons for GCs\u201d. So what is the difference between \u201ctrigger reason\u201d and \u201ccondemned reason\u201d?<\/span><\/p>\n

When I first started working on the .NET GC there was lots of confusion as to when\/how a GC is triggered. I remember one of the misunderstandings was to explain how a gen2 GC was triggered. The explanation was \u201cGC will do a gen0 GC first; if that\u2019s not enough, it will do a gen1 GC; if that\u2019s still not enough, it will do a gen2 GC\u201d. Well, that would be quite inefficient but it does serve as good context info for explaining the difference between those 2 reasons. \u201cTrigger reason\u201d is how a GC starts or comes into existence. If the most common reason for a GC to start is due to allocating on the SOH, that GC would start as a gen0 GC (because the gen0 threshold was exceeded). Now <\/span>after<\/span><\/em> the GC starts, we then decide what generation we would actually collect. It might stay as a gen0 GC, or get escalated to a gen1 or even a gen2 GC \u2013 this is something we decide as one of the very first things we do in a GC. And factors that would cause us to escalate to a high generation GC are what we called \u201ccondemned reasons\u201d (so for a GC there\u2019s only one trigger reason but can be multiple condemned reasons).<\/span><\/p>\n

For the \u201cCondemned reasons for GC\u201d table it says<\/span><\/p>\n

This table gives a more detailed account of exactly why a GC decided to collect that generation. Hover over the column headings for more info.<\/span><\/em><\/p>\n

I won\u2019t repeat the info here but you can see the difference between the 2nd column (Initial Requested Generation) and the 3rd column (Final Generation). The former is the generation when the GC is triggered while the latter is after we went through the condemned reasons the generation we landed at. So the former is always <= the latter.<\/span><\/p>\n

Now let\u2019s take a look at other columns in the GC tables.<\/span><\/p>\n

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

These also have explanations of the columns so if you hover over the column header you will see what that column is for. The next 2 columns interesting to talk about are \u201cSuspend MSec\u201d and \u201cPause MSec\u201d. The \u201cPause MSec\u201d column is what tells you how long your threads were paused for due to GC. And \u201cSuspend MSec\u201d is part of this pause (this is usually a small number; if not then that would indicate a problem). Let me explain how these columns are calculated \u2013 it\u2019s useful to know because you could incoporate this into your perf automation framework as some of our internal teams do. One very useful thing you could measure with this is for your request latency you can tell exactly how much the GC pause contributed to it (and you can tell for example how often and how much GC pause is the problem for your longest requests).<\/span><\/p>\n

(suspension and resumption are explained <\/span>here<\/span><\/a>)<\/span><\/p>\n

The GC ETW events are documented <\/span>here<\/span><\/a>. And the relevant ones for pause time are (you can get the event ID and field description on the MSDN page):<\/span><\/p>\n

GCStart_V1 Event<\/span><\/em> <\/span><\/p>\n

\nGCEnd_V1 Event<\/span><\/em> <\/span><\/p>\n

\nGCSuspendEE_V1 Event<\/span><\/em> <\/span><\/p>\n

\nGCSuspendEEEnd_V1 Event<\/span><\/em> <\/span><\/p>\n

\nGCRestartEEBegin_V1 Event<\/span><\/em> <\/span><\/p>\n

\nGCRestartEEEnd_V1 Event<\/span><\/em><\/p>\n

In a typical blocking GC (this means all ephemeral GCs and full blocking GCs) the event sequence is very simple:<\/span><\/p>\n

GCSuspendEE_V1 Event <\/span><\/p>\n

\nGCSuspendEEEnd_V1 Event <\u2013 suspension is done<\/span><\/p>\n

\nGCStart_V1 Event <\/span><\/p>\n

\nGCEnd_V1 Event <\u2013 actual GC is done<\/span><\/p>\n

\nGCRestartEEBegin_V1 Event <\/span><\/p>\n

\nGCRestartEEEnd_V1 Event <\u2013 resumption is done.<\/span><\/p>\n

GCSuspendEE_V1 and GCSuspendEEEnd_V1 are for suspension; and GCRestartEEBegin_V1 and GCRestartEEEnd_V1 are for resumption.<\/span><\/p>\n

The Suspension MSec column is simply (timestamp of the GCSuspendEEEnd_V1 \u2013 timestamp of the GCSuspendEE_V1). We don\u2019t give you the time it takes to resume as it\u2019s very, very short. And the Pause MSec\u201d column is (timestamp of the GCRestartEEEnd_V1 \u2013 timestamp of the GCSuspendEE_V1) so this requires the longest possible pause introduced by this GC \u2013 \u201clongest possible\u201d is because there are threads that are running for part of the suspension and resumption.<\/span><\/p>\n

However for a background GC it\u2019s quite a bit more complicated. It is explained <\/span>here<\/span><\/a>:. It shows a background GC with one foreground GC happening during its duration. We know that all foreground GCs are ephemeral GCs which means they all follow the simple sequence we have above. If we add in the suspension\/resumption from the background GC itself it\u2019ll look like this:<\/span><\/p>\n

1) GCSuspendEE_V1 Event <\/span><\/p>\n

2) GCSuspendEEEnd_V1 Event<\/span><\/p>\n

3) GCStart_V1 Event <\u2013 BGC starts<\/span><\/p>\n

There might be a gen0 or gen1 GC happening here and if so you’d see this sequence<\/p>\n

GCStart_V1 Event <\u2013 gen0 or gen1 starts<\/span><\/p>\n

GCEnd_V1 Event <\u2013 gen0 or gen1 GC is done<\/span><\/p>\n

4) GCRestartEEBegin_V1 Event <\/span><\/p>\n

\n5) GCRestartEEEnd_V1 Event <\u2013 done with the initial suspension<\/span><\/p>\n

There might be 0 or more foreground gen0 or gen1 GC happening here and if so you’d see this sequence<\/p>\n

GCSuspendEE_V1 Event <\/span><\/p>\n

\nGCSuspendEEEnd_V1 Event <\u2013 suspension for foreground GC is done<\/span><\/p>\n

\nGCStart_V1 Event <\/span><\/p>\n

\nGCEnd_V1 Event <\u2013 foreground GC is done<\/span><\/p>\n

\nGCRestartEEBegin_V1 Event <\/span><\/p>\n

\nGCRestartEEEnd_V1 Event <\u2013 resumption for foreground GC is done<\/span><\/p>\n

6) GCSuspendEE_V1 Event <\/span><\/p>\n

\n7) GCSuspendEEEnd_V1 Event <\/span><\/p>\n

\n8) GCRestartEEBegin_V1 Event <\/span><\/p>\n

\n9) GCRestartEEEnd_V1 Event <\u2013 done with BGC\u2019s own suspension<\/span><\/p>\n

Again, there might be 0 or more foreground gen0 or gen1 GC happening here<\/p>\n

10) GCEnd_V1 Event <\u2013 BGC ends<\/span><\/p>\n

That concludes our pause data explanation.<\/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 GC ETW Events – Part 3 (this post) GC ETW Events – Part 4 Processing GC ETW Events Programmatically with the GLAD Library In the last blog entry we looked at a particular GC trigger reason \u2013 InducedNotForced GCs. […]<\/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-23182","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 GC ETW Events – Part 3 (this post) GC ETW Events – Part 4 Processing GC ETW Events Programmatically with the GLAD Library In the last blog entry we looked at a particular GC trigger reason \u2013 InducedNotForced GCs. […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23182","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=23182"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23182\/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=23182"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=23182"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=23182"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}