IIS – TroubleShooting – High CPU Utilization – Debug Diagnostic Tools v2.1 – Day 1

Background

Needing to do a deep drive into troubleshooting IIS Servers.  As part of our troubleshooting exercises we will cover one of Microsoft’s own tool, Debug Diagnostic Tools.

 

Debug Diagnostic Tools

Version

The tool’s team blog is here.

And, the current version is 2.1 and it is available here.

Details

The version was availed on 2015-Nov-13.

Requirements

Link

We are running MS Windows 2012 R2.

And, the bitness is 64-bit.

 

Install

Image

Welcome

End-User License Agreement

End-User License Agreement – Initial

End-User License Agreement – Completed

Custom Setup

 

Ready to install

Installing….

Completed

Debug File

Before we actually use the debug tool, let us go generate dump files from a working w3wp process.

Identify Process

Code


c:\windows\system32\inetsrv\appcmd list wp

 

Output

Dump file

Task Manager

On the IIS machine, launch Task Manager, access the Processes tab, select the “IIS Worker Process”.

Right click on your selection and choose “Create dump file“.

 

Use Debug Diagnostic Tool

Start Menu

Here is the Start Menu,

We will choose the menu option “Debug Diagnostics Tool 2” \ “Debug Diag2 Analysis”.

 

Data Files

We will click the “Add Data Files” button and navigate to the folder where we kept the dump file that was created earlier.

Here is the screenshot once we have added our dump file.

 

Analysis Rules

From the list of rules, we chose “Default Analysis” “CrashHangAnalysis“.

Start Analysis

Please click the “Start Analysis” button.

Reports

Analysis Report – Dashboard

Here we noted 3 Warnings.

 

Sections

Previous .Net Exceptions Reports ( Exception in all .Net Heaps )

Image

Tabulated

 

Exception Count Message Stack Trace
System.Exception 1 <none>  ;
System.OutOfMemoryException 1 <none>  ;
 

System.StackOverflowException

1 <none>  ;
System.ExecutionEngineException 1 <none>  ;
System.Threading.ThreadAbortException 2 <none>  ;
System.NullReferenceException 3 Object reference not set to an instance of an object.  garage.Models.Articulation.GeneratedPrefixAgreement+<>c__DisplayClass1e.<Generate>b__b(garage.Models.Articulation.Courses.CourseToCourseArticulation)
System.Linq.EnumerableSorter`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].ComputeKeys(System.__Canon[], Int32)
System.Linq.EnumerableSorter`1[[System.__Canon, mscorlib]].Sort(System.__Canon[], Int32)
System.Linq.OrderedEnumerable`1+<GetEnumerator>d__1[[System.__Canon, mscorlib]].MoveNext()
garage.Models.Articulation.GeneratedPrefixAgreement.Generate(CodeFirstMembershipSharp.DataContext)
LinqKit.Extensions.ForEach[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Action`1<System.__Canon>)
garage.Infrastructure.GeneratedAgreementFactory.Generate(garage.Models.Articulation.GeneratedAgreement)
 

System.Reflection.TargetInvocationException

3 Exception has been thrown by the target of an invocation.  System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Object[], System.Signature, Boolean)
System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(System.Object, System.Object[], System.Object[])
System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
Hangfire.Server.CoreBackgroundJobPerformer.InvokeMethod(System.Reflection.MethodInfo, System.Object, System.Object[])
 

Hangfire.Server.JobPerformanceException

3  

An exception occurred during performance of the job.

  Hangfire.Server.CoreBackgroundJobPerformer.InvokeMethod(System.Reflection.MethodInfo, System.Object, System.Object[])
Hangfire.Server.CoreBackgroundJobPerformer.Perform(Hangfire.Server.PerformContext)
Hangfire.Server.BackgroundJobPerformer+<>c__DisplayClass8_0.<PerformJobWithFilters>b__0()
Hangfire.Server.BackgroundJobPerformer.InvokePerformFilter(Hangfire.Server.IServerFilter, Hangfire.Server.PerformingContext, System.Func`1<Hangfire.Server.PerformedContext>)
Hangfire.Server.BackgroundJobPerformer.PerformJobWithFilters(Hangfire.Server.PerformContext, System.Collections.Generic.IEnumerable`1<Hangfire.Server.IServerFilter>)
Hangfire.Server.BackgroundJobPerformer.Perform(Hangfire.Server.PerformContext)
Hangfire.Server.Worker.PerformJob(Hangfire.Server.BackgroundProcessContext, Hangfire.Storage.IStorageConnection, System.String)

 

Thread Report

Image

Explanation
  1. 54 Threads
    • 32% of all threads have this same call stack

 

clr!Thread::intermediateThreadProc ( 54 Threads )

Image

 

Explanation

mscorlib_ni!System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Insert(System.__Canon, System.__Canon, Boolean)+bf 
garage.Models.garageSystem.Menu.AddItemForRoles(CodeFirstMembershipSharp.User, System.String, System.String, Boolean, System.String[], Boolean, System.String)+d5 
garage.Controllers.HomeController.BuildMenu()+6c 
garage.Controllers.BaseController.Initialize(System.Web.Routing.RequestContext)+1956 
System.Web.Mvc.Controller.BeginExecute(System.Web.Routing.RequestContext, System.AsyncCallback, System.Object)+179 
System.Web.Mvc.MvcHandler.b__4(System.AsyncCallback, System.Object, ProcessRequestState)+37 
System.Web.Mvc.Async.AsyncResultWrapper+WrappedAsyncVoid`1[[System.Web.Mvc.MvcHandler+ProcessRequestState, System.Web.Mvc]].CallBeginDelegate(System.AsyncCallback, System.Object)+41 
System.Web.Mvc.Async.AsyncResultWrapper+WrappedAsyncResultBase`1[[System.Web.Mvc.Async.AsyncVoid, System.Web.Mvc]].Begin(System.AsyncCallback, System.Object, Int32)+aa 
System.Web.Mvc.MvcHandler.BeginProcessRequest(System.Web.HttpContextBase, System.AsyncCallback, System.Object)+23b 
System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()+132 
System_Web_ni!System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)+9d 
System_Web_ni!System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)+5dc 
System_Web_ni!System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)+79 
System_Web_ni!System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)+e0 
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+407 
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+14 
System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+5b 
System_Web_ni!DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)+7e 
[[InlinedCallFrame] (System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion)] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatusByRef) 
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+5e6 
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+14 
System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+5b 
[[ContextTransitionFrame]] 


 

clr!Thread::intermediateThreadProc ( 16 Threads – 9% of all threads )

Image

Explanation
  1. 16 Threads
    • Thread is waiting in a waitOne

 

clr!Thread::intermediateThreadProc ( 8 Threads – 4% of all threads )

Image

Textual

Entry point   clr!Thread::intermediateThreadProc 
Create time   8/2/2017 3:30:18 PM 
Time spent in user mode   0 Days 00:00:00.093 
Time spent in kernel mode   0 Days 00:00:00.031 

This thread is waiting for .net garbage collection to finish.
The current set of scripts were not able to determine which thread induced GC.
The garbage collector thread wont start doing its work till the time the threads which have pre-emptive GC disabled have finished executing. 
The following threads have pre-emptive GC disabled 28,51,52,53,54,55,56,57,66,67,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,155,156,157,158,159,160,161,162,163,165,166,167,

Call Stack

ntdll!NtWaitForSingleObject+a 
KERNELBASE!WaitForSingleObjectEx+94 
clr!SVR::gc_heap::wait_for_gc_done+134 
clr!SVR::gc_heap::wait_for_gc_done+cb 
clr!CLREventBase::WaitEx+7c 
clr!SVR::gc_heap::bgc_thread_function+a7 
clr!Thread::intermediateThreadProc+86 
kernel32!BaseThreadInitThunk+22 
ntdll!RtlUserThreadStart+34 


Explanation

This is a very important group:

  1. This thread is waiting for .net garbage collection to finish.
  2. The garbage collector thread wont start doing its work till the time the threads which have pre-emptive GC disabled have finished executing.
  3. The following threads have pre-emptive GC disabled…..

 

Summary

Here is a quick compilation of what the tool is informing us of:

  1. We have exceptions that are not gracefully handled
    • System.NullReferenceException
      • Entity Framework calls
        • Uncompleted DB Calls that likely timed out
        • .Net code should review return code before trying to access returned dataset
    • System.Reflection.TargetInvocationException
    • Hangfire.Server.JobPerformanceException
      • Hangfire background process when accessing persistent backend
  2. Seeming contention issue accessing Dictionary Collection?
    • Stack Trace :-
      • mscorlib_ni!System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Insert(System.__Canon, System.__Canon, Boolean)+bf
        garage.Models.garageSystem.Menu.AddItemForRoles(CodeFirstMembershipSharp.User, System.String, System.String, Boolean, System.String[], Boolean, System.String)+d5
        garage.Controllers.HomeController.BuildMenu()+6c
  3. Garbage Collection Issues
    • Stack Trace :-
      • This thread is waiting for .net garbage collection to finish.The current set of scripts were not able to determine which thread induced GC.  The garbage collector thread wont start doing its work till the time the threads which have pre-emptive GC disabled have finished executing. The following threads have pre-emptive GC disabled

 

References

  1. Developer Network
    • Mourad Lagdas
      • How to Use the Debug Diagnostic Tool v1.1 (DebugDiag) to Debug User Mode Processes
        Link
  2. Microsoft Developer
    • Michael Friis ( friis[at]microsoft.com )
      • Which w3wp.exe PID corresponds to which application pool ?
        Link
  3. Hangfire
    • Documentation \ Background processing \ Dealing with exceptions
      Link
  4. WhiteSites.com
    • Debugging Faulting Application w3wp.exe Crashes
      Link

One thought on “IIS – TroubleShooting – High CPU Utilization – Debug Diagnostic Tools v2.1 – Day 1

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s