Visual Studio 2010’s Historical Debugging feature fascinates me. As you sit in the debugger, being able to move backwards while in the debugger (or attach the execution log to a bug) has to be the killer feature coming up in the entire Visual Studio 2010 release. Sure, there are some nice things with Silverlight, TFS, and WPF, but they are all secondary in my opinion. Of course, I’m extremely biased as I love all things diagnostics, but you do have to agree anything that lets you fix bugs easier is always the feature you really need at 3AM.
Using Visual Studio 2010 Beta 1, I wanted to describe how Historical Debugging worked because I feel Historical Debugging will change the way you debug so it’s worth starting to look at it now. Also, well, it’s just very cool to figure out how something works. I’m not going to cover much about how you use Historical debugging because it’s mostly obvious how it works and everyone has access to the Beta 1 bits. If you haven’t had a chance to install and use Historical Debugging, Habib Heydarian, PM of all things Diagnostics, has a great overview on his blog.
What I’m going to discuss here is the two sides to Historical Debugging. The first part is how Historical Debugging gets its hooks into your code so it can record what’s going on. The second part is how Historical Debugging decided what events to report and shows how you can extend the reporting model.
As you can imagine, there are all sorts of huge disclaimers on what I’m going to talk about here. This article is based on Beta 1 and is all subject to change so nothing is guaranteed to ever work this way again. Additionally, if you rely on anything in the article it could cause your dog to run off, your plants to die, and you to develop fege bosta so bad nothing will help
Before we dive in, I do have to bring up one disappointing facet to Historical Debugging; it’s 32-bit only. I’ve been in this business long enough to know software development is all about tradeoffs and “Shipping is a Feature” so something had to give during scheduling. However, my personal opinion is that I would have gladly traded the WPF UI for full x64 support across the all tools in Visual Studio, more diagnostic features, project file compatibility between VS 2008 and VS 2010, more TFS features, and speed, speed, and more speed. Don’t get me wrong, Visual Studio 2010 will be a huge landmark release, but I think a wholesale UI change could have waited for another release or two. (Again, I definitely don’t speak for Microsoft, and I don’t speak for anyone else at Wintellect.)
The place to start with Historical Debugging is the Options dialog as that’s where everything is controlled. The first decision is whether you want to record events only or Events, Methods and Parameters.
Obviously, selecting Events, Methods, and Parameters will record much more information. Some rough calculations on the data file sizes show that Event only files are about 20% the size of full information files. As this is Beta 1, I didn’t bother doing any performance tests for the different collection types.
The tantalizing portion of the above dialog are the three grayed out buttons because they allude to the fact that while not supported in Beta 1, future Betas and releases will allow us to control exactly what information we want collected. I can’t wait to see what future releases will allow us to control. Can you imagine how cool it will be if have a hypothesis about a production-only problem and you can develop a collection plan that looks for just that information on the production server without killing performance? That will really make some of those debugging challenges we all face much easier. Now you see why I’m so interested in Historical Debugging!
For Beta 1, the two interesting Options pages are Diagnostic Events and Modules. The Modules is easiest to understand because that’s where you tell Historical Debugging which modules you want to collect data from or exclude from data collection. If you add modules to the Modules list the values you add are stored in the solution’s .SUO file for Beta 1 so if you delete the .SUO, you lose your settings. 
The Diagnostic Events page is the more exciting set of options because it shows you what Beta 1 supports out of the box for the different events recorded by Historical Debugging. While you can enable and disable individual categories and items, Beta 1 doesn’t offer a way to add or remove events through the UI. What lead me on my journey digging into how Historical Debugging works is I wanted to find if I could add my own items to the Diagnostic Events page.
When you are debugging with Historical Debugging turned on, you’ll see two additional DLLs in your address space, which you can see with Process Explorer. The first is a .NET assembly from the GAC, Microsoft.VisualStudio.TraceLog.Runtime.DLL, which I’ll talk more about in a minute. The second is a native DLL, TraceLogProfiler.DLL, which version information description is “VS Logger CLR Profiler.” The description gives away that Historical Debugging is done through a CLR profiler, but what is that profiler doing? As CLR 4.0 profilers can still use the COR_PROFILER environment variable, I saw the value 301EC75B-AD5A-459C-A4C4-911C878FA196, which looking in the registry got me to its COM registration, where the default value gives yet another hint: “Visual Studio Trace Debugger Instrumentation.”
It’s probably not too big a surprise that Historical Debugging is using IL rewriting to inject its hooks into the application as about the only other way would be to require you instrument the IL on disk before you run the binary. Peeking at what the instrumentation looks like is relatively easy with WinDBG and a little SOS magic. For those of you that haven’t done any SOS work with WinDBG and CLR 4.0, the basic idea is still the same. The only difference is that instead of MSCORWKS.DLL being the key DLL, it’s now CLR.DLL. Thus, to load the correct SOS extension, use .loadby sos clr and you’ll be on your way.
The snippet of disassembled code below shows examples of the instrumented code for a Windows Forms Main method where I’ve turned on collection for events, methods, and parameters. I highlighted in red the code injected by Historical Debugging.
0:013> !u 14c8720c
Normal JIT generated code
AnimatedAlgorithm.AnimatedAlgorithmForm.Main()
Begin 14d4bb90, size 70
14d4bb90 push ebp
14d4bb91 mov ebp,esp
14d4bb93 push eax
14d4bb94 cmp dword ptr ds:[14C79D34h],0
14d4bb9b je 14d4bba2
14d4bb9d call clr!JIT_DbgIsJustMyCode (71773bfb)
14d4bba2 mov ecx,2
14d4bba7 call 1162ea70 (Microsoft.VisualStudio.TraceLog.TraceRuntime.
AddEnterNoParametersMethod(Int32), mdToken: 06000172)
14d4bbac nop
14d4bbad mov edx,1
14d4bbb2 mov ecx,2
14d4bbb7 call 1483a760 (Microsoft.VisualStudio.TraceLog.TraceRuntime.
AddCallSite(Int32, Int32), mdToken: 06000175)
14d4bbbc mov ecx,14C872CCh (MT: AnimatedAlgorithm.AnimatedAlgorithmForm)
14d4bbc1 call clr!JIT_NewCrossContext (7151890e)
14d4bbc6 mov dword ptr [ebp-4],eax
14d4bbc9 mov ecx,dword ptr [ebp-4]
14d4bbcc call 1269f214 (AnimatedAlgorithm.AnimatedAlgorithmForm..ctor()
14d4bbd1 mov edx,6
14d4bbd6 mov ecx,2
14d4bbdb call 1483a760 (Microsoft.VisualStudio.TraceLog.TraceRuntime.
AddCallSite(Int32, Int32), mdToken: 06000175)
14d4bbe0 mov ecx,dword ptr [ebp-4]
14d4bbe3 call dword ptr ds:[2606608h] (System.Windows.Forms.Application.
Run(System.Windows.Forms.Form), mdToken: 060012e4)
14d4bbe9 nop
14d4bbea int 3
14d4bbeb nop
14d4bbec mov ecx,2
14d4bbf1 call 14d4b750 (Microsoft.VisualStudio.TraceLog.TraceRuntime.
AddLeaveNoParametersMethod(Int32), mdToken: 06000174)
14d4bbf6 call 14d4b9f0 (Microsoft.VisualStudio.TraceLog.TraceRuntime.
DumpResult(), mdToken: 0600017d)
14d4bbfb nop
14d4bbfc mov esp,ebp
14d4bbfe pop ebp
14d4bbff ret
For those of you paying close attention to the disassembly, the CLR JIT compiler defaults to a fastcall calling convention so ECX is the first parameter and EDX is the second parameter. Looking with Reflector at Microsoft.VisualStudio.TraceLog.Runtime.DLL makes it easy to see what the key TraceLog class expects as parameters. For example, the AddCallSite method, takes a metadata token and an offset as its two parameters. The job of these injected method calls are to collect the minimal data and get it to the logger.
By the way, Reflector works with CLR 4.0, but does not correctly find assemblies in the GAC as the internal GAC directory structure has changed. To load an assembly from the CLR 4.0 GAC, you’ll have to find the assembly in a PowerShell window manually to specify the full path in the Open dialog. I’m sure Red Gate will have an update to Reflector around the Beta 2 timeframe.
Winding through a method like TraceLog.AddCallSite shows that the information is packed up and put on a named pipe. I won’t bother grinding through how that works because there’s nothing too exciting about it. The interesting thing is that if you look with Process Explorer at a Windows Forms application, you’ll see the process start hierarchy is DEVENV.EXE, the debuggee process, and VSTRACELOG.EXE. From the name, you can guess that is where the actual logging occurs. Peaking at the handles for the debuggee and VSTRACELOG.EXE shows named events and sections (memory mapped files) shared between the two processes.
As the debuggee starts VSTRACELOG.EXE, the key coordination information has to be passed through either environment variables or command line parameters. Process Explorer makes it easy to see the command line parameters (which I’ve put each on their own line)):
“C:VSNET10Team ToolsTraceDebugger ToolsVSTRACELOG.EXE”
run
/n:”animatedalgorithm.exe_0000058c_01c9edf3f5c6b945″
/cp:”C:ProgramDataMicrosoft Visual Studio10.0
TraceDebuggingSettingsgnlg3dip.3pv”
/f:”AnimatedAlgorithm_090615_130041.tdlog”
To see what those command line values mean, I figured it couldn’t hurt to try VSTRACELOG.EXE run /? and it turns out to work! Sometimes reverse engineering is mastering the obvious. Here’s what each value means:
- run: Runs a logger.
- /n: The logger name.
- /cp: The collection plan to use
- /f: The name of the log file.
The paths specified in the above command line looked to be the same value specified in the Options dialog, Historical Debugging node Advanced page, Location of Historical Recordings edit control. Of most interest to me was /cp because that’s when I looked at GNLG3DIP.3PV, it is actually an XML file that contains some runtime setting information. Mostly the file has a bunch of elements that look to be the events recorded by Historical Debugging because the values line up with those displayed in the Diagnostic Events in the Options Dialog I showed earlier. As the filename is obviously a temporary filename, I went on a little quest to see what generated the collection plan file for the run.
Running Process Monitor as I started a new debugging session it was easy to figure out what was going on. DEVENV.EXE was reading from the HKCUSoftwareMicrosoftVisualStudio10.0DialogPageMicrosoft.VisualStudio.TraceLogPackage.ToolsOptionDiagnosticEventsNotifyPoints registry key right before is created the collection plan file. Looking at that key was a little confusing because it’s a bunch of REG_SZ values with numbers as the name and True or False as the data.
A more careful look at the Process Monitor log showed DEVENV.EXE reading C:VSNET10Team ToolsTraceDebugger ToolsenCollectionPlan.xml. Aha! That’s where the base collection plan is stored for Beta 1. (Note I installed VS 2010 into C:VSNET10 instead of the default directory.)
Looking at CollectionPlan.XML it isn’t too hard to figure out what’s going on. At the top of the file is the ModuleList element, which is the list of assemblies shown in the Options dialog, Historical Debugging node, Modules property page. Today, this list automatically has wildcard characters at the beginning and end of the values so it’s a big hammer. I suspect we’ll see much better control over modules in future beta releases.
The most interesting part of the file starts with the TracePointProvider element. What I’ll do to show how a collection plan works is show the pieces for the Console.WriteLine events. To define a new collection category, you need, well, the Categories and sub Category elements.
<Categories>
<Category ID=“console“ _locID=“category.SystemConsole“>Console</Category>
</Categories>
The value of the Category is what will appear in the Diagnostic Events property page.
After the Categories, you need to define a mapping between the assembly name and a module ID in the ModuleSpecification element.
<ModuleSpecifications>
<ModuleSpecification ID=“mscorlib“>mscorlib.dll</ModuleSpecification>
</ModuleSpecifications>
The super interesting part of the collection plan starts under the NotifyPointSpecifications element as that’s where you define the events themselves.
<NotifyPointSpecifications>
For each event recorded by historical debugging, there is a NotifyPointSpecification. The enabled attribute is true if reporting of this notify point is enabled, false means don’t report it.
<NotifyPointSpecification enabled=“false“>
The Binding element is obviously how Historical Debugging knows how to hook a particular method. In Beta 1 all of the defined Binding elements have their explicit attributes set to false, which I suspect means to look up the MethodId element values through metadata instead of by token or address. Several of the notification points in the Beta 1 CollectionPlan.XML file show another attribute on the Binding element, onReturn=”true”, which will show the return value for the event.
<Bindings>
<Binding explicit=“false“>
Next comes the mapping to the ModuleSpecification element described earlier.
<ModuleSpecification>mscorlib</ModuleSpecification>
Here’s the method you want to report the event on by type, method, and complete method id.
<TypeName>System.Console</TypeName>
<MethodName>WriteLine</MethodName>
<MethodId>System.Console.WriteLine(System.String):System.Void</MethodId>
The SettingsName element says (0 args) but that is wrong. (It is Beta 1 after all!). The SettingsName value is what Options Dialog, Historical Debugging node, Diagnostic Events property page shows.
<SettingsName _locID=“settingsName.WriteLine“>WriteLine (0 args)</SettingsName>
The Name element is what the Debug History window shows when the event is the single line mode and the Description element shows when you click on the event.
<Name _locID=“name.WriteLine“>Console Output “{0}”</Name>
<Description _locID=“description.WriteLine“>Console Output “{0}”</Description>
To make the above clear, here’s a screen shot showing where the two elements are used.
The Category mapping is presented and the other elements are closed off.
<Category>console</Category>
</Binding>
</Bindings>
The DataQuery elements are where the real action occurs because that’s where parameters and return values are processed so they can be used in the format strings in the Name and Description elements. It’s not clear what the index attribute is supposed to be. There are values ranging from -1 to 2 in the Beta 1 CollectionPlan.XML file. I originally thought they would correspond to format indexes, but they don’t. I did figure out -1 means a return value and only works if you specify onReturn=”true” on the Binding element. The type and name attributes are interesting as those are the values displayed in the Autos window when you click Autos link in an individual event.
<DataQueries>
<DataQuery index=“0“ maxSize=“256“ type=“String“ name=“value“></DataQuery>
</DataQueries>
</NotifyPointSpecification>
</NotifyPointSpecifications>
The above DataQuery is straightforward to pick out, but they get much more interesting. The following snippet from the FileStream.Dispose event shows a value for the element, _fileName, which maps to a field in the FileStream class. If a field is not displayed, the name is assumed to be the parameter or field.
<DataQuery index=“0“ maxSize=“256“ type=“String“ name=“fileName“>_fileName</DataQuery>
Continuing to poke through the Beta 1 CollectionPlan.XML turned up an extremely interesting option for reporting parameters::
<NotifyPointSpecification>
<Bindings>
<Binding explicit=“false“>
<ModuleSpecification>system</ModuleSpecification>
<TypeName>System.Diagnostics.TraceListener</TypeName>
<MethodName>TraceEvent</MethodName>
<MethodId>System.Diagnostics.TraceListener.TraceEvent(
System.Diagnostics.TraceEventCache,
System.String,
System.Diagnostics.TraceEventType,
System.Int32,
System.String,
System.Object[]):System.Void</MethodId>
<SettingsName _locID=“settingsName.TraceEvent“>TraceEvent with format
arguments</SettingsName>
<Category>tracing</Category>
</Binding>
</Bindings>
<DataQueries />
<ProgrammableDataQuery>
<ModuleName>Microsoft.VisualStudio.DefaultDataQueries.dll</ModuleName>
<TypeName>Microsoft.VisualStudio.DataQueries.Tracing.TraceListener.
TraceEventFormat</TypeName>
</ProgrammableDataQuery>
</NotifyPointSpecification>
The ProgrammableDataQuery element gives us a glimpse at the extensibility hooks into event recording. Opening up Microsoft.VisualStudio.DefaultDataQueries.DLL shows that if you derive your class from the IProgrammableDataQuery interface, shown below, you’ll be handed the parameters and return values so you can do more analysis to report better data for your events.
public interface IProgrammableDataQuery
{
// Methods
object[] EntryQuery(object thisArg, object[] args);
object[] ExitQuery(object returnValue);
List<KeyValuePair<string, string>>
FormatCollectedValues(object[] results);
string FormatLongDescription(object[] results);
string FormatShortDescription(object[] results);
}
All of the information I discussed here will probably all change by the time Beta 2 ships, but it’s still worth looking at to give you ideas to start thinking how you can about how to extend Historical Debugging for your particular scenarios. My mind is already working overtime on the tools I might be able to develop to help automate building your own collection plans for custom libraries. Granted building FxCop/Code Analysis rules has always been undocumented (and will continue to be in VS 2010), we can hope for full documentation on how to extend Historical Debugging, but don’t be surprised if there isn’t any. I can’t wait to get my hands on Beta 2, as I’m sure it will be super exciting from a Historical Debugging perspective!