Are you aware that you have thrown over 40,000 exceptions in the last 3 hours?
This may seem like a preposterous statement, but unfortunately it’s all too common.
In my work I go through a lot of dumps, somewhere in the neighborhood of 5-20 in a day:) Since the information is readily available to me, I usually do a quick check for the number of exceptions that the application has thrown and what types of exceptions they are so I can make the customers aware. More often than not, the applications are throwing a lot more exceptions than the developers expected, or they were expecting them but didn’t know that they can actually cause a problem since they don’t seem to have a direct effect on the application.
So why are they so bad? If they are handled and the end users don’t see them are they really harmful?
I can think of 3 reasons off the top of my head.
Exceptions are expensive
- Exceptions can take you into unnecessary code paths.
- Exceptions are generally thrown when something went wrong.
- Exceptions are expensive
Chris Brumme wrote an excellent blog on exceptions and how they work called The Exception Model that you should read if you have the time (definitely worth it).
In his blog he lists some of the things that happen when you throw an exception
- Grab a stack trace by interpreting metadata emitted by the compiler to guide our stack unwind.
- Run through a chain of handlers up the stack, calling each handler twice.
- Compensate for mismatches between SEH, C++ and managed exceptions.
- Allocate a managed Exception instance and run its constructor. Most likely, this involves looking up resources for the various error messages.
- Probably take a trip through the OS kernel. Often take a hardware exception.
- Notify any attached debuggers, profilers, vectored exception handlers and other interested parties. Now, consider this piece of code:
try{
Myvar = (myClass) myParameter;
}
catch (Exception ex){
// do some stuff to handle the exception.
}
Instead of adding a check for if myParameter is null, you have now caused the application to perform all the tasks listed above, and as a special feature, the application has also thrown an additional 1st chance access violation exception (which it always does on a NullReferenceException) so some of the things above actually happen twice…
Before I go any further, there is another thing that I don’t like about the code sample above. We catch a generic exception, so we don’t actually know if it is a NullReferenceException we are catching, perhaps it needs to be handled another way if it is another type of exception. But, rest assured, it is better than catching exceptions and swallowing them without doing anything in the exception handler.
Exceptions can take you down unnecessary code paths
I’d like to share a brief story about a case I had a long time back. The customers servers were performing moderately well but they were not completely satisfied and wanted us to identify potential bottlenecks. We attached a debugger and fairly soon it became apparent that they were throwing some exceptions they weren’t aware of. Unluckily for them, because of one of the exceptions they were throwing they ended up calling a function they were not expecting to call. This function went out and did queries to various different services. The check to avoid the exception was really simple and once they added it, low and behold, they increased their throughput by no less than 20 times… you heard it right 20 times, amazing huh?:) Talk about being completely satisfied with their performance after that…
A common example of when throwing an exception can block you, is the case where you have an global exception handler that logs the exception to an event log, database or file.
Don’t get me wrong, please do log your exceptions, but… make sure you do something about the exceptions you get. If your application throws 40,000 exceptions in 3 hours and you log these to a database or the event log, not only will your logs fill up pretty soon, but you are also likely to get a lot of contention writing to your log. (Especially the event log or a file since writing is usually serialized)
Exceptions are generally thrown when something went wrong
If exceptions are generally thrown when something goes wrong, why do things go wrong so often? In the sample above, if you are expecting the parameter to be null about 20% of the time, perhaps it’s not an exception but rather just one of the cases.
I know we don’t live in a clean room, but a good way of thinking about exceptions is that an exception should only occur in the exceptional case. They shouldn’t be expected, and when they do happen, you should try to take measures to avoid them. Think of try/catch as a safety net rather than a program control feature.
So, now to the good part… here is how you find out how many .net exceptions you are throwing, and why and where…
In performance monitor you can watch the counters:
- .NET CLR Exceptions/#Exceps Thrown (total number of exceptions thrown) and
- .NET CLR Exceptions/#Exceps Thrown / sec
to get an idea of how many .net exceptions your application is throwing.
There are a few different ways you can figure out what exceptions you are throwing with windbg.exe and which one you choose depends a little bit on if you are in production or in a stress test environment where it doesn’t matter if you break in to the process and stop it for a while.
The different ways I’m going to show are
- Attaching and stopping on unmanaged exceptions
- Taking a snapshot memory dump and looking at the recent exceptions
- Leaving a debugger running and logging exceptions Attaching and stopping on unmanaged exceptions
For demonstration purposes I have created a web form and simply call
Throw new System.Exception(“Test”)
from Page_Load
With windbg.exe attached to the w3wp.exe process I run sxe CLR to make the debugger stop on .net exceptions. Since we are going to examine some managed structures we should load the sos extension (.load clr10\sos) and then hit g for go.
Once we hit the first exception we should see something like this in the debugger window
(15c4.163c): CLR exception - code e0434f4d (first chance)
And we should be stopped on Kernel32!RaiseException since this is where we actually throw the native part of the CLR exception.
At this point we can use the following commands to figure out what our exception is and where it is being thrown
!cen (CheckExceptionName to print the exception type and address)
0:005> !cen
System.Exception (0x642e134)
and !clrstack (to print the managed stack)
0:005> !clrstack
Thread 5
ESP EIP
0x0c1bf6e4 0x77e55dea [FRAME: HelperMethodFrame]
0x0c1bf710 0x0c2e0528 [DEFAULT] [hasThis] Void ExceptionsAndStuff.WebForm1.Page_Load(Object,Class System.EventArgs)
at [+0x30] [+0x0] c:\inetpub\wwwroot\exceptionsandstuff\webform1.aspx.cs:21
0x0c1bf728 0x0c3192dc [DEFAULT] [hasThis] Void System.Web.UI.Control.OnLoad(Class System.EventArgs)
0x0c1bf738 0x0c319224 [DEFAULT] [hasThis] Void System.Web.UI.Control.LoadRecursive()
0x0c1bf74c 0x0c3184d7 [DEFAULT] [hasThis] Void System.Web.UI.Page.ProcessRequestMain()
0x0c1bf790 0x0c317207 [DEFAULT] [hasThis] Void System.Web.UI.Page.ProcessRequest()
0x0c1bf7cc 0x0c316c73 [DEFAULT] [hasThis] Void System.Web.UI.Page.ProcessRequest(Class System.Web.HttpContext)
0x0c1bf7d4 0x0c316c4c [DEFAULT] [hasThis] Void System.Web.HttpApplication/CallHandlerExecutionStep.System.Web.HttpApplication+IExecutionStep.Execute()
0x0c1bf7e4 0x0c1d98b8 [DEFAULT] [hasThis] Class System.Exception System.Web.HttpApplication.ExecuteStep(Class IExecutionStep,ByRef Boolean)
0x0c1bf82c 0x0c1d9322 [DEFAULT] [hasThis] Void System.Web.HttpApplication.ResumeSteps(Class System.Exception)
0x0c1bf874 0x0c1d91eb [DEFAULT] [hasThis] Class System.IAsyncResult System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(Class System.Web.HttpContext,Class System.AsyncCallback,Object)
0x0c1bf890 0x01eb6897 [DEFAULT] [hasThis] Void System.Web.HttpRuntime.ProcessRequestInternal(Class System.Web.HttpWorkerRequest)
0x0c1bf8cc 0x01eb6448 [DEFAULT] Void System.Web.HttpRuntime.ProcessRequest(Class System.Web.HttpWorkerRequest)
0x0c1bf8d8 0x01eb2fc5 [DEFAULT] [hasThis] I4 System.Web.Hosting.ISAPIRuntime.ProcessRequest(I,I4)
0x0c1bf9a0 0x79217188 [FRAME: ContextTransitionFrame]
0x0c1bfa80 0x79217188 [FRAME: ComMethodFrame]
This shows us that we have thrown an exception of type System.Exception in ExceptionsAndStuff.WebForm1.Page_Load (and since I had debug=true set in web.config we can also see the page name and line number)
To continue debugging hit gn (go not handled)
After the initial exception if I continue I will get two additional exceptions, first a System.Web.HttpUnhandledException in System.UI.Page.HandleError, and then a rethrow of this System.Web.HttpUnhandledException in System.Web.UI.Page.ProcessRequest. So we can see how this seemingly simple exception just caused me to pass through the exception handlers 3 times.
Debugging Tip!: To make this a bit more automated consider running
sxe -c "!cen;!clrstack;gn" CLRWhich stops on the CLR exception, runs !cen, !clrstack and then continues, so for each exception you will get the type and the call stack in the debugger window.
Taking a snapshot memory dump and looking at the recent exceptions
If you want to look at a production system and you’re throwing enough exceptions that logging in the debugger would slow down the application considerably, you can get a lot of information by taking a hang dump with adplus
adplus -hang –pn [PROCESSNAME.EXE]
With the dump loaded in windbg and with sos.dll loaded, run !dumpallexeptions (or !dae for short), this will show you all exception objects currently on the heap, i.e. all exceptions that have not yet been garbage collected, and should give you an idea of the types of exceptions your application is throwing. !dae gives a statistical view of the exceptions, to see the individual exceptions run !dae –v (verbose mode).
Every time you run !dae you will notice 4 exceptions at the top. The NotSupportedException, ExecutionEngineException, StackOverflowException and OutOfMemoryException. This does not mean that these have been thrown. These exceptions are generated at startup in the case they should be needed since they can not be created at that point. (in other words, ignore these in most cases)
Further down we can see 3 ThreadAbortExceptions in HttpResponse.Redirect/HttpResponse.End and 4 SqlExceptions when trying to fill a dataset.
A redirect will always throw a ThreadAbortException since it needs to stop further execution of the current page, this can be avoided by setting the second parameter of Redirect to false, but then of course the code on the current page will continue running.
0:000> !dae
Number of exceptions of this type: 1
Exception 0x151ce76c in MT 0x79bf44d4: System.NotSupportedException
_message: Specified method is not supported.
-----------------
Number of exceptions of this type: 1
Exception 0x180000bc in MT 0x79b94ee4: System.ExecutionEngineException
-----------------
Number of exceptions of this type: 1
Exception 0x1800007c in MT 0x79b94dac: System.StackOverflowException
-----------------
Number of exceptions of this type: 1
Exception 0x1800003c in MT 0x79b94c74: System.OutOfMemoryException
-----------------
Number of exceptions of this type: 3
Exception 0x28a74114 in MT 0x79bf881c: System.Threading.ThreadAbortException
_message: Thread was being aborted.
_stackTrace:
0x00000000
0x00000000
0x79bb8a00
0x79a29496 [DEFAULT] [hasThis] Void System.Threading.Thread.Abort(Object)
0x0e54eec8
0x79bb8e68
0x030c28fa [DEFAULT] [hasThis] Void System.Web.HttpResponse.End()
0x0e54eecc
0x0200cbe0
0x030c2075 [DEFAULT] [hasThis] Void System.Web.HttpResponse.Redirect(String,Boolean)
0x0e54eee0
0x0200cab0
0x02e2c898 [DEFAULT] [hasThis] Void ExceptionsAndStuff.WebForm1.Page_Load(Object,Class System.EventArgs)
0x0e54eefc
0x02a4af50
-----------------
Number of exceptions of this type: 4
Exception 0x077cf420 in MT 0x02b84e9c: System.Data.SqlClient.SqlException
_message: System error.
_stackTrace:
0x02bf9f18 [DEFAULT] [hasThis] Boolean System.Data.SqlClient.SqlDataReader.Read()
0x0dd1ecf4
0x02b85de8
0x02fe432f [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillLoadDataRow(Class System.Data.Common.SchemaMapping)
0x0dd1ed60
0x02e43110
0x02e2f9cc [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromReader(Object,String,Class System.Data.IDataReader,I4,I4,Class System.Data.DataColumn,Object)
0x0dd1ed50
0x02e430f0
0x02e2f849 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,String,Class System.Data.IDataReader,I4,I4)
0x0dd1edec
0x02e430c0
0x02e2f688 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.FillFromCommand(Object,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior)
0x0dd1edc8
0x02e430b0
0x02e2f4d5 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet,I4,I4,String,Class System.Data.IDbCommand,ValueClass System.Data.CommandBehavior)
0x0dd1ee60
0x02e43090
0x02fe7e96 [DEFAULT] [hasThis] I4 System.Data.Common.DbDataAdapter.Fill(Class System.Data.DataSet)
0x0dd1ee88
0x02e43060
0x036ed5f4 [DEFAULT] [hasThis] Class System.Data.DataSet ExceptionsAndStuff.DBLib.GetData(I4)
0x0dd1ee94
0x029ff6d8
Total 375 exceptions
If we take a look at the SqlException it’s message is System Exception which isn’t terribly helpful. SqlExceptions are a bit special since the actual information is stored in an error object off the exception so the best thing for these is to dump them out separately using the address from the !dae output.
0:000> !dumpobj 0x077cf420
Name: System.Data.SqlClient.SqlException
MethodTable 0x02b84e9c
EEClass 0x02af9340
Size 68(0x44) bytes
GC Generation: 2
mdToken: 0x020001c4 (c:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll)
FieldDesc*: 0x02b84d98
MT Field Offset Type Attr Value Name
0x79b947ac 0x4000029 0x34 System.Int32 instance 0 _xptrs
0x79b947ac 0x400002a 0x38 System.Int32 instance -532459699 _xcode
0x02b84e9c 0x4000fb5 0x3c CLASS instance 0x077cf464 _errors
-----------------
Exception 0x077cf420 in MT 0x02b84e9c: System.Data.SqlClient.SqlException
_message: System error.
_stackTrace:
0x02bf9f18 [DEFAULT] [hasThis] Boolean System.Data.SqlClient.SqlDataReader.Read()
Then dumping out the _errors object and its error object and so on (follow the bolded items… )
0:000> !dumpobj 0x077cf464
Name: System.Data.SqlClient.SqlErrorCollection
MethodTable 0x02b8500c
EEClass 0x02af93a4
Size 12(0xc) bytes
GC Generation: 2
mdToken: 0x020001c3 (c:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll)
FieldDesc*: 0x02b84f2c
MT Field Offset Type Attr Value Name
0x02b8500c 0x4000fb4 0x4 CLASS instance 0x077cf470 errors
0:000> !dumpobj 0x077cf470
Name: System.Collections.ArrayList
MethodTable 0x79ba0d74
EEClass 0x79ba0eb0
Size 24(0x18) bytes
GC Generation: 2
mdToken: 0x020000ff (c:\windows\microsoft.net\framework\v1.1.4322\mscorlib.dll)
FieldDesc*: 0x79ba0f14
MT Field Offset Type Attr Value Name
0x79ba0d74 0x400035b 0x4 CLASS instance 0x077cf488 _items
0x79ba0d74 0x400035c 0xc System.Int32 instance 1 _size
0x79ba0d74 0x400035d 0x10 System.Int32 instance 1 _version
0x79ba0d74 0x400035e 0x8 CLASS instance 0x00000000 _syncRoot
0:000> !dumpobj -v 0x077cf488
Name: System.Object[]
MethodTable 0x01a2209c
EEClass 0x01a22018
Size 80(0x50) bytes
GC Generation: 2
Array: Rank 1, Type CLASS
Element Type: System.Object
Content: 16 items
------ Will only dump out valid managed objects ----
Address MT Class Name
0x077cf400 0x02b851a4 System.Data.SqlClient.SqlError
----------
0:000> !do 0x077cf400
Name: System.Data.SqlClient.SqlError
MethodTable 0x02b851a4
EEClass 0x02af9408
Size 32(0x20) bytes
GC Generation: 2
mdToken: 0x020001c2 (c:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll)
FieldDesc*: 0x02b85090
MT Field Offset Type Attr Value Name
0x02b851a4 0x4000fad 0x4 CLASS instance 0x10015bb0 source
0x02b851a4 0x4000fae 0x10 System.Int32 instance 1205 number
0x02b851a4 0x4000faf 0x18 System.Byte instance 61 state
0x02b851a4 0x4000fb0 0x19 System.Byte instance 13 errorClass
0x02b851a4 0x4000fb1 0x8 CLASS instance 0x077cf28c message
0x02b851a4 0x4000fb2 0xc CLASS instance 0x077cf3c8 procedure
0x02b851a4 0x4000fb3 0x14 System.Int32 instance 22 lineNumber
0:000> !do 0x077cf28c
Name: System.String
MethodTable 0x79b925c8
EEClass 0x79b92914
Size 316(0x13c) bytes
GC Generation: 2
mdToken: 0x0200000f (c:\windows\microsoft.net\framework\v1.1.4322\mscorlib.dll)
String: Transaction (Process ID 104) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
FieldDesc*: 0x79b92978
MT Field Offset Type Attr Value Name
0x79b925c8 0x4000013 0x4 System.Int32 instance 150 m_arrayLength
0x79b925c8 0x4000014 0x8 System.Int32 instance 149 m_stringLength
0x79b925c8 0x4000015 0xc System.Char instance 0x54 m_firstChar
0x79b925c8 0x4000016 0 CLASS shared static Empty
>> Domain:Value 0x000abfc8:0x18000224 0x00163890:0x18000224 <<
0x79b925c8 0x4000017 0x4 CLASS shared static WhitespaceChars
>> Domain:Value 0x000abfc8:0x18000238 0x00163890:0x14005924 <<
As you can see there is plenty more information here you can gather, such as the stored procedure name etc. but I’ll leave those out since you can get them by simply running !dumpobj on the addresses.
Now, let’s say that you get a NullReferenceException in a function and you don’t really know where in the function you are or what could be null.
0:000> !dumpobj 0x3d86c980
Name: System.NullReferenceException
-----------------
Exception 0x3d86c980 in MT 0x79c04e64: System.NullReferenceException
_message: Object reference not set to an instance of an object.
_stackTrace:
0x2fa0536b [DEFAULT] [hasThis] Void ExceptionsAndStuff.WebForm1. btnAdd_Click(Object,Class System.EventArgs)
0x0c10f844
0x0f64be20
0x189b51ec [DEFAULT] [hasThis] Void System.Web.UI.WebControls.LinkButton.OnClick(Class System.EventArgs)
0x0c10f854
0x0e124f00
0x189b4f72 [DEFAULT] [hasThis] Void System.Web.UI.WebControls.LinkButton.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(String)
0x0c10f868
0x0e124f60
0x189b4f22 [DEFAULT] [hasThis] Void System.Web.UI.Page.RaisePostBackEvent(Class System.Web.UI.IPostBackEventHandler,String)
0x0c10f878
0x0c2a1308
0x189b4eea [DEFAULT] [hasThis] Void System.Web.UI.Page.RaisePostBackEvent(Class System.Collections.Specialized.NameValueCollection)
0x0c10f880
0x0c2a12f8
0x10920612 [DEFAULT] [hasThis] Void System.Web.UI.Page.ProcessRequestMain()
0x0c10f890
0x0c2a14d8
The top address on the stack trace will show exactly where we are at in the code (of btnAdd_Click in this case) so we can run !u to disassemble the function and see what it is doing at that location.
0:000> !u 0x2fa0536b
Will print '>>> ' at address: 0x2fa0536b
Normal JIT generated code
[DEFAULT] [hasThis] Void ExceptionsAndStuff.WebForm1.btnAdd_Click (Object,Class System.EventArgs)
Begin 0x2fa05358, size 0x9d
2fa05358 57 push edi
2fa05359 56 push esi
2fa0535a 8bf1 mov esi,ecx
2fa0535c 8b8e68010000 mov ecx,[esi+0x168]
2fa05362 3909 cmp [ecx],ecx
2fa05364 e8cf4313f7 call 26b39738 (System.Web.UI.HtmlControls.HtmlInputFile.get_PostedFile)
2fa05369 8bc8 mov ecx,eax
>>> 2fa0536b 3909 cmp [ecx],ecx
2fa0536d e8464613f7 call 26b399b8 (System.Web.HttpPostedFile.get_ContentLength)
2fa05372 3b053c8b640f cmp eax,[0f648b3c]
2fa05378 7e04 jle 2fa0537e
2fa0537a 33c0 xor eax,eax
2fa0537c eb05 jmp 2fa05383
2fa0537e b801000000 mov eax,0x1
2fa05383 25ff000000 and eax,0xff
2fa05388 7448 jz 2fa053d2
2fa0538a 8bbe68010000 mov edi,[esi+0x168]
2fa05390 8b8e98010000 mov ecx,[esi+0x198]
2fa05396 8b01 mov eax,[ecx]
2fa05398 ff90c4010000 call dword ptr [eax+0x1c4]
2fa0539e 50 push eax
2fa0539f 6aff push 0xff0
2fa053a1 8bd7 mov edx,edi
2fa053a3 8bce mov ecx,esi
2fa053a5 ff1520c1640f call dword ptr [0f64c120]
…
From this we can see that we have called the get method of the PostedFile property on an HtmlInputFile object, then we moved eax into ecx (eax normally contains the return value from a function), and we are comparing it with itself de-referenced, and then we get an exception. You don’t really need to understand all of the assembly, it’s sufficient to look at the big pieces and conclude that likely PostedFile is null and we NullReference when we try to access ContentLength (which is the next thing we see in the code). Since you probably have the code for the function it’s even easier. So from here, just add a check for null on the PostedFile before using it and you’re good to go.
Leaving a debugger running and logging exceptions
I have shown you one way of leaving the debugger running and logging inside the debugger itself, but sometimes it’s convenient to do in a script since it might be your web admin or someone that needs to run this.
Create a config file called TrackCLR.cfg with the following contents
<ADPLUS>
<SETTINGS>
<RUNMODE>CRASH</RUNMODE>
</SETTINGS>
<PRECOMMANDS>
<CMD>!load clr10\sos</CMD>
</PRECOMMANDS>
<EXCEPTIONS>
<OPTION>NoDumpOnFirstChance</OPTION>
<OPTION>NoDumpOnSecondChance</OPTION>
<CONFIG><!-- This is for the CLR exception -->
<CODE>clr</CODE>
<ACTIONS1>Log</ACTIONS1>
<CUSTOMACTIONS1>!cen;!clrstack;gn </CUSTOMACTIONS1>
<RETURNACTION1>GN</RETURNACTION1>
</CONFIG>
</EXCEPTIONS>
</ADPLUS>
And run adplus –pn myprocess.exe –c TrackCLR.cfg
This will generate a log file in a folder under the debuggers directory with managed stacks and exception types for each .net exception.
Or you can even take it one step further and create a dump when a specific exception occurs for example using this config file.
<ADPLUS>
<SETTINGS>
<RUNMODE>CRASH </RUNMODE>
</SETTINGS>
<PRECOMMANDS>
<CMD>!load clr10\sos </CMD>
</PRECOMMANDS>
<EXCEPTIONS>
<OPTION>NoDumpOnFirstChance </OPTION>
<OPTION>NoDumpOnSecondChance </OPTION>
<CONFIG><!-- This is for the CLR exception -->
<CODE>clr </CODE>
<ACTIONS1>Log </ACTIONS1>
<CUSTOMACTIONS1>!clr10\sos.cce System.InvalidOperationException 1; j ($t1 = 1) '.dump /ma /u c:\temp_dumps\exceptiondump.dmp;gn' ; 'gn' </CUSTOMACTIONS1>
<RETURNACTION1>GN </RETURNACTION1>
<ACTIONS2>Void </ACTIONS2>
<RETURNACTION2>GN </RETURNACTION2>
</CONFIG>
</EXCEPTIONS>
</ADPLUS>
The cce (CheckCurrentException) command will set the registry $t1 to 1 or 0 depending on if the CLR exception matches the type you specified. (The 1 passed in as the second argument to cce specifies that we want register t1 and you can choose either t1 or t0 here)
j ($t1 = 1) is an if statement, so this will dump if register $t1 is set to 1, and otherwise just go.
Happy hunting…
– All rules have exceptions, except the ones that don’t.
