{"id":585,"date":"2018-09-09T22:52:44","date_gmt":"2018-09-09T22:52:44","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/?p=585"},"modified":"2021-09-29T15:56:12","modified_gmt":"2021-09-29T22:56:12","slug":"glad-part-2","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/dotnet\/glad-part-2\/","title":{"rendered":"GLAD Part 2"},"content":{"rendered":"

2 years ago I had a blog entry to introduce the GLAD<\/a> (GC Latency Analysis and Diagnostics) library which provides much more insight into the GC heap performance than perf counters and takes care of interpreting raw GC ETW events so our users don’t have to do that work themselves. Since then I have not heard too much usage from our customers \ud83d\ude1b So either not many people are using it, or people are and they\u2019ve had no problem with it so I don\u2019t hear from them (secretly hoping it\u2019s the latter\u2026).<\/p>\n

In any case, I thought I\u2019d give another example that uses GLAD to get GC info at real time<\/i> \u2013 hopefully this will encourage folks who are interested in looking at GC perf but haven’t taken advantage of GLAD to take another look and incorporate it into their diagnostics pipeline. You just need to reference the TraceEvent dll (ie, Microsoft.Diagnostics.Tracing.TraceEvent.dll; I found that you also need Microsoft.Diagnostics.FastSerialization.dll in the same dir). <\/p>\n

If you have used TraceEvent you probably have looked at the TraceEvent Programmers\u2019 Guide<\/a> doc in the PerfView repo. Most people know that you can use TraceEvent to decode an ETW trace after you collect such a trace; but it can also do real time processing (which really is just a feature with ETW \u2013 you could use plain Win32 ETW API and do either real time or post processing on ETW events) which the doc specifically talks about in the \u201cReal Time Processing of Events\u201d section. But we made it even easier than that for you so you don\u2019t have to care about noticing when an individual GC is finished processing to get the processed info – you can just use the processed info in the TraceLoadedDotNetRuntime.GCEnd callback. Below is a method that takes a PID and prints out the GC start and end with the pause time as each GC happens (obviously the pause time is only available at the GC end – at that point a full GC event sequence is completely and the pause time info has been calculated and is available):<\/p>\n

\n        public static void RealTimeProcessing(int pid)\n        {\n            Console.WriteLine(\"Monitoring process {0}\", pid);\n\n            using (var session = new TraceEventSession(\"My Session\"))\n            {\n                var source = session.Source;\n                source.NeedLoadedDotNetRuntimes();\n                source.AddCallbackOnProcessStart(delegate (TraceProcess proc)\n                {\n                    proc.AddCallbackOnDotNetRuntimeLoad(delegate (TraceLoadedDotNetRuntime runtime)\n                    {\n                        runtime.GCStart += delegate (TraceProcess p, TraceGC gc)\n                        {\n                            if (p.ProcessID == pid)\n                            {\n                                Console.WriteLine(\"proc {0}: GC#{1} start at {2:0.00}ms\", p.ProcessID, gc.Number, gc.PauseStartRelativeMSec);\n                            }\n                        };\n                        runtime.GCEnd += delegate (TraceProcess p, TraceGC gc)\n                        {\n                            if (p.ProcessID == pid)\n                            {\n                                Console.WriteLine(\"proc {0}: GC#{1} end, paused for {2:0.00}ms)\",\n                                p.ProcessID, gc.Number, gc.PauseDurationMSec);\n                            }\n                        };\n                    });\n                });\n\n                session.EnableProvider(ClrTraceEventParser.ProviderGuid);\n\n                source.Process();\n\n                foreach (var proc in source.Processes())\n                {\n                    Console.WriteLine(\"{0}\", proc.ToString());\n                }\n            }\n        }\n<\/pre>\n
(I just noticed that p.Name doesn’t seem to work, so I am using the pid instead)<\/p>\n
Below is a sample output – I ran a test that keeps doing GCs and ran this tool. It prints out info about each one as it starts and ends:<\/p>\n
\nE:\\tests\\RealtimeMon\\realmon\\realmon\\bin\\Release>realmon 11112\nMonitoring process 11112\nproc 11112: GC#30 start at 330.29ms\nproc 11112: GC#30 end, paused for 213.52ms)\nproc 11112: GC#31 start at 1014.82ms\nproc 11112: GC#31 end, paused for 22.70ms)\nproc 11112: GC#32 start at 1453.19ms\nproc 11112: GC#32 end, paused for 29.50ms)\nproc 11112: GC#33 start at 1826.29ms\nproc 11112: GC#33 end, paused for 30.10ms)\nproc 11112: GC#34 start at 2182.78ms\nproc 11112: GC#34 end, paused for 34.25ms)\nproc 11112: GC#35 start at 2522.57ms\nproc 11112: GC#35 end, paused for 30.29ms)\nproc 11112: GC#36 start at 3290.49ms\nproc 11112: GC#36 end, paused for 120.48ms)\nproc 11112: GC#37 start at 4285.94ms\nproc 11112: GC#37 end, paused for 41.22ms)\nproc 11112: GC#38 start at 4617.87ms\nproc 11112: GC#38 end, paused for 17.90ms)\nproc 11112: GC#39 start at 4938.86ms\n^C\n<\/pre>\n
There are many interesting cases for diagnostics and we\u2019d love to get your help to build up a repertoire, eg if you used it to build a cool GC perf diag tool, or found a problem and made a fix it would be greatly appreciated if you share with the rest of us!  <\/p>\n","protected":false},"excerpt":{"rendered":"
2 years ago I had a blog entry to introduce the GLAD (GC Latency Analysis and Diagnostics) library which provides much more insight into the GC heap performance than perf counters and takes care of interpreting raw GC ETW events so our users don’t have to do that work themselves. Since then I have not […]<\/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-585","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-dotnet","tag-maoniposts"],"acf":[],"blog_post_summary":"
2 years ago I had a blog entry to introduce the GLAD (GC Latency Analysis and Diagnostics) library which provides much more insight into the GC heap performance than perf counters and takes care of interpreting raw GC ETW events so our users don’t have to do that work themselves. Since then I have not […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/585","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=585"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/585\/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=585"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=585"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=585"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}