{"id":23166,"date":"2007-01-12T00:03:00","date_gmt":"2007-01-12T00:03:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/maoni\/2007\/01\/12\/difference-between-perf-data-reported-by-different-tools-4\/"},"modified":"2021-10-04T16:33:39","modified_gmt":"2021-10-04T23:33:39","slug":"difference-between-perf-data-reported-by-different-tools-4","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/dotnet\/difference-between-perf-data-reported-by-different-tools-4\/","title":{"rendered":"Difference Between Perf Data Reported by Different Tools \u2013 4"},"content":{"rendered":"

.NET CLR Memory\\% Time in GC counter<\/EM> and !runaway on thread(s) doing GC<\/EM>.<\/SPAN><\/P>\n

The 2 common ways people use to look at the time spent in GC are the % Time in GC performance counter under .NET CLR Memory, and the CPU time displayed by the !runaway debugger command in cdb\/windbg<\/FONT><\/A>. What do they mean exactly? % Time in GC is calculated like this:<\/SPAN><\/P>\n

When the nth<\/SUP>GC starts (ie, after the managed threads are suspended and before the GC work starts), we record the timestamp at that time. Let\u2019s call this TA(n);<\/SPAN><\/P>\n

When nth <\/SUP>GC ends (ie, after the GC work is done and before we resume the managed threads), we record another timestamp. Let\u2019s call this TB(n);<\/SPAN><\/P>\n

So Time spent in this GC is TB(n) \u2013 TA(n). And the time since the last GC ended is TB(n) \u2013 TB(n-1). So % Time in GC is (TB(n) \u2013 TA(n)) \/ (TB(n) \u2013 TB(n-1)). <\/SPAN><\/P>\n

Since we only record the timestamps we don\u2019t actually discount the time when the thread was switched out \u2013 for example, if you are on a single proc machine and another process has a thread of the same priority (as the thread that\u2019s doing GC) that\u2019s also ready to run it may take away some time from the thread that\u2019s doing the GC. None the less it\u2019s a good approximation.<\/SPAN><\/P>\n

One common scenario where it\u2019s not a good approximation is when paging occurs. In this case you will see a very high % Time in GC but really the time that\u2019s actually spent doing GC work is low \u2018cause most of the time is spent doing IO. To verify if you hit this case you can look at the Memory\\Pages\/sec to see how much it\u2019s paging.<\/FONT><\/SPAN><\/P>\n

!runaway is more accurate in the sense that it does record the actual time spent on the threads. However I did observe 2 common mistakes when using !runaway to look at time spent in GC.<\/SPAN><\/P>\n

1) mistake \u201ctime spent on the GC thread(s)\u201d as \u201ctime spent in GC\u201d. <\/SPAN><\/P>\n

Let\u2019s take Server GC as an example. When a GC is needed the GC threads first perform the suspension work. Obviously this takes time. Sometimes it can take quite a bit time if you have many threads or some threads get stuck and it takes a long time to suspend them. <\/SPAN><\/P>\n

2) using the current !runaway output to judge how much time GC has taken without taking into count that some user threads have died. Besides looking at the User\/Kernel Mode time you may want to also look at Elapsed Time. The following output is from one of the issues I looked at:<\/SPAN><\/P>\n

Elapsed Time<\/SPAN><\/P>\n

  Thread       Time<\/SPAN><\/P>\n

   0:2094      0 days 11:57:10.406<\/SPAN><\/P>\n

   1:2098      0 days 11:57:10.152<\/SPAN><\/P>\n

   2:2044      0 days 11:57:09.898<\/SPAN><\/P>\n

   3:27cc      0 days 11:57:09.882<\/SPAN><\/P>\n

   4:20c0      0 days 11:57:09.597<\/SPAN><\/P>\n

  13:810       0 days 11:57:09.565<\/SPAN><\/P>\n

  12:21d4      0 days 11:57:09.565<\/SPAN><\/P>\n

  11:2308      0 days 11:57:09.565<\/SPAN><\/P>\n

  10:1d24      0 days 11:57:09.565<\/SPAN><\/P>\n

   9:23e0      0 days 11:57:09.565<\/SPAN><\/P>\n

   8:24d0      0 days 11:57:09.565<\/SPAN><\/P>\n

   7:2168      0 days 11:57:09.565<\/SPAN><\/P>\n

   6:2134      0 days 11:57:09.565<\/SPAN><\/P>\n

   5:2124      0 days 11:57:09.565<\/SPAN><\/P>\n

  14:570       0 days 11:57:08.582<\/SPAN><\/P>\n

  15:10fc      0 days 11:57:00.000<\/SPAN><\/P>\n

  16:1ac4      0 days 11:56:58.256<\/SPAN><\/P>\n

  17:1900      0 days 11:56:58.176<\/SPAN><\/P>\n

  18:1624      0 days 11:56:57.494<\/SPAN><\/P>\n

  19:11f8      0 days 10:35:01.881<\/SPAN><\/P>\n

  <\/SPAN>21:1620      0 days 0:41:45.017<\/SPAN><\/P>\n

  22:1cc8      0 days 0:37:30.496<\/SPAN><\/P>\n

  23:2de0      0 days 0:29:01.820<\/SPAN><\/P>\n

  24:2e10      0 days 0:29:01.711<\/SPAN><\/P>\n

  25:2d88      0 days 0:22:26.988<\/SPAN><\/P>\n

  26:1668      0 days 0:19:26.175<\/SPAN><\/P>\n

  27:2cb0      0 days 0:16:16.814<\/SPAN><\/P>\n

  29:2d1c      0 days 0:11:53.779<\/SPAN><\/P>\n

  28:1de8      0 days 0:11:53.779<\/SPAN><\/P>\n

  30:2ed4      0 days 0:11:35.466<\/SPAN><\/P>\n

  32:2030      0 days 0:11:22.544<\/SPAN><\/P>\n

  31:2084      0 days 0:11:22.544<\/SPAN><\/P>\n

  33:12b0      0 days 0:07:53.510<\/SPAN><\/P>\n

  35:28e4      0 days 0:03:13.801<\/SPAN><\/P>\n

  34:2654      0 days 0:03:13.801<\/SPAN><\/P>\n

  36:2d68      0 days 0:02:31.988<\/SPAN><\/P>\n

 <\/SPAN><\/P>\n

The orange lines are GC threads. They were created about 12 hours ago. The green lines are user threads and they were created 2 mins to 40mins ago. So naturally at the current state these user threads couldn\u2019t\u2019ve spent much time. <\/FONT><\/SPAN><\/P><\/p>\n","protected":false},"excerpt":{"rendered":"

.NET CLR Memory\\% Time in GC counter and !runaway on thread(s) doing GC. The 2 common ways people use to look at the time spent in GC are the % Time in GC performance counter under .NET CLR Memory, and the CPU time displayed by the !runaway debugger command in cdb\/windbg. What do they mean […]<\/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":[322,3011,108],"class_list":["post-23166","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-dotnet","tag-debugging","tag-maoniposts","tag-performance"],"acf":[],"blog_post_summary":"

.NET CLR Memory\\% Time in GC counter and !runaway on thread(s) doing GC. The 2 common ways people use to look at the time spent in GC are the % Time in GC performance counter under .NET CLR Memory, and the CPU time displayed by the !runaway debugger command in cdb\/windbg. What do they mean […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23166","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=23166"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/posts\/23166\/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=23166"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/categories?post=23166"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/dotnet\/wp-json\/wp\/v2\/tags?post=23166"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}