High memory utilization in dbghost.exe when using Debugdiag

I have seen lately many issues where Administrators and developers alike are claiming that Debugdiag is causing the whole server to become unresponsive.

In some situation, the debugger host (dbghost.exe) grows uncontrollably in memory consumption causing it to shutdown which will bring the target process the debugger was attached to to terminate as well. 

In other situations, the debugger host (dbghost.exe) along with the target process seem to just be consuming all CPU cycles rendering the whole server unresponsive.

I looked into these issues to try to determine the root cause of these problems. And what I have noticed was something very interesting.

The first issue in which dbghost.exe seems to be leaking memory was actually an issue with .net 2.0 debugger extension (sos.dll).  Here is a description of the problem and how to resolve it.

As you may have already known, Debugdiag relies mainly on sos.dll for .net debugging. So when you create a crash rule to catch a .net exception and run actions, dbghost.exe loads sos.dll and runs the "!dumpobj" command to determine the type of exception that was throws every time a .net exception is thrown. Below how the script for a crash rule determines the type of .net exception thrown.

    1: Function GetCLRExceptionType(ByVal ExceptionObjHexAddr, ByVal bInnerException)
    2:     Dim Output, Lines, i
    3:  
    4:     If Debugger.IsClrExtensionMissing Then
    5:         WriteToLog "Unable to determine CLR exception type - extension dll could not be loaded."
    6:     Else
    7:         Output = Debugger.Execute("!DumpObj " & ExceptionObjHexAddr)
    8:         Lines = Split(Output, Chr(10))
    9:         For i = 0 To UBound(Lines)        
   10:             If bInnerException Then
   11:                 If InStr(Lines(i), "_innerException") <> 0 Then
   12:                     Tokens = Split(Lines(i), " ")
   13:                     For j = 0 To UBound(Tokens)
   14:                         If Len(Tokens(j)) = 8 Then                                
   15:                             GetCLRExceptionType = GetCLRExceptionType(Tokens(j), False)
   16:                             Exit For
   17:                         End If
   18:                     Next
   19:                 End If
   20:             ElseIf Len(Lines(i)) >= 7 Then
   21:                 If InStr(Lines(i), "Name: ") = 1 Then
   22:                     GetCLRExceptionType = Mid(Lines(i), 7)
   23:                     Exit For
   24:                 End If
   25:             End If
   26:         Next
   27:     End If
   28: End Function

Line 7 is where the "dumpobj" command is ran against the exception object to determine the type.

There is a known issue with the "dumpobj" command that it leaks 4k every time it is ran. This leads to a situation where dbghost.exe runs out of memory and terminates.

There is an updated sos.dll that fixes a different issue but contains a fix  for this problem. (https://support.microsoft.com/kb/967812). So all what needs to be done is to replace the existing sos.dll, and reactivate the crash rule.

The second issue has to do basically with the high rate of handled exceptions thrown by the target process (1st chance exceptions. It does not matter of the exceptions are managed or native.

For instance, if you look at the below log file generated for a crash rule, you see that there is a high number of exceptions thrown per sec.

 

    1: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 2200
    2: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.Threading.ThreadAbortException'
    3: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 2200
    4: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.Web.HttpContext'
    5: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
    6: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
    7: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
    8: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
    9: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   10: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   11: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   12: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   13: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   14: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   15: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   16: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   17: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   18: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   19: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   20: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   21: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   22: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   23: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   24: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   25: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   26: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   27: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   28: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   29: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   30: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   31: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   32: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   33: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   34: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   35: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   36: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   37: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   38: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   39: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 2656
   40: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'
   41: [1/27/2010 5:48:08 AM] First chance exception - 0xe0434f4d caused by thread with system id 6780
   42: [1/27/2010 5:48:08 AM] CLR Exception Type - 'System.InvalidOperationException'

 

An average of around 22 exceptions/sec.  Let look closely at what happens when an exception is raised: 

From https://support.microsoft.com/default.aspx?scid=kb;EN-US;105675...

.... if the application is being debugged, the debugger sees all exceptions before the program does. This is the distinction between the first and second chance exception: the debugger gets the first chance to see the exception (hence the name). If the debugger allows the program execution to continue and does not handle the exception, the program will see the exception as usual. If the program does not handle the exception, the debugger gets a second chance to see the exception. In this latter case, the program normally would crash if the debugger were not present.

...

In other words, when an exception is raised, control is passed to the debugger, the debuggers acts on that exception and passes control back to the program to handle the exception. This is an expensive operation and involve a lot of context switching. 

So, in this particular example, things are worse because for every CLR exception raised, debugdiag will run the command (!dumpObj ExceptionAddress ) to determine the type  "GetCLRExceptionType(GetCLRExceptionPtr(CausingThread), False)".  If sos.dll being used is the one with the leak issue, you will notice a high CPU utilization in both the debugger (dbghost.exe) and the target process  along with a quick increase in memory utilization in dbghost.exe. This will eventually lead to an unexpected termination of the debugger and the target process.

In the case of native exceptions, the issue will manifest itself as a high CPU that may lead to an unresponsive server as a whole! To be able to debug such environment, you would need to know what are the exceptions that are thrown in a high rate and avoid them.

Comments

  • Anonymous
    July 16, 2010
    The comment has been removed