{"id":725,"date":"2019-04-08T18:29:46","date_gmt":"2019-04-08T18:29:46","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/?p=725"},"modified":"2021-09-29T11:54:36","modified_gmt":"2021-09-29T18:54:36","slug":"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","status":"publish","type":"post","link":"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\/","title":{"rendered":"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)"},"content":{"rendered":"<p>I\u2019ve been talking about doing managed heap performance analysis with ETW events for ages because ETW is just such a powerful tool. It has a well defined format so many components, from kernel modes to user mode ones, all emit ETW events which means you can have tools that just know how to parse the event format and correlate them. At Microsoft perf teams have analysis that tells you \u201cthis long request took X ms and X0 ms was due to a kmode component0, X1 ms was due to a umode component1 and etc\u201d by interpreting ETW events. This is immensely useful.<\/p>\n<p>However, you do need admin privilege to turn on ETW events which is not always desirable. Also I myself am moving part of my development to Linux due to the cross-plat nature of coreclr so I started to look at other eventing mechanisms more closely, from both GC\u2019s and customers\u2019 POV. I had heard of <a href=\"https:\/\/docs.microsoft.com\/en-us\/dotnet\/api\/system.diagnostics.tracing.eventsource?view=netframework-4.7.2\">EventSource<\/a>\/<a href=\"https:\/\/docs.microsoft.com\/en-us\/dotnet\/api\/system.diagnostics.tracing.eventlistener?view=netframework-4.7.2\">EventListener<\/a> before but had never used it myself. These had existed on desktop CLR for years and managed components were using them to fire events. In coreclr 2.2 we made it possible to obtain the CLR runtime events (eg. the GC events) via this mechanism. And I was talking to our diagnostics expert <a href=\"https:\/\/github.com\/noahfalk\">Noah Falk<\/a> who mentioned it\u2019s super simple to get the GC events if that\u2019s all I cared about. Now, for GC\u2019s own perf analysis, I absolutely do care about other events (mostly kernel events). But for customers, it\u2019s usually sufficient to get just the informational level GC events. It turned out it\u2019s literally 10 lines of code to just get the GC events, in process, in managed code \u2013<\/p>\n<p><script src=\"https:\/\/gist.github.com\/Maoni0\/f8a64179f8a5573cac645cb2fdcb3dfd.js\"><\/script><\/p>\n<p>And really the main part is just line 7 and 8. <\/p>\n<p>(I was tempted to say \u201c2 lines\u201d in the title but I resisted)<\/p>\n<p>These 2 lines say to enable keyword 1 (which is the keyword for GC), level Informational in the CLR provider (Microsoft-Windows-DotNETRuntime).<\/p>\n<p>And you can choose to process any of these GC events. As a simple example, if I want to print out to the console each GC with its duration, I can add another method in my SimpleEventListener class:<\/p>\n<p><script src=\"https:\/\/gist.github.com\/Maoni0\/871164f54c18266f55009a5f689ba3ad.js\"><\/script><\/p>\n<p>You could print out eventData.EventName to see other GC events. The list is also documented on MSDN.<\/p>\n<p>Of course on production you do not want to print to console. It would be an improvement to log to a file but why stop there when you could do things like dynamically enabling and disabling these events easily? Let\u2019s say I want to disable GC events after the first 100 GCs, I can save the event source in OnEventSourceCreated to eventSourceDotNet and in OnEventWritten where I\u2019m handling the GCEnd I can do:<\/p>\n<pre>\r\n        if (gcIndex &gt;= 100)\r\n            DisableEvents(eventSourceDotNet);\r\n<\/pre>\n<p>Then GC events are disabled. A very common thing perf folks do is \u201clet\u2019s log for X mins every Y hours\u201d so they can use this to enable\/disable whenever they need to. <\/p>\n<p>You could also do stuff like \u201cif I see &gt; X gen2 GCs\/minute, I will start logging GC events and perhaps even enable more events or even more providers to help me diagnose problems\u201d. <\/p>\n<p>Of course you don\u2019t need to save anything to text logs, you can for example choose to write whatever info you get from these events to a buffer that gets flushed periodically to a location of your choice. Do whatever you like, the world is your oyster \uf04a<\/p>\n<p>There are of course other event source providers. You can get the available ones in OnEventSourceCreated &#8211;<\/p>\n<pre>\r\nprotected override void OnEventSourceCreated(EventSource eventSource)\r\n{\r\n    \/\/ This shows all providers in your process.\r\n    Console.WriteLine(eventSource.Name);\r\n}\r\n<\/pre>\n<p>In my minimal test that just allocates byte arrays and with the SimpleEventListener class I see 3 providers:<\/p>\n<pre>\r\nMicrosoft-Windows-DotNETRuntime\r\nSystem.Threading.Tasks.TplEventSource\r\nSystem.Runtime\r\n<\/pre>\n<p>And of course you could get other runtime events from the DotNETRuntime provider if you like \u2013 I\u2019ve included some other keywords in the full example below along with the output. Note that I did not need to create a thread \u2013 a thread is created for you if needed so you don\u2019t need to worry about it. With ETW you\u2019d need to handle that yourself.<\/p>\n<p><script src=\"https:\/\/gist.github.com\/Maoni0\/e7e4c94aa0a23fb096ff09a5b84f9a48.js\"><\/script><\/p>\n<p>Output<\/p>\n<pre>\r\nF:\\coreclr-event\\bin\\tests\\Windows_NT.x64.Release\\Tests\\Core_Root&gt;corerun Collect0.exe 1\r\nKEYWORD= 1\r\nMicrosoft-Windows-DotNETRuntime\r\nSystem.Threading.Tasks.TplEventSource\r\nSystem.Runtime\r\nGC#1 took 0.677ms\r\nGC#2 took 0.313ms\r\nGC#3 took 0.030ms\r\nGC#4 took 0.021ms\r\nGC#5 took 0.018ms\r\ntook 6661ms\r\nTotal Count= 70\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"<p>I\u2019ve been talking about doing managed heap performance analysis with ETW events for ages because ETW is just such a powerful tool. It has a well defined format so many components, from kernel modes to user mode ones, all emit ETW events which means you can have tools that just know how to parse the [&hellip;]<\/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],"class_list":["post-725","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-dotnet","tag-maoniposts"],"acf":[],"blog_post_summary":"<p>I\u2019ve been talking about doing managed heap performance analysis with ETW events for ages because ETW is just such a powerful tool. It has a well defined format so many components, from kernel modes to user mode ones, all emit ETW events which means you can have tools that just know how to parse the [&hellip;]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/725","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=725"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/725\/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=725"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=725"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=725"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}