May 2015

Volume 30 Number 5

Visual Studio 2015 - Use IntelliTrace to Diagnose Issues Faster

By Angelos Petropoulos | May 2015

Think about your typical workflow when you’re debugging. Until you’ve successfully identified the root cause of an issue, you’re stuck in a loop of setting breakpoints and repeating testing steps that reproduce the issue. You can now use IntelliTrace to record historical debugging information as the application is running. This helps you break this loop. You can execute the testing steps once to reproduce the issue, then use historical debugging to identify the root cause.

IntelliTrace is the set of historical debugging technologies that extends the debugger in Visual Studio 2015 Enterprise. There’s also a standalone component you can use outside of Visual Studio. IntelliTrace records your application execution looking for interesting events. When an interesting event occurs, IntelliTrace automatically records the call stack and local variables while the application continues to run. You can control the events IntelliTrace considers “interesting” through Tools | Options | IntelliTrace | IntelliTrace Events.

IntelliTrace presents you with a history of your app’s execution using a timeline (a high-level view of events) and a table that displays the details of each event. It also gives you access to historical debugging data by extending and integrating with the Visual Studio debugger. This lets you go back in time and see the call stack and local variables of collected events.

IntelliTrace has found a new home in the Diagnostic Tools window in Visual Studio 2015. The Diagnostic Tools window contains the CPU Usage tool and Memory Usage tool, along with IntelliTrace. If your project type and debugging configuration is supported (for up-to-date information, check aka.ms/diagtoolswindow), you’ll see a Diagnostic Tools window appear when you start debugging in Visual Studio 2015 (you can press F5 or you can always open it manually using Debug | Show Diagnostic Tools). When you activate Historical Debugging, you’ll see something similar to Figure 1.

Figure 1 Historical Debugging with IntelliTrace

Explore the UI

Following is a list of each component of the IntelliTrace UI and its intended purpose and functionality:

Debugger Events: The Debugger Events details table (see Figure 2) is a tabular view of the events IntelliTrace has collected. The columns from left to right are:

1. A pointer to the event for which the debugger is currently showing information; only one row will have the yellow arrow indicating the location of the current instruction pointer and one row might have a pink arrow indicating which historical event you’ve activated.
2. The icon used to represent this event on the Debugger Events timeline.
3. A brief description of the event.
4. The number of seconds from the start of the debugging session to the time the event was collected.
5. The duration of the event. (Note: Not all events have a duration.)
6. The thread ID and name that generated the event. (Note: Not all events are associated with a thread)

Figure 2 Debugger Events Table

If you click on an event in the list to expand it, you can then select Activate Historical Debugging and set the debugger to the point where IntelliTrace recorded the selected event.

Category Filter Control: This filtering control lets you hide or show event categories while they’re still being collected. If you want to focus on a particular category or you’re completely uninterested in another, you can use this to quickly bring them in and out of view. The current list of categories includes: ADO.NET, ASP.NET, Console, Data Binding, Debugger, Environment Variables, Exception, File, Gesture, Lazy Initialization, Output, Registry, Service Model, Threading, Tracing, User Prompt and XAML.

Thread Filter Control: This filtering control lets you hide or show events by the thread from which they were generated, in case you’re only interested in diagnosing a specific thread or you’re positive executing a specific thread has no issues.

Show Events from External Code Button: IntelliTrace respects the debugger’s Just My Code setting. This means that by default it hides events that originate from non-user code to reduce noise. Clicking on this will bypass the debugger’s setting and show events from external code. Most of the time, this will lead to verbose output.

Debugger Events Timeline: This is a graphical view of the events IntelliTrace has collected over time. This is a different view of the same information shown in the Events details table. Use the timeline to get a high-level view, and identify and select areas you want to drill into with the Events details table view. You can filter what you see in the Events details table view by selecting a specific time range.

The Ruler: Above the timeline, there’s a ruler that shows you the point in time at which each event occurred. It also lets you select a specific time range by clicking and dragging. Select a time range to filter the Debugger Events details table.

Break Events Track: Every time a break-related event occurs, it appears on this timeline track. Break events are hitting breakpoints, completed steps, clicking Break All, invoking Debugger.Break or an unhandled exception breaking execution. Think of this as the master timeline track to help you orient where events in the other tracks occurred in the program’s execution (because using breakpoints and steps is how you control your application’s execution). Clicking on an event in this track applies a time filter that will filter events in the Debugger Events details table. This way you can easily filter only those events that happened when you stepped over a line of code or between you pressing F5 and hitting a breakpoint.

Output Events Track: This track shows events for messages appearing in the Output window. The event categories that appear on this track are: Thrown Exceptions, Program Output (or Console.WriteLine), Module Loaded/Unloaded, Thread Exit and Process Exit. This lets you correlate standard debug output messages with the rest of the debugger’s historical information.

IntelliTrace Event Track: Every other event category collected by IntelliTrace appears on this timeline track: ADO.NET, ASP.NET, Console, Data Binding, Environment Variables, File, Gesture, Lazy Initialization, Registry, Service Model, Threading, Tracing, User Prompt and XML.

Diagnostic Tools Toolbar: The toolbar gives you Zoom In and Zoom Out buttons, as well as a Reset View button to reset the timeline back to the default zoom level and clears any existing time selection. This filters all collected data into view. The Select Tools dropdown lets you select the tools you would like included in the Diagnostic Tools window, besides IntelliTrace.

You can run multiple diagnostic tools at the same time. The Diagnostic Tools window can host the Memory Usage, CPU Usage tools and IntelliTrace all at the same time. This gives you a holistic view into your application’s behavior. For example, Figure 3 shows how the series of Module Load events increases the memory and CPU usage for an ASP.NET application as it starts up.

Figure 3 The Diagnostic Tools Window Shows How Your App Is Behaving and Performing

Fix a Real Bug with IntelliTrace

Now I’ll walk you through fixing a real bug using Live Debugging features of IntelliTrace in Visual Studio 2015 Enterprise. The application I’ll debug is a Windows Forms application from CodeProject called SocialClub.

The app maintains a database of members for a social club. The bug is that search behaves erratically after registering a member. To reproduce the bug, I start the application and register a new member. Then I perform a Get All search that’s supposed to return all registered members. I expect only one result, but instead I get two (see Figure 4). The second search result is unexpected, so that’s what I need to fix.

Figure 4 Get All Search Result Contains an Unexpected Record

To fix this bug, what should I do next? At this point, my hypothesis is that there’s either something wrong with the Get All search function or there’s something wrong with the new member registration process. The application has another search mode that takes specific search criteria, so I’ll use it to search for the unexpected record returned by Get All (the one with the missing data and Unknown values).

Here are the possible scenarios: If I get no results, it probably means the unexpected record doesn’t exist in the database and the issue is with the Get All search function. If I do get a result matching a record with Unknown for Occupation and MaritalStatus, the issue is probably with the registration function entering more records in the database than it should.

So now I perform a search with Unknown for Occupation and Unknown for MaritalStatus, which returns exactly one result: the record I successfully registered as Engineer and Married. That’s weird and, unfortunately, it didn’t get me any closer to the root cause of the bug. Instead of spending time setting breakpoints, registering new members and searching for them over and over, I’ll see how IntelliTrace can help expedite the investigation.

I want to see the events IntelliTrace has collected, but IntelliTrace events aren’t updated until the Debugger breaks the application’s execution (meaning it hits a breakpoint). Because I don’t have a specific breakpoint in which I’m interested, I simply click Break All on the Visual Studio toolbar. The app is now in a break state with all threads suspended. IntelliTrace is displaying the data it collected in both the timeline and tabular details view of the Diagnostic Tools window.

At this point, I’ve interacted with the application quite a bit since I started debugging. I’ve logged in, registered a new member, searched using Get All, and searched with specific search criteria. However, I’m only interested in events that occurred as a direct result of clicking Register. To filter my view to just these events, I hover over the events in the timeline until I find where I clicked Register. Then I drag and select a cluster of events. When I look at my tabular detailed view, after having selected time, I can see the two most recent events listed (other than hitting Break All) are two INSERT statements (see Figure 5).

Figure 5 The Tabular Details View Is Filtered to Show Events from the Selected Time Range

Clicking an event in the list expands it to multiple lines to show the entire executed SQL statement. I can see I have two INSERT statements happening. The second one is inserting a bad record with NULL values. Here are the two SQL statements:

Execute Reader "insert [dbo].[ClubMembers]([Name], [DateOfBirth],
  [Occupation], [Salary], [MaritalStatus], [HealthStatus], [NumberOfChildren],
  [ExpirationDate])values (@0, @1, @2, @3, @4, @5, @6, @7)
  select [Id] from [dbo].[ClubMembers] where @@ROWCOUNT > 0 and [Id] =
  scope_identity()"
Execute Reader "insert [dbo].[ClubMembers]([Name], [DateOfBirth],
  [Occupation], [Salary], [MaritalStatus], [HealthStatus], [NumberOfChildren],
  [ExpirationDate])values (null, @0, @1, null, @2, @3, null, @4) select [Id] from
  [dbo].[ClubMembers] where @@ROWCOUNT > 0 and [Id] = scope_identity()"

You can ignore the SELECT statement that follows the INSERT. That’s Entity Framework retrieving the ID of the record it just inserted. The next question is: Why do I get two SQL statements executed for a single click of the Register button? IntelliTrace helps me quickly answer that question by letting me activate Historical Debugging for each of the events (see Figure 6) and checking their respective historical call stacks in the Call Stack window.

Figure 6 Activate Historical Debugging for the First of Two INSERT Statements

The first INSERT’s historical call stack is:

John.SocialClub.Data.dll!John.SocialClub.Data.Service.ClubMemberService.Create(...)
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Forms.Membership.Manage.RegisterMember()
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Forms.Membership.Manage.Register_Click(...)
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Program.Main()

The historical call stack of the second INSERT with the bad record is:

John.SocialClub.Data.dll!John.SocialClub.Data.Service.ClubMemberService.Create(...)
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Forms.Membership.Manage.RegisterMember()
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Forms.Membership.Manage.btnRegister_MouseClick(...)
John.SocialClub.Desktop.exe!John.SocialClub.Desktop.Program.Main()

Clicking on each frame takes me to the corresponding line of code. After examining the two historical call stacks, I’ve determined I have two different event handlers subscribed to the same button click: Register_Click(…) and btnRegister_MouseClick(…). Reading the code in those two functions, I quickly deduce that because the form’s fields are reset after each new member registration, the first event handler inserts the records to the database correctly. However, the second event handler inserts a record with blank and NULL fields. So I quickly found the bug by using Break All, and then used IntelliTrace to identify and navigate to the offending piece of code.

What If IntelliTrace Events Are Not Enough to Find the Bug?

At this point, as excited as you are about IntelliTrace improving the way you debug, you might be wondering what to do if IntelliTrace doesn’t record any interesting events that can lead you to a bug’s root cause. Are you out of luck? No, you’re not. Don’t forget you can control what IntelliTrace events are enabled using Tools | Options | IntelliTrace | IntelliTrace Events. Not all of them are enabled by default, but even enabling all of them might not always be enough for some pesky bugs.

For those tricky issues, you can configure IntelliTrace to record not just events, but also every method call and its parameters. Simply go to Tools | Options | IntelliTrace and select IntelliTrace events and call information. This is a powerful debugging feature, but it comes at a runtime cost. With this setting, IntelliTrace will intercept every method call and record it, which affects the app’s performance. That’s why it doesn’t collect method calls by default. You have to opt in through IntelliTrace settings.

You can view and navigate this new information in two different ways. You can use the sub-tab Calls in the Debugger Events details table, which lists all recorded calls (for more information on the Calls view, go to aka.ms/itracecalls). Another way is to activate Historical Debugging for an event and use the IntelliTrace control within the text editor to navigate back and forth in the application’s execution. The controls appear between your code and the instruction pointer. So IntelliTrace has you covered for all your live debugging scenarios.

What If You Can’t Reproduce the Bug on a Dev Machine?

This is where Non-Live Debugging with IntelliTrace comes in. So far, I’ve assumed you know the steps necessary to reproduce the issue you’re debugging. That’s not always the case. Some of the most difficult and time-consuming bugs are those for which you might not have exact steps to reproduce. IntelliTrace can eliminate this dreaded “no repro” scenario by letting you record the application’s execution on a production or test environment. Then you can debug it on your development machine, by exploring the collected information using the same Diagnostic Tools window I’ve been using here.

IntelliTrace offers a standalone collector you can deploy to other environments to which Visual Studio can’t connect. You shouldn’t encounter any resistance from your admins because there’s no installation involved. It’s simply a matter of copying the collector to the target environment. The collector records the application’s execution to an .itrace file that you can transfer to your development machine and open with Visual Studio. This scenario is referred to as Non-Live Debugging because you can’t control app execution while debugging. For up-to-date information on how to use the IntelliTrace standalone collector, please visit aka.ms/itracecollector.

Wrapping Up

The new IntelliTrace experience and integration with the Diagnostic Tools window have some exciting possibilities. You can keep up-to-date with the latest information on these and other diagnostic-related features by going to aka.ms/DiagnosticsBlog.

Angelos Petropoulos is a senior program manager on the Visual Studio team. After getting his master’s in object-oriented software engineering, he worked as an IT consultant in the United Kingdom. After moving to the United States, he joined the Diagnostic Tools team in Visual Studio and he’s now the program manager for IntelliTrace.

Thanks to the following Microsoft technical experts for reviewing this article: Andrew Hall, Daniel Moth, Dan Taylor, Charles Willis