Understanding IntelliTrace Part IV: IntelliTrace Calls

This is a multi-part series, you can find the other parts here:

Understanding IntelliTrace Part I: What the @#$% is IntelliTrace?

Understanding IntelliTrace Part II: Where Do I Use IntelliTrace?

Understanding IntelliTrace Part III: IntelliTrace Events

Understanding IntelliTrace Part IV: IntelliTrace Calls

 

 

IntelliTrace Calls

Continuing with our examination of how to use IntelliTrace this post will focus on another set of skills needed for troubleshooting when events aren’t enough. We use events for errors that are surfaced through the events we have specified. In the last post we looked at a classic 404 error and how to troubleshoot using IntelliTrace.

 

What if the error is more subtle or even intermittent? What if we need more information than events alone can give us? For more detailed information we turn to IntelliTrace Calls. Now is a good time to review the previous post if you haven’t read it yet or haven’t seen the information in a while. Whereas events are quick, low-overhead inflection points we can put into the code; calls incur a lot of overhead but you get a LOT of information.

 

Here is how the documentation describes IntelliTrace call information:

https://msdn.microsoft.com/en-us/library/vstudio/dd264915.aspx#WhatData

===

You can configure IntelliTrace to collect call information for functions. This information lets you see a history of the call stack and lets you step backward and forward through calls in the code. For each function call, IntelliTrace records this data:

• Function name

• Values of primitive data types passed as parameters at function entry points and returned at function exit points

• Values of automatic properties when they are read or changed

• Pointers to first-level child objects, but not their values other than if they were null or not

 

NOTE: IntelliTrace collects only the first 256 objects in arrays and the first 256 characters for strings.

===

 

 

Collecting Call Information

The best way to learn about calls is to go through a scenario. Let’s get started by setting up IntelliTrace to collect call information. We will be using the Brian Keller Virtual Machine with the Tailspin Toys codebase just like when we learned about events. Open the Tailspin Toys solution then go to Tools | Options | IntelliTrace | General and turn on IntelliTrace Events and Call Information:

 

Take note of the warning. You will not be able to use Edit and Continue while using Call Information so you will have to stop debugging to correct issues when you find them. It’s not a huge issue but something you need to be aware of as you use this feature so the team decided to call it out on this dialog.

 

 

Filtering Calls

One of the most confusing aspects of IntelliTrace is filtering the calls. Remember that we can use the IntelliTrace Events area to filter event information but there doesn’t seem to be an obvious place to filter call information. Where could it possibly be? In the IntelliTrace world we filter calls by filtering out the processes and modules that the calls come from/to. As we will see in a later post, there are places where we can’t assume the process and therefore have to specify a list of processes to capture. An example of this can be found in Microsoft Test Manager when we configure IntelliTrace:

 

Because we are in Visual Studio, however, there is no need for us to figure out the process since we assume the current process when we start a debugging session. The only thing we worry about is module filtering which can be found at Tools | Options | IntelliTrace | Modules:

 

Regardless of the type of call filtering you are doing there is one fundamental choice that needs to be made: deciding to include or exclude items. The default behavior, seen in the above process and module screenshots, is to use a blacklist of items to EXCLUDE from collection.  The danger of doing this is you will collect everything unless you specifically tell IntelliTrace not to collect. If you recall from my previous lesson on filtering events my personal feeling is that you should collect as much as you can and then filter AFTER the data is gathered. This will cause performance loss during collection but will give you the most information to work with.

 

The other option is to use a whitelist of items to INCLUDE during collection. The danger here is you might miss an important piece of information that was not included. From a performance perspective this is the best way to get a performance boost because IntelliTrace doesn’t have to collect as much information. As before there is no “right” answer to this situation--just personal preference.

 

 

Default Processes Filtered

Even though you can’t change it from Visual Studio, there actually IS a list of processes to be excluded.  In time I’ll show you how to modify the entries but, for now, here is the list of processes currently excluded when you use IntelliTrace from Visual Studio:

(NOTE: Feel free to Bing any of the processes you are not familiar with.)

devenv.exe mtm.exe TestAgentConfigUI.exe TestControllerConfigUI.exe DW20.exe TFSMgmt.exe TFSJobAgent.exe TFSBuildServiceHost.exe Microsoft.VisualStudio.PerfWatson.exe FxCopCmd.exe

MSBuild.exe sqlservr.exe IntelliTrace.exe MSVSMON.exe IntelliTraceSC.exe xdesproc.exe VWDExpress.exe VsWinExpress.exe Blend.exe

 

 

Default Modules Filtered

The modules filtered by default are essentially any assemblies we provide. You can quickly get an idea of which assemblies are excluded by going to the GAC (<windows install dir>\assembly) and comparing the list of exclusions to entries there. Here is the list of modules excluded by default in Visual Studio:

PublicKeyToken:B77A5C561934E089 PublicKeyToken:B03F5F7F11D50A3A PublicKeyToken:31BF3856AD364E35 PublicKeyToken:89845DCD8080CC91 PublicKeyToken:71E9BCE111E9429C Microsoft.*

 

 

Default Filtering Philosophy

The main goal of the default filters is to keep the noise from Microsoft products to a minimum. As you can see by the list of processes and modules the default filters center around specific processes and modules that we expect you are least likely to want in result sets. You can add or remove items from the list as needed to get the desired level of detail. For our scenario we will use the default call filtering settings.

 

 

 

Troubleshooting with Calls

Build and run the Tailspin Toys sample code. We are going to experience a problem that can’t be solved with events. First, let’s buy some airplanes! Okay, paper airplanes but still pretty cool stuff. Select Paper Airplanes:

 

There are lot of good choices here but, for now, view the Contoso Cloud Explorer:

 

Add one of these to your cart and notice the number of items in the cart goes up by one:

 

Select the Contoso Cloud Explorer link to view the details again:

 

Add another one to your cart and notice the number of items is still one:

 

Clearly we have a logic error in the code. Events won’t help us much here because there is no exception raised or other event that will lead us to the problem. Also, we know we are going to have to dig deeper into the code for answers. This scenario literally screams for you to collect call information. Switch back to Visual Studio and let’s examine the IntelliTrace data by breaking execution:

 

We know that the problem surfaced after the second time we tried to add an item to our cart so filtering on ASP.NET events seems like a good starting point:

(NOTE: Unfortunately event filtering in the IntelliTrace window is still a bit of a blunt instrument. You can filter on event categories but not on specific types of events.)

 

Once we have the filtered data we can scan for the interesting event or filter further by searching for keywords.  Since we know the issue is related to our shopping cart we should probably try searching for the word “cart”:

 

The resulting list is very easy to scan and we can find a starting point for our troubleshooting efforts. In this case, the second AddItem POST is the perfect anchor point for our searching:

 

The events only tell us that we sent some data to the server now we need to get into the code. Click the Calls View link:

 

Notice that our anchor point is highlighted and we are now in the Calls View window:

 

This window can be a little confusing at first so taking a closer look at this point is a good idea. First, the window is divided into two pieces. The top piece (above the double lines) is the current call in our history:

 

The second piece is indented below the double lines and represents calls from the current call and events associated with the current call:

 

As we look at our current location we know that the issue we are looking for happened after the POST. As we look down the timeline of calls there is definitely one that stands out--the AddItem call:

 

If you double-click this call it will become our current call and we can see more information:

 

At this point we are in our code so we can see our current location not only in the tool window but also in the code base:

 

Notice there is another call to AddItem below our function entry point. Click once on the entry and we can examine the code:

 

It looks like another call to AddItem and apparently we are building up information as we make these calls. Notice it is passing in product information for this particular call. If we double-click here then we get another set of calls with yet another AddItem:

 

Notice how we are building up our call stack above the double lines? As we keep drilling down we get clear line-of-sight to the call path we are going down. Drill down (double click) on the next AddItem call and pay attend to the code to the left as we keep searching for where the quantity is updated:

 

Drill down again. Notice we have run out of AddItem calls but we might have finally found our culprit with the AdjustQuantity call:

 

A look at the code shows that we are probably on the right track:

 

Let’s take a look at the Locals window to get more information about this call:

 

We can definitely see a potential problem with newQuantity. At this point we could continue to dig into AdjustQuantity but, for now, we will assume we know this is the area to be fixed. The problem is we are passing the quantity of the current item but we are not adding it to the existing quantity. It’s a simple fix, we just stop debugging and modify the code as follows:

 

Build and run the code. Make sure the fix worked by adding some planes to your cart. You should see the quantity going up as you add items to it:

 

 

Review

In this post the goal was to teach you about IntelliTrace calls and do an introduction to troubleshooting with the feature. The ability to browse a historical call stack and view the associated code raises problem resolution to a new level. There are a few limitations but, for the most part, you can debug historical code just like any normal debugging session. Later on we will explore more on how to do more advanced navigation in the editor and other advanced topics.

Comments

• Anonymous
  April 22, 2013
  This was an interesting series; thanks for writing it. Unfortunately, IntelliTrace will probably remain outside the toolbox of most developers. It's difficult to justify the huge difference in cost between Professional and Ultimate just for this one feature. Charging so much for the IDE may make some small amount of money in the short run, but in the long run the missing features in the lesser versions of Visual Studio just make the whole product seem less capable than it actually is. This makes the underlying platforms less appealing to developers than they otherwise might be. Compare this to Apple, where XCode is free.

• Anonymous
  May 27, 2013
  The comment has been removed