ExceptionMon

Once I had ProfilerLib up and running, I was able to start ExceptionMon. Looking at the ICorProfilerCallback interface, you'll see that you have all sorts of amazing callbacks to let you know exactly what processing is happening when an exception occurs. It's almost like someone at Microsoft was reading my mind! At an initial glance, you might think that ExceptionMon was absolutely trivial to implement. As usual, reality was a little bit different.

In my design for ExceptionMon, I wanted to record which exception was thrown, which finally handlers were called, and where the exception was handled. The exception handling notification methods in the ICorProfilerCallback interface, listed in the following code, fit the bill exactly. The fact that you also get the function IDs as well as the object ID of the exception thrown and caught is icing on the cake.

    STDMETHOD ( ExceptionThrown ) ( ObjectID thrownObjectId ) ;     STDMETHOD ( ExceptionUnwindFinallyEnter ) ( FunctionID functionId ) ;     STDMETHOD ( ExceptionCatcherEnter ) ( FunctionID functionId ,                                           ObjectID   objectId    ) ;

I quickly whipped up the initial ExceptionMon using ProfilerLib, writing the output to a logging file in the same directory the process ExceptionMon is loaded into. The first small issue I ran into was how to best debug ExceptionMon. Since the CLR does all the work to bring the specified profiler into the address space, I wanted to ensure I could start debugging right from the beginning. Since you already have to utilize environment variables to get the profiler started, I decided to go ahead and add one, EXPMONBREAK, which, if set, would cause ExceptionMon to call DebugBreak so that I could get a debugger attached.

Although you can debug the profiler like you would with any native DLL loaded into a process, I prefer the DebugBreak call because the profiler will be loaded into Visual Studio .NET since it hosts the CLR. You can always limit the process loading by setting the EXPMONPROC environment variable to set just the single process to debug. However, for development and testing purposes, I like to run multiple programs to test. By using the EXPMONBREAK scheme, I can get multiple debuggers attached to multiple processes easily.

Because I am mentioning environment variables, I need to talk about two that are primarily for handling ASPNET_WP.EXE/W3WP.EXE exception monitoring. By default, ExceptionMon doesn't flush the output file, so you need to stop ASPNET_WP.EXE/W3WP.EXE to see any reported exceptions. However, if you set the EXPMONFLUSH environment variable, all writes are flushed immediately.

The other issue with file writing is that ExceptionMon will put the logging file into the same directory as the process, but that's a problem because the default ASPNET account probably doesn't have permission to create files in %SYSTEMROOT%\Microsoft.NET\Framework\%FRAMEWORKVERSION%, which is where ASPNET_WP.EXE resides. For Windows Server 2003, the account is NETWORK SERVICE and W3WP.EXE resides in %SYSTEMROOT%\System32\inetsrv. The EXPMONFILENAME environment variable is where you can specify the complete path and filename for the output file for ExceptionMon. Obviously, you'll have to double-check that the ASPNET user account has create and write permission to the directory.

The initial version of ExceptionMon worked great because you were handed the function ID and object IDs and could simply call the appropriate methods in the ICorProfilerInfo interface to acquire the class and function tokens to look up names in the metadata. The code in Listing 10-1, CBaseProfilerCallback::GetClassAndMethodFromFunctionId, shows all the work necessary to look up the class and method names from a function ID.

In-Process Debugging and ExceptionMon

Once the basic version was up and running, I thought a useful feature would be to add a stack trace whenever an exception was thrown. That way you could see how you got into the situation in the first place and could take a look at the conditions. Looking at the documentation for the profiling API, I noticed you could pass a bit option to ICorProfilerInfo::SetEventMask—COR_PRF_ENABLE_INPROC_DEBUGGING—to turn on in-process debugging.

With in-process debugging, the profiling API gives you notifications of events, but you'll need some way of gathering more detailed information that you can get through the ICorProfilerInfo interface. Since Microsoft has already developed a fine advanced debugging API that works hand-in-hand with the CLR, the idea was to give us a limited version of the debugging API, which can perform tasks like look up live variable values and walk the stack.

The complete debugging API is discussed in the DebugRef.DOC in the same directory as the profiling API and metadata API documents. As with all documents found in the Tools Developers Guide directory, DebugRef.DOC is long on describing the interface, method, and parameter values, and pretty short on usage. The Samples directory contains a working debugger that's about 98 percent of the real CORDBG source code, but the actual code is sometimes confusing to follow although it will eventually reveal its secrets.

When reading over the debugging API documentation, pay special attention to which methods are callable from in-process debugging. If the method has "Not Implemented In-Process" in green text below its name, you can't use the method. What you'll find is that most of the methods you can't use are related to setting breakpoints and changing values. Since the main reason you'll need the in-process debugging is simply for information gathering, the important parts are fully accessible.

The first step to using in-process debugging with the profiling API is to set the COR_PRF_ENABLE_INPROC_DEBUGGING flag when calling ICorProfilerInfo::SetEventMask. Interestingly, simply setting that flag causes two side effects. The first is that once you request in-process debugging, the profilee will run slower. That's because the CLR won't use any precompiled code that is compiled with NGEN.EXE, thus forcing that code to be jitted like it normally would. You might not be using NGEN.EXE, but the .NET Framework uses it quite a bit, so that's where you'll take the hit.

If you've run NGEN.EXE, you might have noticed that you have a command-line option named /PROF that adds profiling information to generated code. Although you might think it's worth a shot, the profiling API currently doesn't support it, so you can't use it. I still think the limitations of slower code are worth it because of the benefits.

The second issue you'll run into is undocumented and completely confused me when I first encountered it. The ICorProfilerCallback::ExceptionThrown method is passed an object ID that describes the class being thrown. With my first implementation, which didn't use in-process debugging, I always got an ID I could pass to CBaseProfilerCallback::GetClassAndMethodFromFunctionId. Simply adding the COR_PRF_ENABLE_INPROC_DEBUGGING flag to ICorProfilerInfo::SetEventMask and not even using the actual in-process debugging API changes something internally so that an object ID of 0 is the only thing passed. Even though the in-process debugging API had the necessary methods to find the information, it was quite disconcerting to wonder what had happened to my object ID simply because I tripped a flag!

To use the debugging interfaces, you first have to call the ICorProfilerInfo::BeginInprocDebugging method to start the process of acquiring the appropriate interface. As part of that call, you'll pass a DWORD pointer to a context cookie. You'll need to save that cookie so that you can pass it to the ICorProfilerInfo::EndInProcDebugging method you have to call to indicate you're stopping in-process debugging. The second step is to acquire the appropriate debugging interface. If you're interested only in the current thread, you call the ICorProfilerInfo::GetInprocInspectionIThisThread method to get the IUnknown interface, which you can query for the ICorDebugThread interface. If you want to do process-wide debugging, you call the ICorProfilerInfo::GetInprocInspectionInterface and query the return IUnknown for ICorDebug. Personally, I don't see why the two ICorProfilerInfo methods can't simply return the appropriate interfaces.

Once you have the debugging interface, you're all set to access the debugging API to get the information you need from it. In my case, I wanted to get the last exception on the thread, so all I needed to do was call the ICorDebugThread::GetCurrentException method to get the ICorDebugValue interface, which describes the last exception thrown. The odd thing was that every time I called the ICorDebugThread::GetCurrentException method, it failed, so I was really starting to wonder if I was ever going to get ExceptionMon working!

After a very careful read of the profiling and debugging API documents, I came across a statement saying that in order to have in-process debugging do any stack operations, you need to call ICorDebugThread::EnumerateChains. The debugging API uses the concept of stack chains to string together the managed and native stack traces, which add up to the complete stack trace. I couldn't see that calling ICorDebugThread::GetCurrentException would have anything to do with the stack, but I figured it was worth a try to call ICorDebugThread::EnumerateChains before I did anything else. Though not documented—at least not clearly—I figured out that to do anything with the debugging API, you need to call ICorDebugThread::EnumerateChains first or most methods will fail. Listing 10-2 shows the wrapper method I use inside ExceptionMon to get in-process debugging started.

Listing 10-2: BeginInprocDebugging

 HRESULT CExceptionMon ::      BeginInprocDebugging ( LPDWORD               pdwProfContext     ,                             ICorDebugThread **    pICorDebugThread   ,                             ICorDebugChainEnum ** pICorDebugChainEnum ) {     // Tell the profiling API I want to get the in-process debugging     // stuff.     HRESULT hr = m_pICorProfilerInfo->                                 BeginInprocDebugging ( TRUE          ,                                                        pdwProfContext );     ASSERT ( SUCCEEDED ( hr ) ) ;     if ( SUCCEEDED ( hr ) )     {         IUnknown * pIUnknown = NULL ;             // Ask the profiling API for the IUnknown I can get the         // ICorDebugThread interface from.         hr = m_pICorProfilerInfo->                         GetInprocInspectionIThisThread ( &pIUnknown ) ;         ASSERT ( SUCCEEDED ( hr ) ) ;         if ( SUCCEEDED ( hr ) )         {             hr = pIUnknown->                     QueryInterface ( __uuidof ( ICorDebugThread ) ,                                      (void**)pICorDebugThread       ) ;             ASSERT ( SUCCEEDED ( hr ) ) ;                          // No matter what happens, I don't need the IUnknown any             // more.             pIUnknown->Release ( ) ;                          // I'm doing this as part of the normal processing because             // if you don't call ICorDebugThread::EnumerateChains as             // the first thing called off ICorDebugThread, many of the             // other methods will fail.             if ( SUCCEEDED ( hr ) )             {                 hr = (*pICorDebugThread)->                             EnumerateChains ( pICorDebugChainEnum ) ;                 ASSERT ( SUCCEEDED ( hr ) ) ;                 if ( FAILED ( hr ) )                 {                     (*pICorDebugThread)->Release ( ) ;                 }             }         }     }     return ( hr ) ; }

Once I was able to get ICorDebugThread::GetCurrentException to return a proper value, I thought I was home free because all I had to do was get the class name from the ICorDebugValue. Alas, looking through all the interfaces related to values—ICorDebugGenericValue, ICorDebugHeapValue, ICorDebugObjectValue, ICorDebugReferenceValue, and ICorDebugValue—I realized there was obviously a lot more to it because only ICorDebugObjectValue had the GetClass method necessary to get the class interface that would get the name. That meant I had to do some work to translate the original ICorDebugValue from ICorDebugThread::GetCurrentException into the ICorDebugObjectValue. The easiest thing for me to do is show you the code that does all the work in Listing 10-3. As you can see, it's a matter of dereferencing the object and querying for the ICorDebugObjectValue interface.

Listing 10-3: GetClassNameFromValueInterface

 HRESULT CExceptionMon ::     GetClassNameFromValueInterface ( ICorDebugValue * pICorDebugValue ,                                      LPTSTR           szBuffer        ,                                      UINT             uiBuffLen        ) {     HRESULT hr = S_FALSE ;         ICorDebugObjectValue * pObjVal = NULL ;          ICorDebugReferenceValue * pRefVal = NULL ;          // Get the reference to this value. Exceptions should come in this     // way. If getting the ICorDebugReferenceValue fails, the type is     // ICorDebugGenericValue. There's nothing I can do with a     // ICorDebugGenericValue as I need the class name.     hr = pICorDebugValue->                  QueryInterface ( __uuidof ( ICorDebugReferenceValue ),                                    (void**)&pRefVal                    );     if ( SUCCEEDED ( hr ) )     {         // Dereference the value.         ICorDebugValue * pDeRef ;         hr = pRefVal->Dereference ( &pDeRef ) ;                  if ( SUCCEEDED ( hr ) )         {             // Now that I dereferenced, I can ask for the object value.             hr = pDeRef->                     QueryInterface ( __uuidof ( ICorDebugObjectValue ),                                     (void**)&pObjVal                 );                                                  // I no longer need the dereference.             pDeRef->Release ( ) ;         }         // I no longer need the reference.         pRefVal->Release ( ) ;     }         ASSERT ( SUCCEEDED ( hr ) ) ;     if ( SUCCEEDED ( hr ) )     {         // Get the class interface for this object.         ICorDebugClass * pClass ;              hr = pObjVal->GetClass ( &pClass ) ;                  // I don't need the object reference any more.         pObjVal->Release ( ) ;              ASSERT ( SUCCEEDED ( hr ) ) ;         if ( ( SUCCEEDED ( hr ) ) )         {             // Gotta have the class type def token value.             mdTypeDef ClassDef ;             hr = pClass->GetToken ( &ClassDef ) ;                          ASSERT ( SUCCEEDED ( hr ) ) ;             if ( SUCCEEDED ( hr ) )             {                 // In order to look up the class token, I need the                 // module so I can query for the meta data interface.                 ICorDebugModule * pMod ;                 hr = pClass->GetModule ( &pMod ) ;                          ASSERT ( SUCCEEDED ( hr ) ) ;                 if ( SUCCEEDED ( hr ) )                 {                     // Get the metadata.                     IMetaDataImport * pIMetaDataImport = NULL ;                         hr = pMod->                         GetMetaDataInterface ( IID_IMetaDataImport ,                                     (IUnknown**)&pIMetaDataImport   ) ;                                  ASSERT ( SUCCEEDED ( hr ) ) ;                     if ( SUCCEEDED ( hr ) )                     {                         // Finally, get the class name.                         ULONG ulCopiedChars ;                                                  hr = pIMetaDataImport->                                   GetTypeDefProps ( ClassDef       ,                                                     szBuffer       ,                                                     uiBuffLen      ,                                                     &ulCopiedChars ,                                                     NULL           ,                                                     NULL            ) ;                         ASSERT ( ulCopiedChars < uiBuffLen ) ;                         if ( ulCopiedChars == uiBuffLen )                         {                             hr = S_FALSE ;                         }                                                                                   pIMetaDataImport->Release ( ) ;                     }                     pMod->Release ( ) ;                 }             }             pClass->Release ( ) ;         }     }     return ( hr ) ; }

After getting the class name of the exception, I just had to walk the stack. I'd already gotten the ICorDebugChainEnum interface, so walking the stack was a simple matter of following the algorithm discussed in the DebugRef.DOC file. The only interesting issue regarding the stack walking is that you can't walk native stacks with the debugging API. To check whether a chain is a native, call ICorDebugChain::IsManaged.

I've found ExceptionMon to be invaluable to help me keep an eye on the exceptions my applications are generating. I'm perfectly happy with the text file output, but you might want to consider adding an option to push the output over to a GUI application so that you can see the exceptions in almost real time. Adding that option isn't a huge programming exercise and would be an excellent way to learn about Windows Forms programming!