{"id":100185,"date":"2018-11-12T07:00:00","date_gmt":"2018-11-12T22:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/?p=100185"},"modified":"2019-12-21T08:33:08","modified_gmt":"2019-12-21T16:33:08","slug":"20181112-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20181112-00\/?p=100185","title":{"rendered":"The case of the System process that consumed a lot of CPU"},"content":{"rendered":"

A report came in through Feedback Hub that the System process was consuming high CPU. I was able to explain to the customer how to include a performance trace so the problem could be diagnosed.<\/p>\n

In case you want to file a performance issue, the way to include a performance trace is to go to the Additional details<\/i> section and click the Recreate my problem<\/i> button. You will get additional options:<\/p>\n\n\n\n
\n
To help us understand what is causing the problem, please try to make it happen again while we follow along and capture data.<\/div>\n
\n
\u2713<\/div>\n
Include data about Performance<\/span> \u2335<\/div>\n
\u2713<\/div>\n
Include screenshots of each step<\/div>\n<\/div>\n
You will be able to review and edit the data before sending it.<\/div>\n<\/td>\n
\u00a0<\/td>\n\n
\u23f1\ufe0e<\/div>\n
Start
\ncapture<\/div>\n<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

Check the Include data about<\/i> box and select Performance<\/i> as the category. Assuming the performance problem is ongoing, click Start capture<\/i> and let it run for about 15 seconds, then click Stop capture<\/i>. (If the performance problem occurs only when you perform a certain activity, then click Start capture<\/i>, then do the activity that creates the performance issue, and then click Stop capture<\/i>.)<\/p>\n

That creates a performance trace that will be attached to your report.<\/p>\n

Okay, let’s open the performance trace that this customer included. The tool for this is the Windows Performance Analyzer<\/a>.<\/p>\n

Since the problem is high CPU, the natural place to start is the Computation graph, which shows CPU usage.<\/p>\n

\n
Computation<\/div>\n
(svg not supported on this site)<\/div>\n<\/div>\n

Yup, that sure looks like high CPU usage there.<\/p>\n

Create an analysis page for that graph and zoom in to the period of high CPU. Here’s what’s using the CPU:<\/p>\n\n\n\n\n\n\n\n
Line #<\/td>\nProcess<\/td>\nThread ID<\/td>\nStack<\/td>\n\u00a0<\/td>\nCount<\/td>\n% Weight<\/td>\n<\/tr>\n
1<\/td>\n\u25b7 System<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n29,815<\/td>\n65.15<\/td>\n<\/tr>\n
2<\/td>\nIdle<\/td>\n0<\/td>\n\u25b7 [Idle]<\/td>\n510<\/td>\n21.35<\/td>\n<\/tr>\n
3<\/td>\n\u25b7 Taskmgr.exe (14412)<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n0.25<\/td>\n<\/tr>\n
4<\/td>\n\u25b7 MsMpEng.exe (5180)<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n0.07<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

And indeed most of it is going to the System process with 65.15%. The Idle thread is a distant second with 21.35%, and everybody else is noise.<\/p>\n

So let’s dig into the System process.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
Line #<\/td>\nProcess<\/td>\nThread ID<\/td>\nStack<\/td>\n\u00a0<\/td>\nCount<\/td>\n% Weight<\/td>\n<\/tr>\n
1<\/td>\n\u25bcSystem (4)<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n29,815<\/td>\n65.15<\/td>\n<\/tr>\n
2<\/td>\n\u00a0<\/td>\n9200<\/td>\n\u25b7[Root]<\/td>\n1,605<\/td>\n3.51<\/td>\n<\/tr>\n
3<\/td>\n\u00a0<\/td>\n19708<\/td>\n\u25b7[Root]<\/td>\n1,576<\/td>\n3.44<\/td>\n<\/tr>\n
4<\/td>\n\u00a0<\/td>\n\u25b718748<\/td>\n\u00a0<\/td>\n1,361<\/td>\n2.97<\/td>\n<\/tr>\n
5<\/td>\n\u00a0<\/td>\n17480<\/td>\n\u25b7[Root]<\/td>\n1,346<\/td>\n2.93<\/td>\n<\/tr>\n
6<\/td>\n\u00a0<\/td>\n12132<\/td>\n\u25b7[Root]<\/td>\n1,341<\/td>\n2.93<\/td>\n<\/tr>\n
7<\/td>\n\u00a0<\/td>\n13020<\/td>\n\u25b7[Root]<\/td>\n1,220<\/td>\n2.67<\/td>\n<\/tr>\n
8<\/td>\n\u00a0<\/td>\n15064<\/td>\n\u25b7[Root]<\/td>\n1,181<\/td>\n2.58<\/td>\n<\/tr>\n
9<\/td>\n\u00a0<\/td>\n16364<\/td>\n\u25b7[Root]<\/td>\n1,084<\/td>\n2.36<\/td>\n<\/tr>\n
10<\/td>\n\u00a0<\/td>\n11376<\/td>\n\u25b7[Root]<\/td>\n1,058<\/td>\n2.31<\/td>\n<\/tr>\n
11<\/td>\n\u00a0<\/td>\n20444<\/td>\n\u25b7[Root]<\/td>\n994<\/td>\n2.17<\/td>\n<\/tr>\n
12<\/td>\n\u00a0<\/td>\n21000<\/td>\n\u25b7[Root]<\/td>\n978<\/td>\n2.14<\/td>\n<\/tr>\n
13<\/td>\n\u00a0<\/td>\n20648<\/td>\n\u25b7[Root]<\/td>\n905<\/td>\n1.97<\/td>\n<\/tr>\n
14<\/td>\n\u00a0<\/td>\n\u25b719076<\/td>\n\u00a0<\/td>\n895<\/td>\n1.95<\/td>\n<\/tr>\n
15<\/td>\n\u00a0<\/td>\n8572<\/td>\n\u25b7[Root]<\/td>\n757<\/td>\n1.65<\/td>\n<\/tr>\n
16<\/td>\n\u00a0<\/td>\n13864<\/td>\n\u25b7[Root]<\/td>\n743<\/td>\n1.62<\/td>\n<\/tr>\n
17<\/td>\n\u00a0<\/td>\n17072<\/td>\n\u25b7[Root]<\/td>\n685<\/td>\n1.50<\/td>\n<\/tr>\n
18<\/td>\n\u00a0<\/td>\n16224<\/td>\n\u25b7[Root]<\/td>\n653<\/td>\n1.43<\/td>\n<\/tr>\n
19<\/td>\n\u00a0<\/td>\n\u25b715988<\/td>\n\u00a0<\/td>\n625<\/td>\n1.37<\/td>\n<\/tr>\n
20<\/td>\n\u00a0<\/td>\n19592<\/td>\n\u25b7[Root]<\/td>\n604<\/td>\n1.32<\/td>\n<\/tr>\n
21<\/td>\n\u00a0<\/td>\n1784<\/td>\n\u25b7[Root]<\/td>\n571<\/td>\n1.25<\/td>\n<\/tr>\n
22<\/td>\n\u00a0<\/td>\n17872<\/td>\n\u25b7[Root]<\/td>\n560<\/td>\n1.22<\/td>\n<\/tr>\n
\u22ee<\/td>\n\u00a0<\/td>\n\u22ee<\/td>\n\u22ee<\/td>\n\u22ee<\/td>\n\u22ee<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

Hm, everything just flattens out. There’s no big culprit sucking up all the CPU.<\/p>\n

Are we being nibbled to death?<\/p>\n

Let’s look at two of those threads, maybe we’ll discover something.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
Line #<\/td>\nProcess<\/td>\nThread ID<\/td>\nStack<\/td>\n\u00a0<\/td>\nCount<\/td>\n% Weight<\/td>\n<\/tr>\n
1<\/td>\n\u25bcSystem (4)<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n29,815<\/td>\n65.15<\/td>\n<\/tr>\n
2<\/td>\n\u00a0<\/td>\n9200<\/td>\n\u25bc<\/span>[Root]<\/td>\n1,605<\/td>\n3.51<\/td>\n<\/tr>\n
3<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25bc<\/span>ntoskrnl.exe!KxStartSystemThread<\/td>\n1,605<\/td>\n3.51<\/td>\n<\/tr>\n
4<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!PspSystemThreadStartup<\/td>\n1,605<\/td>\n3.51<\/td>\n<\/tr>\n
5<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!ExpWorkerThread<\/td>\n1,605<\/td>\n3.51<\/td>\n<\/tr>\n
6<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25b7<\/span>|- ntoskrnl.exe!IopProcessWorkItem<\/td>\n1,554<\/td>\n3.40<\/td>\n<\/tr>\n
7<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25b7<\/span>|- ntoskrnl.exe!KeRemovePriQueue<\/td>\n50<\/td>\n0.11<\/td>\n<\/tr>\n
8<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n|- ntoskrnl.exe!ExpWorkerThread<itself><\/td>\n1<\/td>\n0.00<\/td>\n<\/tr>\n
9<\/td>\n\u00a0<\/td>\n19708<\/td>\n\u25bc<\/span>[Root]<\/td>\n1,576<\/td>\n3.44<\/td>\n<\/tr>\n
10<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|- ntoskrnl.exe!KxStartSystemThread<\/td>\n1,574<\/td>\n3.44<\/td>\n<\/tr>\n
11<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!PspSystemThreadStartup<\/td>\n1,574<\/td>\n3.44<\/td>\n<\/tr>\n
12<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!ExpWorkerThread<\/td>\n1,574<\/td>\n3.44<\/td>\n<\/tr>\n
13<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25b7<\/span>|\u00a0 \u00a0 |- ntoskrnl.exe!IopProcessWorkItem<\/td>\n1,538<\/td>\n3.36<\/td>\n<\/tr>\n
14<\/td>\n\u00a0<\/td>\n\u00a0<\/td>\n\u25b7<\/span>|\u00a0 \u00a0 |- ntoskrnl.exe!KeRemovePriQueue<\/td>\n36<\/td>\n0.08<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

Okay, it seems that the threads are doing Iop\u00adProcess\u00adWork\u00adItem<\/code>. That explains why the work is so evenly spread out: It’s a thread pool.<\/p>\n

Remove the Thread ID<\/i> column because we don’t care about which thread is doing the work. Now we can group purely by stacks.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n
Line #<\/td>\nProcess<\/td>\nStack<\/td>\n\u00a0<\/td>\nCount<\/td>\n% Weight<\/td>\n<\/tr>\n
1<\/td>\nSystem (4)<\/td>\n\u00a0<\/td>\n29,815<\/td>\n65.14<\/td>\n<\/tr>\n
2<\/td>\n\u00a0<\/td>\n\u25bc<\/span>[Root]<\/td>\n29,810<\/td>\n65.13<\/td>\n<\/tr>\n
3<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|- ntoskrnl.exe!KxStartSystemThread<\/td>\n29,794<\/td>\n65.09<\/td>\n<\/tr>\n
4<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!PspSystemThreadStartup<\/td>\n29,794<\/td>\n65.09<\/td>\n<\/tr>\n
5<\/td>\n\u00a0<\/td>\n|\u00a0 \u00a0 ntoskrnl.exe!ExpWorkerThread<\/td>\n29,699<\/td>\n64.89<\/td>\n<\/tr>\n
6<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|\u00a0 \u00a0 |- ntoskrnl.exe!IopProcessWorkItem<\/td>\n28,742<\/td>\n62.81<\/td>\n<\/tr>\n
7<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|\u00a0 \u00a0 |- contoso.sys!<PDB not found><\/td>\n28,707<\/td>\n62.74<\/td>\n<\/tr>\n
8<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|\u00a0 \u00a0 |\u00a0 \u00a0 |- contoso.sys!<PDB not found><\/td>\n28,699<\/td>\n62.72<\/td>\n<\/tr>\n
9<\/td>\n\u00a0<\/td>\n\u25bc<\/span>|\u00a0 \u00a0 |\u00a0 \u00a0 |\u00a0 \u00a0 |- contoso.sys!<PDB not found><\/td>\n28,588<\/td>\n62.48<\/td>\n<\/tr>\n
10<\/td>\n\u00a0<\/td>\n\u25b7<\/span>|\u00a0 \u00a0 |\u00a0 \u00a0 |\u00a0 \u00a0 |\u00a0 \u00a0 |- ntoskrnl.exe!RtlWriteRegistryValue<\/td>\n28,572<\/td>\n62.44<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

Aha, basically all of the work items are going to the the Contoso driver, and that driver does very little work of its own. Of the 28,707 samples that showed that we were running a Contoso work item, 28,572 of them (over 99%) were in Rtl\u00adWrite\u00adRegistry\u00adValue<\/code>.<\/p>\n

Basically, the Contoso driver was burning up all your CPU writing furiously to the registry.<\/p>\n

The developers at Contoso replied that the customer was running a version of the driver that was over a year old. They suggested the customer upgrade to the latest driver and see if that fixes the problem.<\/p>\n

I’m sure that upgrading to the latest driver will make the problem go away, but I’m not convinced that it’ll fix the problem. Because what’s probably happening is that the driver got into some sort of error state and is writing diagnostic information to the registry. That’ll go away even if you don’t<\/i> upgrade the driver. All you have to do is reboot.<\/p>\n

The real question is what sort of error state the driver managed to get itself into.<\/p>\n

 <\/p>\n","protected":false},"excerpt":{"rendered":"

Let’s look at the performance trace.<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[26],"class_list":["post-100185","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-other"],"acf":[],"blog_post_summary":"

Let’s look at the performance trace.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/100185","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=100185"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/100185\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=100185"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=100185"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=100185"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}