Debugging a Web Site with IntelliTrace: Part II

Article
02/04/2013

This topic applies to Visual Studio 2010 Ultimate only.

In this scenario, you will learn how to use the advanced features of IntelliTrace to debug a Web site. You will turn on the IntelliTrace option to collect call information, and you will see how call information enables you to examine the execution history of your Web application.

Collecting call IntelliTrace can affect program performance. For this reason, the option is not enabled by default. For an example of how you can use IntelliTrace to debug a Web site with the default settings, see Debugging a Web Site with IntelliTrace: Part I.

Although the Web application shown in this scenario is written in C#, the code is fairly simple. Visual Basic programmers with a basic reading knowledge of C# should have no trouble following along. If you would rather see scenarios walkthroughs that use Visual Basic code, see Debugging a Card Game with IntelliTrace: Part I and Debugging a Card Game with IntelliTrace: Part II.

Prerequisites

You can read this topic and understand its lessons without installing the sample application. If you want to see the complete code and perform the steps in this scenario for yourself, you can download a complete VHD that contains the Tailspin sample application. The Tailspin sample was still being refined at the time this scenario was written, so there might be some minor differences between the sample that you downloaded and what appears in this topic.

Using IntelliTrace

Traditional debuggers show you the state of your application at the current moment. They provide limited information about events that occurred in the past. During debugging, you must infer events that have occurred in the past, based on the current state of your application, or restart your application and try to re-create those past events. If you view a call stack, for example, you see the call stack as it exists at the current moment. To see the call stack as it existed during a previous call, you have to set a breakpoint and restart the debugging session.

With IntelliTrace, you have access to call stacks and other information that was collected at many points in time. You can "time travel" between various events that happened in the past, which eliminates the need to restart your application and set a breakpoint for many debugging problems. At each point in time, examine the call stack, use the various debugger windows, and drill down into debugging data.

Collecting call information

By default, IntelliTrace collects information about your program when certain key events occur. These IntelliTrace events include exceptions, breakpoints, .NET Framework events, and other system events that are useful for debugging. Sometimes, a bug occurs within your own code and is not directly related to one of these events. In those cases, it is useful to see a history of procedure or function calls within your application, including the parameters, return values, and call sites. IntelliTrace can collect this call information, although it is not enabled by default.

To prepare for this debugging scenario, you have to adjust the IntelliTrace settings to collect both IntelliTrace events and call information.
1. On the Tools menu, click Options.
2. In the Options dialog box, open the IntelliTrace node, and then click General.
3. Click IntelliTrace events and call information.
1. Click OK.

Testing the Web site

In this scenario, you will debug a simple ecommerce site called Tailspin Toys. If you have downloaded the Tailspin VHD, you should now build the application and start to test the Web site. The goal is to verify that the cart is updated correctly when items are added to it.
1. In Visual Studio, open TailspinToys.sln.
2. On the Debug menu, click Start Debugging.
  
  The home page of the Tailspin Toys Web site appears.
3. On the home page, click the Paper Airplanes link.
4. On the next page, click the Contoso Cloud Explorer link.
5. On the Contoso Cloud Explorer page, click Add to Cart.
  
  In the Shopping Cart, notice that there is one item in the cart and the total is $50.00.
6. Click the Contoso Cloud Explorer link again.
7. Click Add to Cart again.
  
  There is still only one item in the cart, and the total is still $50.00.
  
  The cart was not updated when you added the second Contoso Cloud Explorer. This is the bug you will investigate in this scenario.

Breaking the application

Locate the IntelliTrace window. In the default configuration, you will find this window docked with Solution Explorer.
In the IntelliTrace window, click the Break All link.

Debugging the Web site with IntelliTrace

The IntelliTrace window provides two views of our application's runtime history: the IntelliTrace Events view and the Calls view. In the IntelliTrace window, click Show IntelliTrace Events.

The Tailspin Toys Web site uses a Model View Controller architecture. Therefore, there is no event handler for the Add to Cart button click. Instead, a POST message is sent to a controller. POST messages are collected as IntelliTrace events, so you can find the POST message in the IntelliTrace Events view. When you have found the POST message, you can navigate to the point in the debugging session when the Add Item logic was invoked.
In the IntelliTrace Events view, there is a Search box above the IntelliTrace events list. In the Search box, type Post, then press Enter.

The IntelliTrace Events view searches the list and displays only the events that match the string that you have entered.
Click the first POST event to see more information about the event:
Clear the Search box to display all events again:
Click the second POST event. This is the instance after which the incorrect value appeared. Therefore, this is the instance that you want to investigate.
Under the POST event, click the Calls View link.

The IntelliTrace window switches to the Calls view.

In the Calls View, a call stack appears at the top of the IntelliTrace window. This call stack is synced to a moment in time during the execution of your application. As you use IntelliTrace, the moment you are seeing can move forward or backward in time, under your control. When the timeframe changes, the Calls View changes, as does information in the other debugger windows.

The root call of your application is on the top of the stack. The current call is on the bottom. "Current" means current to the timeframe you are viewing, not current in real time. The orientation of the call stack in this window is opposite to the convention used in the Call Stack window, where the current frame is on the top.

Underneath the current call, you will see an indented list. Here, you can see IntelliTrace events that were collected for the current call, as well as calls that are made from the current call to other functions and methods.

In the Calls View, you can double-click any to view the point in time when that call was current. The Calls View and debugger windows update automatically.

You can single-click any call or event that is indented underneath the current call. Single-clicking a call does not cause IntelliTrace to step into the call, but it moves the execution pointer to the call site within the current call.
You will use the Calls View to view the Add Item code. Double-click Function Entry: Tailspin.Web.App.Controllers.CartController.AddItem:
Double-click Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product})

You are now inside the Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product})call:
Double-click Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product},int quantity =1)

You are now inside the Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product},int quantity =1)call:
Double-click Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product},int quantity =1,System.DateTimeAdded=3/10/2010 8:45:47 PM)

You are now inside the Tailspin.Model.ShoppingCart.AddItem(Tailspin.Model.Product product={Tailspin.Model.Product},int quantity =1,System.DateTimeAdded=3/10/2010 8:45:47 PM)call:

Each time you step into a new call, the Calls View updates. The debugging information that is shown in the debugger windows also updates.
Now, examine the Locals window:
In the Locals window, expand the AddItem function node:

You can see that quantity added is 1.
Next, examine the source code window:

The Navigation Gutter provides another way of navigating through the debugging session. This gutter, which is gray, appears only when you have IntelliTrace call information enabled. The Navigation Gutter contains icons that you can use to move forward or backward in time. Stepping in IntelliTrace is similar to stepping in the regular Visual Studio debugger, but there are important differences. In regular Visual Studio debugging, also known as live debugging, stepping occurs line by line. In IntelliTrace, stepping occurs from one IntelliTrace event or call to the next. In live debugging, stepping causes code to execute in real time. In IntelliTrace, you are viewing a recording of events that have happened in the past. That means you can move freely both forward and backward in time.

The next few steps show how you can use the Navigation Gutter to step through the runtime history of your application.
Click the Go to Next Call or IntelliTrace Event (F10) icon.
Click the Go to Next Call or IntelliTrace Event (F10) icon again.
Look at the Locals window again.
Expand the AdjustQuantity node:

Notice that newQuantity is still 1. This value should be 2, so the code that sets this value is the source of the bug.
To fix the bug, stop debugging and change this line of code:

AdjustQuantity(product, item.Quantity);

to this:

AdjustQuantity(product, item.Quantity + quantity);