April 2010
Volume 25 Number 04
IntelliTrace - Debugging Applications with IntelliTrace
By Justin Marks | April 2010
How does anyone fix a bug in their code? You set a few breakpoints, run the program under the debugger, do a little single-stepping—and pray the problem falls into your lap so you can get on to other things.
We’ve been doing the same style of debugging almost since the ENIAC was invented. This tedious and time-intensive debugging approach has served us well, but it’s time debugging got easier. With the release of Visual Studio 2010 Ultimate, the new IntelliTrace feature brings debugging into the 21st century by giving developers better insight into their applications’ execution.
Much like other monitoring and tracing tools such as Process Monitor from Windows Sysinternals, Visual Studio 2010 collects data about an application while it’s executing to help developers diagnose errors. The collected data is referred to as IntelliTrace events. These events are collected as part of the default debugging experience, and among other things, they let developers step back in time to see what happened in an application without having to restart the debugger.
In this article, I’ll introduce you to IntelliTrace and show how it provides value to developers as part of their day-to-day development activities. I’ll show how IntelliTrace provides a time line of events that occurred during the execution of an application, and how developers can use these events to aid debugging. Next, I’ll discuss the settings developers can change to collect a deeper set of information about the application to get a complete execution history. Finally, I’ll show how to use a previously recorded IntelliTrace file that was created by someone else—a tester—to debug an application, without having to run the application to reproduce the error.
When the Visual Studio diagnostics team started planning for Visual Studio 2010, we spent a lot of time talking to customers about how they diagnose problems in their applications. Though everyone has a different pattern and favorite set of tools, one point was overwhelmingly clear: the traditional methods of diagnosing application issues are difficult, time-consuming and costly. The bug reports that developers receive almost never have any steps to reproduce the problem, and mostly consist of statements like “I was using the program and it crashed.” In the rare case when decent repro steps are available, you may be faced with bugs occurring in specific environments, and this leads to a whole new set of problems to solve. Moreover, bugs often are caused by a misunderstanding of how a framework or other code operates.
With these pain points in mind, we set about to create a new debugger feature where the right information was collected at the time the problem occurred. Our goal was to hand developers the exact repro steps and system environment settings, as well as expose the behavior of frameworks and code they use, to drastically improve their diagnosability. With the release of Visual Studio 2010 Ultimate, IntelliTrace brings a greatly improved debugging experience by giving developers better insight into the application and framework behavior, as well as the ability to open an IntelliTrace file collected by a tester to resolve “no repro” scenarios.
Introducing IntelliTrace
When a developer needs a deeper understanding of code execution, IntelliTrace offers a way to “turn up the dial” to collect the complete execution history of an application.
To illustrate this, I will use the Tailspin Toys demo application to show you the type of information IntelliTrace can collect. To begin, I’ll open up the solution in Visual Studio and start debugging. When the Web site launches, I’ll navigate to the “About us” page and receive an error from the server. How might you diagnose the problem? If you’re anything like me, your first instinct is to configure the web.config file to not show custom errors and then restart the debugger. But what if this issue is intermittent? Wouldn’t it be nice if you could just break into the process at this point, after the error occurred, and get a history of what happened in the application from Visual Studio?
While you’re debugging, IntelliTrace collects data about a managed application in the background, including information from many framework components such as ADO.NET, ASP.NET and System.XML. These IntelliTrace events allow the developer to see what has previously occurred during execution, and most importantly, to “step back in time” to see prior states of the application without having to restart the debugger. When I break into the debugger, I’m immediately presented with a sequential list of the IntelliTrace events that were collected (see Figure 1).
Figure 1 Diagnostic Information Collected by IntelliTrace
As you can see from Figure 1, the list of IntelliTrace events goes far beyond file and registry accesses as you’d see in Process Monitor. We have defined almost 150 IntelliTrace events for Visual Studio 2010, and we plan on augmenting this list with additional events over time. Figure 2 highlights some of the categories of events that are collected by IntelliTrace.
Figure 2 IntelliTrace Events Are Available Across the Microsoft .NET Framework
Category | Description and Collected Data |
ADO.NET | Events around executing queries against SQL, the executed command as well as the connection string. |
ASP.NET | Events around the ASP.NET pipeline as well as request processing and redirection. |
Console | Console output. |
Data Binding | Windows Forms data binding. |
Environment Variables | Evaluation and retrieval of environment variables from the process. |
File | Creation, deletion and access of files. |
Gestures | User actions performed against common controls from Web forms, Windows Forms and WPF. In addition to collecting data about the interaction with the control, clicking on one of these events automatically redirects you to the appropriate event handler. |
Lazy Initialization | Initialization of lazily loaded variables. |
Registry | Creation, deletion and querying of registry information. |
Service Model | Web service calls from WCF. |
Threading | Queuing of user work items and parallel computing tasks. |
Tracing | Debugger trace output and assertions. |
User Prompt | Display of Windows Forms and WPF message boxes as well as the result of the dialog. |
Workflow | Activity instantiation and completion. |
XML | XML file loading. |
The IntelliTrace window lets me filter the list of collected events by category—the categories shown in Figure 2—or by thread. In addition, I can do text-based searches to find key events I can quickly jump to. Because IntelliTrace also collects exceptions, I can do a search for the term “exception” and the list will filter to show me the exception that caused the ASP.NET error page, both where it was thrown and where it was caught. In this case, the error was caused by an XMLException while parsing an entity on line 10, position 53 (see Figure 3). When I click on the thrown exception event, other debugger windows, such as the Call Stack and Watch windows, show data relative to the event itself, so it’s like you were debugging the instant that exception was thrown. In addition, just like walking up a call stack, the editor will open the appropriate source file and highlight the line of code corresponding to the event in orange to represent IntelliTrace.
Figure 3 An XMLException Was Thrown While Parsing an Entity on Line 10, Position 53
IntelliTrace has given me a very helpful piece of information for diagnosing the issue: an XML file was loaded and a specific character in the XML was unexpected or incorrect. But I still don’t know which file was accessed. Once again, IntelliTrace has collected the information I need—namely the file access.
Looking again at the IntelliTrace window in Figure 3, I can see that the event just prior to the exception is an XML file load event for “Content\Xml\Ads.xml.” This must be the file causing the error. I can easily open this file in Visual Studio. Looking at line 10, position 53, I see that there is indeed an error in this file, namely that “&b=1” is invalid for the NavigateUrl XML element. By removing these invalid characters, the Web site should now load correctly.
Now I want you to think about the last unhandled exception you debugged with traditional debugging techniques. If it was an exception like this one, you would have seen where the exception occurred, but definitely not the exact reason or the invalid character. This is the key to IntelliTrace—it gives you better information to diagnose issues quicker and easier. You have more important things to do than waste your time hunting around for information.
Using IntelliTrace to Track Debugger Events
I’ve just shown you how IntelliTrace collects exceptions, both handled and unhandled, that occur during an application’s execution, and how IntelliTrace events across the framework can provide insight into what an application did under the hood. But that’s not all. IntelliTrace also collects events caused by the debugger, namely breakpoints, tracepoints and stepping events.
One of the most common debugging techniques is to set a breakpoint near the point where you think a problem exists and then step through the code watching variables change. This is especially useful when debugging through loops, watching for a variable to change to a specific value. Unfortunately, most developers are impatient and pound the F10 key to step quickly through the code, only to find that they stepped too far. Then they need to restart their debugging session and try again. With IntelliTrace, all breakpoints and stepping events are recorded, along with their contextual data, so you can quickly navigate to points where you stopped before.
If I click on one of these debugger events, the Watch window will show me all the data I previously looked at, including values I evaluated in the Locals, Watch and Autos windows, as well as QuickWatch and DataTips.
Often, previously developed and deployed code doesn’t have the needed tracing built in to help debug issues that may arise. Breakpoints offer the ability to see more of what’s going on under the hood of the application. But most of the time, the developer doesn’t need to stop at the breakpoint; rather he wants to collect some data and continue execution. This is especially the case inside loops where you want a record of the iterator value without having to stop at each iteration. In these scenarios, tracepoints are a great alternative. Tracepoints let the developer make the debugger perform a custom action; that is, execute a macro or print out a trace message, instead of breaking execution. With IntelliTrace, the tracepoints output is collected and can be viewed in the same interface as the other IntelliTrace events (see Figure 4).
Figure 4 Tracepoints Can Dynamically Add Trace Outputs to Code
Turning up the Dial
By default, IntelliTrace is configured to collect only IntelliTrace events. This is a low-overhead solution but doesn’t provide a full execution history of your application. When you need a deeper level of information, IntelliTrace can be configured to collect more data. Like other debugger settings, IntelliTrace can be configured from the Options dialog, accessible from the Tools menu (see Figure 5).
Figure 5 IntelliTrace Settings Can Be Changed from the Options Dialog
Choosing “IntelliTrace events and call information” configures IntelliTrace to collect not only the IntelliTrace events, but also call information at every method enter, exit and callsite, such as parameters and return values at those locations. Unfortunately, enabling this mode causes Edit-and-continue to be disabled during the debugging session. Obviously, your choice to collect more information means there’s more overhead to your application. We worked very hard to find the balance between useful information and performance, but we do give you full control.
Every debugging session creates an IntelliTrace file stored on disk that is automatically cleaned up when Visual Studio closes. The IntelliTrace Advanced pane reached through the Options dialog lets you configure where you want the files created during debugging to be stored and how large they can be. If the maximum file size is reached, a circular buffer is used to help compress and truncate the information stored in the IntelliTrace log, thereby reducing the footprint on disk of the log file. The two other settings on the Advanced pane let you hide the navigation gutter and disable Team Foundation Server (TFS) lookup of available symbols.
Because of performance concerns, only a subset of the defined IntelliTrace events has been enabled for collection by default. Some of the events you may want to consider enabling are console output, file accesses, lazy initialization, registry accesses and threading events. You can enable or disable an entire category of events or individual events from the IntelliTrace Events pane in the Options dialog.
The final IntelliTrace Options pane allows you to control which modules IntelliTrace collects data from. All modules except those shipped by Microsoft as part of the Microsoft .NET Framework and Visual Studio are collected by default. A lot of data can be collected in this manner, so you may consider changing this list to an inclusion list and specifying only the modules you care about. Conversely, if you use some common third-party libraries, you may wish to exclude these, because they’re out of your control.
Investigating a User Code Error
Now that I’ve verified that the “About us” page is operational in the demo application, let’s make sure our shopping cart is working as well. When I add a paper airplane to the cart for purchase, I see that indeed it has been correctly added to the cart. However, when I repeat this action to add a second instance of the item to the cart, the quantity still shows as 1, though I expected it to show 2. I want to use the debugger to solve the problem without having to restart, but the list of IntelliTrace events probably won’t help me in this scenario (all the work was done in my code, not the .NET Framework). This is where the “IntelliTrace events and call information” mode of IntelliTrace can help show me an execution history of my application. Let’s break into the debugger and see what additional features of IntelliTrace I can use to solve this problem.
I start with the hypothesis that something went wrong with my “Add Item to Cart” logic. Because this is a Model-View-Controller (MVC) application, there is no event handler for the button click, but rather a POST message has been sent and handled by the MVC. This POST message has been recorded as an IntelliTrace event and, although it isn’t useful in itself, I use the event as a starting point for my investigation. By clicking this IntelliTrace event, I can jump to the point of the debugging session where the “Add Item” logic began. I can quickly find these POST messages by searching for the word “POST” in the IntelliTrace window. This action was taken twice by the user so, as I expected, two results are returned from the search. After selecting the second event, clearing the search field shows it in context with all of the collected events (see Figure 6).
Figure 6 The IntelliTrace Events View Can Help You Start Your Investigation
Now that I have context on where I am in the application’s timeline, I want to dig deeper and gain an understanding of the method calls that were made. From the Events view, I can switch views to see the execution history. By clicking on the “Switch to IntelliTrace Calls View” link at the top of the window, I can transition to the Calls view to see a complete execution history of the application (see Figure 7). At any time, I can go back to the Events view by clicking the “Switch to IntelliTrace Events View” link.
Figure 7 The IntelliTrace Calls View Shows the Execution History of the Application
One mechanism for navigating the execution history is to use the Calls view to drill into the calls you’re interested in investigating. Each time you double-click on a call in the bottom half of the Calls view, the call is popped to the bottom of the top half of the view, and the Instruction Pointer syncs in the code editor to the method entry point of the call, just like in live debugging when you walk up the call stack. You can continue to navigate and walk backward and forward through the data collected by IntelliTrace history in this way. Navigating through the Calls view is a quick mechanism for gaining an overview of the execution history and making large jumps around the code base.
Using the Calls view is only one method of navigation. I can also navigate by stepping through the code. In the gutter of the source code window, there’s a new set of DVR-style controls that allow you to step through the code, just as in a traditional debugging session (see Figure 8). Because I’m in IntelliTrace debugging mode, stepping is by recorded events that occur at every callsite, function enter and function exit. Of course, F10/F11 work as expected if you prefer keyboard controls.
Figure 8 The Navigation Bar Offers DVR-Style Controls to Let You Step Through Your Application
These two navigation methods are great for investigation, but sometimes you know exactly where you would have set the breakpoint. In the case of this application, I know the name of the function where the item is added to the cart: Kona.Model.ShoppingCart::AddItem. What I really want to do is jump to the second time this function was called and inspect the values passed into and returned from the function. More specifically, I want to seek to the line of code where the “AdjustQuantity” function call was made. Of course, IntelliTrace also supports this navigation technique.
In the editor, I can right-click on the line I wish to seek to and choose “Search For This Line In IntelliTrace” from the context menu (see Figure 9). The search begins and the results are presented in a search bar at the top of the editor window, allowing me to navigate between the search results. After synchronizing to the second search result, my instruction pointer is right where I want it to be and I can investigate the call using the other debugger windows (see Figure 10).
Figure 9 The Search Functionality Lets You Jump Right to a Specific Function Call
Figure 10 Search Results Are Displayed in a Search Results Bar at the Top of the Editor Window
Looking in the Locals window at this point, you can see that the cart is being adjusted so that the product’s new quantity in the cart is 1. This is the bug; I was expecting the adjusted quantity to be 2. Looking at the line of code, the new Quantity parameter should take into account not only “item.Quantity” but the “quantity” variable passed into the function call as well. The fix is to change the function call to:
AdjustQuantity(product, item.Quantity + quantity);
Eliminating the Dreaded ‘No Repro’ Scenario
All too often, testers and developers participate in the “no repro” dance in which the tester files a bug stating something is broken, only to have it resolved back with a comment “it didn’t repro on my machine.” Neither the developer nor the tester wants to participate in the dance, but they don’t have the right set of tools to help them communicate what happened at the point that the failure occurred. This is why we designed the system so that the same diagnostic information IntelliTrace provides to the developer during a debugging session can be collected during the execution of manual tests through the Microsoft Test Manager (MTM).
Let’s revisit the first scenario I debugged, where the “About us” page failed to render correctly. If a tester filed this bug, it would probably have a title like “Application error when viewing the about page,” and perhaps, if the developer was lucky, a screenshot of the error would be attached. If you received a bug like this today, how might you go about debugging it? Most likely, you would load the application’s solution from source control and reproduce the problem on your developer machine. In this case, you would be able to debug the issue and solve the problem, but think of how much time this would take. Or what if the problem was caused by a difference in configuration between your machine and the tester’s machine? Developers are much more productive when debugging issues rather than setting up repro environments.
With Visual Studio 2010, the MTM has given testers the ability to conveniently author, manage and execute both manual and automated tests. But that’s not all the tool does. MTM offers testers the ability to have diagnostic data adapters collect information in the background while a test is executing. For example, you can automatically collect a video recording of the test being executed so the developer can see exactly what the tester saw. Other collectors include the ability to collect system information and Event Logs from the box being tested on.
We’ve added an IntelliTrace diagnostic data adapter to automatically collect IntelliTrace files in the background. When the tester fails a test step and chooses to file a bug, the collected IntelliTrace file is automatically uploaded to TFS and linked to the bug. This gives the developer a much richer set of information to debug with than simply a set of repro steps. When the developer opens the IntelliTrace file linked to the bug, he’s given an experience similar to debugging a mini-dump, but over the entire timeline of the application, not just a point in time when the application crashed. IntelliTrace data can be collected for any managed application on local or remote test agents, including ASP.NET applications running under IIS.
When I open a TFS bug, the MTM has automatically added repro steps based on the manual test steps described by the tester. What’s even cooler is that if I look at the “All Links” tab of the bug (see Figure 11), I can see that an IntelliTrace file was also collected. By double-clicking on this file, I’m brought to a summary page view of the IntelliTrace file (see Figure 12).
Figure 11 Collected IntelliTrace Files Are Accessible Through the “All Links” Tab
Figure 12 The IntelliTrace Summary Provides an Overview of What Data Was Collected
The summary page gives me a lot of information about what the IntelliTrace file contains. At the top of the page, I’m given a timeline view of the threads in the application. If I expand the “Threads List” section of the summary page, I can see the same data in a tabular format. Double-clicking on a thread will start a debugging session from the IntelliTrace file and set my instruction pointer to the beginning of the thread.
I’m also given a list of all the exceptions collected in the IntelliTrace file. If I select an exception, a vertical orange line appears on the thread timeline showing where the exception occurs in time. Double-clicking an exception starts an IntelliTrace debugging session and the exception event will be selected in the IntelliTrace Events view. Further down on the summary page, I can see a list of all the test events matching up to the manual repro steps. The outcome of each step is also displayed. Clicking on one of these events also puts a vertical line on the thread timeline, and double-clicking an event starts an IntelliTrace debugging session selecting the closest event possible. The bottom of the summary page shows a list of system information collected about the computer upon which the tested application was running, and below that is a list of all the modules that were loaded into the process along with their file path.
You may be asking yourself, does this work on release builds? Of course! In addition, you don’t need access to symbols when collecting or viewing the IntelliTrace data. Symbols are necessary only to link the collected data to source files, so they’re helpful when you open the debug session.
Visual Studio 2010 and TFS have added support for symbol and source server, so if your application was built as part of the TFS build system, the right version of symbols and source code will automatically be downloaded from TFS as needed by IntelliTrace. You don’t have to even know the symbol server path.
Once you start a debugging session from the summary page, the debugger works just as it would for a live debugging session (see Figure 13). Most debugger windows are available to you, and you can navigate to any of the data IntelliTrace has collected.
Figure 13 When Debugging Starts from the Summary Page, Visual Studio Operates Just Like a Live Debugging Session
Wrapping Up
In this article, you’ve seen how IntelliTrace can greatly improve both your day-to-day development activities and your ability to quickly and easily diagnose problems without having to restart your application and debug with the traditional break-step-inspect technique. I’ve also shown you how an organization can reduce the number of “no repro” bugs by collecting IntelliTrace data during testing, enabling developers to debug issues offline without access to a live repro. This is just a brief introduction to the feature, and as you become more familiar with the power of IntelliTrace, it will start to change the way you debug.
Justin Marks started at Microsoft in 2002 after receiving his BS in Computer Science and Engineering from MIT. He has worked on MSN.com as a systems engineer, Windows as a software design engineer in Test, and now Visual Studio as a program manager. As a PM on the Diagnostics team, Marks has been working on the IntelliTrace feature for the next release of Visual Studio 2010.
Thanks to the following technical experts for reviewing this article: Bill Boris, David Gray, Habib Heydarian and John Robbins