{"id":92111,"date":"2015-11-13T07:00:00","date_gmt":"2015-11-13T22:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/20151113-00\/?p=92111\/"},"modified":"2019-03-13T12:21:46","modified_gmt":"2019-03-13T19:21:46","slug":"20151113-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20151113-00\/?p=92111\/","title":{"rendered":"Diagnosing high CPU by studying profiling results, example"},"content":{"rendered":"

A customer asked for assistance determining why their program demonstrated sporadic high CPU. It occurred only at a client location, so they couldn’t set up a full debugging environment. They were able to convince the client to trace one of the spikes in a profiler<\/a>. During this capture, high CPU was recorded for around 20% of the running time. Here is the drill-down of where most of that time was going. <\/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\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\n\n\n\n\n\n\n\n\n\n\n\n
Stack<\/td>\n% Weight<\/td>\n<\/tr>\n
[Root]<\/td>\n19.36<\/td>\n<\/tr>\n
 |- ntdll.dll!RtlUserThreadStart<\/td>\n19.36<\/td>\n<\/tr>\n
 |    kernel32.dll!BaseThreadInitThunk<\/td>\n19.36<\/td>\n<\/tr>\n
 |    contoso.exe!__wmainCRTStartup<\/td>\n19.36<\/td>\n<\/tr>\n
 |    contoso.exe!wWinMain<\/td>\n19.36<\/td>\n<\/tr>\n
 | ⋮<\/td>\n⋮<\/td>\n<\/tr>\n
 |    fabrikam.dll!Widget::~Widget<\/td>\n19.36<\/td>\n<\/tr>\n
 |    fabrikam.dll!WidgetProxy::Disconnect<\/td>\n19.36<\/td>\n<\/tr>\n
 |    fabrikam.dll!WidgetProxy::DisconnectAll<\/td>\n19.36<\/td>\n<\/tr>\n
 |    fabrikam.dll!WidgetProxy::TransactCommand<\/td>\n19.36<\/td>\n<\/tr>\n
 |    fabrikam.dll!WidgetProxy::WaitForResponse<\/td>\n19.36<\/td>\n<\/tr>\n
 |    |- user32.dll!MsgWaitForMultipleObjectsEx<\/td>\n18.63<\/td>\n<\/tr>\n
 |    |    |- kernel32.dll!WaitForMultipleObjectsExImplementation<\/td>\n17.37<\/td>\n<\/tr>\n
 |    |    |    |- KernelBase.dll!WaitForMultipleObjectsEx<\/td>\n16.55<\/td>\n<\/tr>\n
 |    |    |    |    |- ntdll.dll!ZwWaitForMultipleObjects<\/td>\n8.69<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceCopyEnd<\/td>\n4.76<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntoskrnl.exe!NtWaitForMultipleObjects<\/td>\n4.71<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!ObpWaitForMultipleObjects<\/td>\n4.02<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |    |- ntoskrnl.exe!ObpWaitForMultipleObjects<\/td>\n4.02<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |    |- ntoskrnl.exe!KiCheckForKernelApcDelivery<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |    |- ntoskrnl.exe!KiDpcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatch<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!NtWaitForMultipleObjects<\/td>\n0.49<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!memcpy<\/td>\n0.20<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!KiDpcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceCopyEnd<\/td>\n0.05<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemCall64<\/td>\n1.84<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntdll.dll!ZwWaitForMultipleObjects<\/td>\n1.20<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceExit<\/td>\n0.56<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceRepeat<\/td>\n0.16<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceGdiTebAccess<\/td>\n0.13<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceStart<\/td>\n0.03<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceCopyStart<\/td>\n0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |- KernelBase.dll!BaseSetLastNTError<\/td>\n6.57<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntdll.dll!RtlNtStatusToDosError<\/td>\n6.33<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntdll.dll!RtlNtStatusToDosErrorNoTeb<\/td>\n6.05<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntdll.dll!RtlNtStatusToDosErrorNoTeb<\/td>\n6.04<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!KiDpcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!KiApcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntdll.dll!RtlNtStatusToDosError<\/td>\n0.29<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |    |- KernelBase.dll!BaseSetLastNTError<\/td>\n0.19<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntdll.dll!RtlSetLastWin32Error<\/td>\n0.05<\/td>\n<\/tr>\n
 |    |    |    |    |- ntdll.dll!memcpy<\/td>\n0.15<\/td>\n<\/tr>\n
 |    |    |    |    |- KernelBase.dll!memcpy<\/td>\n0.01<\/td>\n<\/tr>\n
 |    |    |    |    |- ntoskrnl.exe!KiApcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |    |- ntoskrnl.exe!KiDpcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |- kernel32.dll!WaitForMultipleObjectsExImplementation<\/td>\n0.60<\/td>\n<\/tr>\n
 |    |    |    |- ntdll.dll!memcpy<\/td>\n0.16<\/td>\n<\/tr>\n
 |    |    |    |- kernel32.dll!WaitForMultipleObjectsEx<\/td>\n0.04<\/td>\n<\/tr>\n
 |    |    |    |- kernel32.dll!memcpy<\/td>\n0.02<\/td>\n<\/tr>\n
 |    |    |    |- ntoskrnl.exe!KiInterruptDispatchNoLock<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |    |- ntoskrnl.exe!KiApcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |- ntoskrnl.exe!KiDpcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |    |- ntoskrnl.exe!KiApcInterrupt<\/td>\n<0.01<\/td>\n<\/tr>\n
 |    |- KernelBase.dll!GetTickCount<\/td>\n0.24<\/td>\n<\/tr>\n
 |    |- KernelBase.dll!GetLastError<\/td>\n0.20<\/td>\n<\/tr>\n
 |    |- fabrikam.dll!GetLastError<\/td>\n0.09<\/td>\n<\/tr>\n
 |    |- kernel32.dll!GetLastError<\/td>\n0.02<\/td>\n<\/tr>\n<\/table>\n

From this chart, you can see that all of the time is consumed in Widget­Proxy::Wait­For­Response<\/code>, and most of that time is in Msg­Wait­For­Multiple­Objects­Ex<\/code>. There is a lot of detail inside that function, so let’s hide everything that contributes less than one percent. <\/p>\n\n\n\n\n\n\n\n\n\n\n\n
Stack<\/td>\n% Weight<\/td>\n<\/tr>\n
 |    fabrikam.dll!WidgetProxy::WaitForResponse<\/td>\n19.36<\/td>\n<\/tr>\n
 |    |- user32.dll!MsgWaitForMultipleObjectsEx<\/td>\n18.63<\/td>\n<\/tr>\n
 |    |    |- kernel32.dll!WaitForMultipleObjectsExImplementation<\/td>\n17.37<\/td>\n<\/tr>\n
 |    |    |    |- KernelBase.dll!WaitForMultipleObjectsEx<\/td>\n16.55<\/td>\n<\/tr>\n
 |    |    |    |    |- ntdll.dll!ZwWaitForMultipleObjects<\/td>\n8.69<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemServiceCopyEnd<\/td>\n4.76<\/td>\n<\/tr>\n
 |    |    |    |    |    |    |- ntoskrnl.exe!NtWaitForMultipleObjects<\/td>\n4.71<\/td>\n<\/tr>\n
 |    |    |    |    |    |- ntoskrnl.exe!KiSystemCall64<\/td>\n1.84<\/td>\n<\/tr>\n
 |    |    |    |    |- KernelBase.dll!BaseSetLastNTError<\/td>\n6.57<\/td>\n<\/tr>\n<\/table>\n

If we look only at the time spent in Wait­For­Multiple­Objects­Ex<\/code>, 8.69%\/16.55% = around half of the time is spent in Zw­Wait­For­Multiple­Objects<\/code> (the kernel part of the function which does the waiting), and 6.57%\/16.55% = around 40% of the time is the time setting the last error code. <\/p>\n

That’s odd. Why is this function spending nearly half of its time setting the last error code? <\/p>\n

My theory: Because the call is failing with an error! <\/p>\n

That explains the high CPU. The call to Wait­For­Multiple­Objects­Ex<\/code> is failing, which means that instead of waiting, it returns immediately with an error code. The Widget­Proxy::Wait­For­Response<\/code> function doesn’t quite know what to do in that case, so it shrugs its shoulders and tries waiting again. Eventually, whatever it’s waiting for actually happens, and the call returns, but instead of waiting at low CPU, it accidentally created a CPU spin loop. <\/p>\n","protected":false},"excerpt":{"rendered":"

Why would a wait consume so much CPU time?<\/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":[25],"class_list":["post-92111","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"

Why would a wait consume so much CPU time?<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/92111","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=92111"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/92111\/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=92111"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=92111"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=92111"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}