Thursday, August 25, 2011

Finding out the culprit behind “# of Exceps Thrown / Sec” using ProcDump and WinDbg

I’ll show you how to find out the culprit (exceptions) who is causing a high number of .Net “# of Exceps Thrown / Sec”
We’ll do this with WinDbg and ProcDump tools.
Let us start with reviewing the documentation for this performance counter.
  "Exception Performance Counters"

# of Exceps Thrown / Sec
  Displays the number of exceptions thrown per second. This includes both .NET exceptions and unmanaged exceptions that are converted into .NET exceptions.
  For example, an HRESULT returned from unmanaged code is converted to an exception in managed code.
  This counter includes both handled and unhandled exceptions. It is not an average over time; it displays the difference between the values observed in the
  last two samples divided by the duration of the sample interval. This counter is an indicator of potential performance problems if a large (>100s) number of exceptions are thrown.

So we know from here that a large number of exceptions could cause performance issues.
The ‘problem’ here is that this counter includes handled exceptions which means that there will be no crash because, well, it is handled.
In other words it will not be anything in the event logs or any type of stack trace to look at.
And it will not be easy to set a dump trigger on a particular exception since we do not know what the exact exception is.
It could be anything, and this post is about finding out what exception is being thrown this frequently (and possibly cause the performance issue).

All we know is that the application is performing slowly, there are no crashes and the Net “# of Exceps Thrown / Sec” hits a high number (> 100).
So how do we go on from here? I’ll stick to my way of demonstrating from scratch. So the first thing is to create an application that will show this behavior.

Create a new .Net C# console application with the following code:

    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("Press any key to start!");
            Console.ReadLine();

            for (int i = 1; i < 4; i++)
            {
                ThrowHighAmountOfExceptions();
                Console.WriteLine("Iteration {0} done.", i);
            }
           
        }

        private static void ThrowHighAmountOfExceptions()
        {
            int waitTime = 5000;
            bool run = true;
            Stopwatch sw = new Stopwatch();

            Thread.Sleep(waitTime);
            sw.Start();

            while (run)
            {
                int x = 0;
                try
                {
                    int y = 1 / x;
                }
                catch (Exception ex)
                {
                    //Exception is handled.
                }

                if (sw.ElapsedMilliseconds >= waitTime)
                {
                    run = false;
                }
            }
            sw.Stop();
        }
    }


This application will wait 5 seconds, then throw a lot of exceptions for 5 seconds then wait 5 seconds. It will do this over 3 iterations.

Run the application but do not press any key yet.
Start performance monitor (Start – Run – PerfMon ).
Add the “.NET CLR Exceptions\# of Exceps Thrown / sec“ counter.

 

Then run the application and you should have an output like this, notice that the % Processor Time follows (in green).

 

So we can see that we have a lot of .Net exceptions thrown. So now the question is; what exceptions?
( In this case we know (DivideByZeroException), but in real life you probably don’t. If you did, you would have fixed it and not read this J )

First download and install Proc Dump from here:
  “ProcDump”

Start the application again (do not hit any key yet) and figure out what the PID is for the application (use Task Manger for example) or use the process name.
Then navigate to the directory where you have extracted Proc Dump and run the following.

C:\ProcDump>procdump 6140 -ma -s 3 -p "\.NET CLR Exceptions(_Global_)\# of Exceps Thrown / sec" 100

Here we are saying that when the process with PID 6140 hits more than 100 exceptions thrown per second and keeps doing this for at least 3 seconds, then do a full dump (-ma) on the process.
So run this and start the application. This should give an output like this:

C:\ProcDump>procdump 6140 -ma -s 3 -p "\.NET CLR Exceptions(_Global_)\# of Exceps Thrown / sec" 100

ProcDump v3.04 - Writes process dump files
Copyright (C) 2009-2011 Mark Russinovich
Sysinternals - www.sysinternals.com

Process:               HighExcepPerSec.exe (6140)
CPU threshold:         n/a
Performance counter:   \.NET CLR Exceptions(_Global_)\# of Exceps Thrown / sec
Performance threshold: 100
Commit threshold:      n/a
Threshold seconds:     3
Number of dumps:       1
Hung window check:     Disabled
Exception monitor:     Disabled
Terminate monitor:     Disabled
Dump file:             C:\ProcDump\HighExcepPerSec.dmp

[13:56.09] Counter:    17580  1s
[13:56.10] Counter:    33398  2s
[13:56.11] Counter:    33835  3s

Process has hit performance counter spike threshold.
Writing dump file C:\ProcDump\HighExcepPerSec_110623_135611.dmp ...
Dump written.

Dump count reached.

So now you have a dump of the process.
Next step is to download and install the Debugging Tools for Windows. Found here:
  "Download and Install Debugging Tools for Windows"

Start WinDbg and select Open Crash Dump (CTRL+D) and navigate to the dump just created and open that one.
Then load the sos.dll found in your .Net installation directory:

0:000> .load C:\Windows\Microsoft.NET\Framework\v2.0.50727\sos.dll

and then dump out all objects of type exception:

!dumpheap -stat -type Exception

in my case this gives the following output:

0:000> !dumpheap -stat -type Exception
total 10093 objects
Statistics:
      MT    Count    TotalSize Class Name
6c2f3fbc        1           12 System.Text.DecoderExceptionFallback
6c2f3f78        1           12 System.Text.EncoderExceptionFallback
6c2f0e2c        1           72 System.ExecutionEngineException
6c2f0d9c        1           72 System.StackOverflowException
6c2f0d0c        1           72 System.OutOfMemoryException
6c2f0ebc        2          144 System.Threading.ThreadAbortException
6c90b7a0    10086       726192 System.DivideByZeroException
Total 10093 objects

So this clearly shows that 10086 exceptions have been thrown and this is most likely the cause of the high number of “# of Exceps Thrown / Sec” and possible performance issues.

Now all we have to do is to find where in our code that particular exception(s) could be thrown. Thats it!
Author: Michael Aspengren