Tuesday, February 9, 2016

How to Profile an IIS Web Application Using Jetbrains dotTrace

What is dotTrace and what it does ?

  • JetBrains  dotTrace is a proprietary profiler for hunting down performance bottlenecks in .NET and Silverlight 4 applications.

  • The latest release, dotTrace 6.1 Performance, helps .NET developers quickly find performance bottlenecks and optimize their applications.

  • Profiling with dotTrace Performance lets you:
    1. Locate slowest-running parts in your code.
    2. Identify performance bottlenecks down to any particular     function.
    3. Focus on a function to see what makes it consume CPU time.
    4. Untangle complex recursive calls.
    5. Compare function timings before and after optimization.

  • The process of identifying bottlenecks in your application consists of two steps:
        1. Profiling the application       
        2. Analyzing the profiling results

  • During profiling dotTrace measures the execution time of particular operations in the profiled application and saves this information in a snapshot.

  • The more accurate profiling settings are, the easier it is for you to find bottlenecks. Thus it is very important to choose the right profiling mode, profiling target and time measurement method.

How to Launch dotTrace ?

  • Launch JetBrains dotTrace from the Start Menu as “Run as Administrator”. Please note that the dotTrace has to be installed in the WebServer (IIS) where the application under test is hosted;
0_LaunchDotTrace.jpg

  • However you can have the dotTrace installed in your PC and then do a remote profiling where it is not the case for this instance.
  • Configuring and connecting to the license server was considered as out of the scope for this article and you can refer the following link for the detailed explanation on how to connect with the Jetbrains license server;

The following landing screen will be seen upon launching the dotTrace;1_LoadDotTrace.jpg

  • Click on the “Profile” button and you will be listed the applications which you can profile on;
2.2_SelectIIS.jpg

Out of the available options select “IIS Application” as you are going to profile on a web application hosted in Microsoft IIS web server;
2_SelectIISApplication.jpg
Once you are selected the IIS Application you will be asked to select the profiling configurations where there are a set of profiling types and measures you need pick.

Once you are selected the IIS Application you will be asked to select the profiling configurations where there are a set of profiling types and measures you need pick.

3_ProfileConfiguration.jpg
Profiling Methods Available in dotTrace

  • An application can be profiled in several ways. In dotTrace you can choose between:
1. Sampling profiling.2. Tracing profiling.3. Line-by-line profiling.
  • Sampling is the fastest and the least precise mode. This is a way of profiling when dotTrace basically grabs current call stacks on all threads once in a while. The output snapshot reflects statistics for the observed call stacks. In this mode the number of calls isn't available and times are approximate. Accuracy cannot be more than the sampling frequency which is several hundred hertz.
  • Tracing is slower, but more precise than Sampling. This is a way of profiling when profiler gets notifications from CLR when a method is entered and left. The time between these two notifications is taken as the execution time of the method. In this mode you can learn precise timing information and the number of calls on the method level.

  • Line-by-line is the slowest and the most precise mode. This is a way of profiling when dotTrace collects timing information for every statement in methods. This way of profiling lets you collect the most detailed information on methods that perform significant work. You can specify exactly which methods you want to profile or profile all methods for which dotTrace Performance is able to locate symbol information.

  • dotTrace Performance provides you with three ways to measure execution time:
          1. Wall time (CPU instruction).    2. Wall time (performance counter).    3. Thread time.
  • Wall time (CPU instruction), also called real-world time or wall-clock time, is time elapsed between method entry and method exit. Wall time method makes no difference between the cases when a method consumes CPU and does some meaningful work and when a method is in a sleep, wait or join, as they both are taken into account when measuring time. When this time measurement method is selected, dotTrace Performance reads values of TSC processor register on method entry and on method exit and then measures the difference.

  • Wall time (performance counter) is similar to Wall time (CPU instruction) except that it uses a slightly different way of measuring time intervals. The operating system, network, and devices provide counter data that an application can consume to provide information on how an application is performing. When this time measurement method is selected, dotTrace Performance uses Performance Counter API to retrieve and use that data for measuring time.

  • Thread time is the time measured by a thread-specific timer which is paused when its thread is paused (waiting for a semaphore, sleeping, etc). This kind of measurement is supported only for sampling profiling and has lower resolution than other methods (about 10ms).

  • Consider the following example. Function A executes for 10 seconds. For 8 seconds out of those 10 it is waiting for some data from the network and for the remaining 2 seconds it is actively processing the data (without sleeping or waiting anymore). Wall time for this function is 10 seconds; Thread time for this function is 2 seconds.

Based on the requirements of our profiling, lets go ahead with the following profiling options;
  1. Line by Line as the profiling type
  2. Wall Time (CPU Instructions) as the measure
  3. Non “Run Browser” mode as I will open the preferred browser later
  4. Non “Start Profiling Immediately” mode as I do not need to start the profiling from the very first user transaction.

4_SelectLineByLine.jpg
Once you start to Run the dotTrace profiling with the aforementioned configurations you will able to see the following dialog box;
5_StartUpProcessWindow.jpg
Since you have not started to run your browser you will not have any IIS Worker Process (w3wp) IDs listed in the “Process” drop down list.

  • Now go ahead and launch your web application through the web browser and then immediately you will see the corresponding IIS Worker Processes (w3wp) are getting listed;


If you have an application where you have multiple sites hosted in different IIS pools you need to first identify which site/subsystem you need to profile. For that go to the command prompt and go to  “C:\Windows\System32\inetsrv\” path and run the “appcmd list wps” command where it list down the running Process IDs.



  • Note that so far you have not started the profiling and have browsed the workflow up until the place where you want to start the profiling. Now it’s time to start profiling, so click on “Start Profiling” button after selecting the correct w3wp Process ID from the process drop down.  In my case the transaction which I need to profile is a thread post and the w3wp Process ID which the targeted code lies is 13324 as highlighted in the above screenshot.

  • Now go ahead and perform the transaction on the browser which you need to profile

8_SaveThread.jpg

Once you are done with the profiling click “Get Snapshot” for the same w3wp ID;

9_GetSnapshot_beforeClick.jpg
What is a Snapshot in dotTrace ?

  • After a profiling session completes, the performance data collected during the profiling process is saved in a snapshot file. Each snaphot file (*.dtp file) contains the call tree structure of the profiled application and various metrics, such as:
  1. The number of calls for each function.
   2. Time spent executing a function.
   3. Time spent executing a function and all its child functions.
   4. Information about function recursiveness.

Given below is the Overview section of the Snapshot which was generated for my profiling;

10_Snapshot_Overview.jpg

Ways of Presenting Snapshot Data;

  1. Threads Tree View

  • The Threads Tree view lists all threads in your application. They are sorted by their execution time. Each thread is identified by a name or ID. The main thread is marked with the icon, other threads are worker threads are not assigned an icon.
    1. View what kind of threads are being spawned by your application.   
    2. Monitor all threads and their activities.   
    3. Analyze each thread's activity.   
    4. Find and examine critical execution paths.   

  • Each node in the Thread Tree view contains the following information:
   1. The percentage of time spent in this call related to time spent executing the thread.
   2. Short name of the function being called.
   3. Total time spent in this call stack.
   4. Number of calls made in this call stack.
   5. Full name of the called function.

Given below is the Threads Tree View for my Snapshot of the profiling which I did;

10_Snapshot_ThreadsTree.jpg
You can search for the method which you need to measure and then you can get the following information as mentioned earlier;
  1. The percentage of time spent in this call related to time spent executing the thread.
   2. Short name of the function being called.
   3. Total time spent in this call stack.
   4. Number of calls made in this call stack.
   5. Full name of the called function.

2.  Call Tree View

  • The Call Tree view is a representation of all function calls in all threads. Each top-level node represents a top-level function which was executed by a certain thread. Each node corresponds to a function call and contains metrics gathered during profiling.

  • This view lets you;
   1. Quickly get down to actual application activity.  
   2. Look through the execution path of the process or a function. 
  • Each node of the Call Tree view contains the following information and you can find the same as shown in the following screenshot:
   1. The percentage of time spent in this call relative to time spent in all calls in the current tab.
   2. Short name of the called function.
   3. Total time spent in this call stack.
   4. Number of calls made in this call stack.
               5. Full name of the called function.
11_MethodsInCallTree.jpg

  • Provided the correct .pdb and .cs files, you can view the complete implementation of the corresponding method.

  • The Plain List view shows all functions reachable in the current tab and you can look through the list of all functions called in your application during the profiling process.

  • You also can sort functions by Function Name, Time, Ave Time, Own Time and Calls. To do that, click the corresponding column name. By default, functions are sorted by time.

    3. HotSpot View
  • The Hot Spots view lists 100 most time-consuming functions of the profiled application code.

14_HotSpot.jpg
4. Plain List View

12_Method_In_PlainList.jpg

  • 'Own Time' is the time spent by all functions in a particular namespace performing some work (doing some math or calculations) instead of calling other functions. The percentage near own time in that column shows how much time this function spent performing some work compared to whole time spent by this function (that is (Own Time/Time)*100 %).