Interesting IntelliTrace Anecdotes

Over the past few months I have had the opportunity to encounter some interesting anecdotes from customers that are using IntelliTrace as part of their development cycle with Visual Studio Ultimate. The ones that I want to highlight here have come to me as perceived flaws with IntelliTrace.  Now don't get me wrong I'm not saying that the feature is flaw free but there are some interesting side effects of using IntelliTrace as part of your development cycle.

IntelliTrace is broken, it's recording way too many ADO.NET calls!
This was an interesting complaint that I got a while back.  A developer was working on an application and looked at the recorded ADO.NET events that we had on the IntelliTrace list and noticed that there were four events listed for the exact same database call. This was not good! We took a look at the problem and it turned out that the path through the application was actually executing the same database call four times.  Naturally IntelliTrace recorded each call.  This was a great example of how IntelliTrace can be used in a static analysis manner on top of runtime data.  We were able to identify a great opportunity to optimize the code and reduce the extra database calls from the code path and make the application faster.

When I turn IntelliTrace on High (IntelliTrace Events and Call Information) it's too slow!
Well this can easily be very true and unfortunately it's one of those things that really depends on a few variables.  Let me explain.  When IntelliTrace is turned on high all of the modules (aka assemblies) are instrumented when you start debugging.  This means that we add extra code to record a certain degree of data for all of the parameters and return values for every single method call in all modules that are not in the inclusion/exclusion list.  Running against the RAWR application using the default IntelliTrace high settings can be a painful experience, however once you have clicked two buttons and patiently waited for the action to complete if you analyze the IntelliTrace data you might find that at least one method was call about 1,250,000 times!  This was occurred when simply clicking two buttons after starting the application!  Of course things are slow when we record data for 1.2 million method calls. This is another great indication that there are some optimization that can be made in the code. IntelliTrace runs slow when it's recording a lot of data.  Take this as a clue to analyze what's going on to seek out opportunities to improve your application.

One of the optimization that was taken early was to turn off certain IntelliTrace events by default.  We did this to improve performance.  During early testing we encountered an application that was running very slowly with IntelliTrace due to a huge number of registry access calls that it was performing. With the registry events turned on data was being collected for each access and it caused poor performance.  What it also did was highlight a tight loop within the code that was accessing the registry far more than was necessary. By moving the call to the same registry out of the loop improved both IntelliTrace performance as well as the application performance.

The default settings for IntelliTrace is to exclude certain modules when running on high mode.  A more optimized approach is to use an inclusion list rather than an exclusion list for the modules. By switching the Modules setting to "Collect data from only the following modules" and then providing strings to match only the modules that you care about will improve performance as well. Otherwise any modules that don't match the exclusion list will be included, this would include all third party modules that you may not care about.

When my boss saw the IntelliTrace log he made me change my code!
Using an IntelliTrace run as part of a code review is a great way to get some insight into what's going on from a high level. Reviewing exceptions that were caught within the user developed code showed a high number of catches that weren't being recorded or rethrown.  Essentially there were exceptions being caught and swallowed.  This is always a danger.  If an exception is thrown and caught but not logged there can easily be bugs in your code that can be very hard to track down.  Reviewing the exceptions data can help you develop more robust applications.

Conclusions
These are a few examples of anecdotes that I have encountered over the past few months that have shown some of the additional value that IntelliTrace adds to the development cycle in addition to the ability to historical debugging.  I hope you find these ideas valuable and can share a few of your own.

IntelliTrace In Production with VS11 CTP

Ok, so you've got your hands on the CTP of Visual Studio 11 that was released at the //build conference.  Cool.  Have fun with that, there's a ton to play around with!  More info here.

So where do you get the IntelliTrace cab file that was shown for the "IntelliTrace in Production" scenario?  Well, it's not exactly the most obvious but you can track it down in the following location once you've installed Visual Studio Ultimate CTP (note that this location is likely to change with upcoming releases).  C:\Program Files (x86)\Microsoft Visual Studio 11.0\Team Tools\TraceDebugger Tools

Once you have the IntelliTraceCollection.cab file you can take it to any other machine to leverage the IntelliTrace collection against IIS application pools without anything else!  No Visual Studio installation is required.

To extract the files in the cab be sure to use the expand command from the command line and don't just open the cab and extract the files.  The extract command from the command line maintains the file structure while using the extract command from Windows Explorer does not.  This is very important!

e.g. "expand /f:* IntelliTraceCollection.cab c:\IntelliTrace"  This will extract the files into a folder named IntelliTrace on the c: drive of the local computer.

Once you have the files extracted you are good to go with the PowerShell import and start collecting IntelliTrace against an application pool.

Note that you need to run your PowerShell as Administrator due to the stopping and starting of the application pool that is performed when the IntelliTrace profiler is started and stopped.  Once you have PowerShell running you add the IntelliTrace bits by running
Import-Module \Microsoft.VisualStudio.IntelliTrace.PowerShell.dll

Once that succeeds you can validate the import by executing "Get-Help IntelliTrace" in your PowerShell window to see the commands that are available.  Use Get-Help on any of the commands provided to get details on the usage.  Also watch Mark Groves and Tracey Trewin's Thursday afternoon session at //build to see advanced usage.

I would love to hear your responses and experiences with this feature.  More blog posts and official documentation will be forth coming.  Send me feedback at my Microsoft email address which is larrygug.

Examining IntelliTrace Events

This post dives into IntelliTrace Events as available in Visual Studio 2010 Ultimate edition, explaining what they are, how they work and the benefits to be had.

The typical “F5” usage pattern of IntelliTrace goes something like this:

-          Press F5 while in Visual Studio to initiate a debug run

-          Record an IntelliTrace session of your application during execution

-          Use the recorded information to enable replay of the execution

-          Analyze the data to determine what happened

Let’s take a look at some really useful analysis that can be done with IntelliTrace event information.

The examples in this post will assume the default settings for IntelliTrace that configure the feature to only record selected “IntelliTrace events”.

The events that are captured are found under the IntelliTrace Events section.

You can think of these events like log entries that are handled for you without adding anything to your code at design time. You can turn on or off event collection by category or by individual events within a category. The only event type that you do not have control over are Exceptions.  Regardless of any other events that may be selected IntelliTrace will always capture Exceptions thrown and caught when IntelliTrace is enabled.

What can be prove to be an interesting exercise is to take a look at the events list that IntelliTrace captures during a run of your application.  Do this by checking that IntelliTrace collection is enabled as shown in the first screenshot and then run your application in Visual Studio in debug mode. Walk through a usage scenario or two in your application.  Before exiting your application return to Visual Studio and select the “Break All” link in the IntelliTrace window.

If you don’t see the IntelliTrace window, open it by going to Debug -> IntelliTrace -> IntelliTrace Events from the Visual Studio menu or by pressing Ctrl+D, V.  What you see next depends on what events IntelliTrace collected during the execution of your application.  You may see anything from a very short list to a very long list.  The events are listed in the chronological order in which they occurred with the first event at the top and the last event at the bottom of the list.

Reviewing the events list can provide insightful information about the behavior of your application, the structure of the code, various IO performed and many other things.  Take a look at the following events list as taken from a quick usage of the StockTrader sample WCF application:

By reviewing this events list you can determine which database calls were made, what requests were made to the web server, what exceptions were thrown and caught and any breakpoints that were hit. Analyzing this information can be very beneficial as part of a code review as well as provide understanding of execution paths and opportunities for improvement in addition to finding and resolving bugs.

Click any of the events in the list to get further information.  For example, clicking on the first exception may do a couple of things. 

-          it expands the event to provide more information inline as shown below.

-          If you have the solution open in Visual Studio that contains the point where the exception was thrown it will take you to the code

-          Your application execution is “rewound” to the point where the exception was thrown for further analysis

 

At this point you can review the call stack by clicking the “Call Stack” link, which will open the call stack window.

Expanding one of the ADO.NET events in the list provides both the query that was executed as well as the connection string that was used.

This can be especially valuable when trying to track down connection permissions issues or query problems.  A huge benefit that many people have discovered is when you are using data access technologies like Entity Framework or Linq to SQL as this event will show you the SQL statement that was generated and executed based on your LINQ statements.  Very handy!

People are often surprised when they examine the ADO.NET statements in the list of events.  Frequently it is discovered that there are far more database calls being made than expected. The events list can also present duplicate calls that are executed. This can be a great opportunity to investigate caching strategies.

So how is this event collection done?

Each event in the events list is associated with some method in the .NET framework. When you execute your application within Visual Studio these methods have additional code injected that writes the data that you see in the events list to an IntelliTrace log.  The impact to execution is completely dependent on how often the methods that have the additional instrumentation are executed.  If you find that IntelliTrace is slowing down the execution of your application and you have only events collection enabled (see the first screenshot) take a look at the events list, you may discover that one or more events are being recorded many times.  This may indicate redundant execution within a loop perhaps.  For example if you have a loop that executes 1000 times and, unknowingly, each iteration performs a database query or a registry lookup you will find that IntelliTrace collection of that many events will impact performance. The benefit of all of this is that you will have discovered a great opportunity to refine your code and reduce potentially redundant code execution!

Hopefully you will see how IntelliTrace events alone can provide great value to your development cycle.  There is a lot of valuable information to be mined from them.  Take a look at the events that are available and turn on the ones that your code would encounter during execution.  Take some time to examine how your code works and maybe you will find opportunities for improvement as well as fix your bugs faster.

I am always eager to hear about your experiences using IntelliTrace!