What Is Timeline Profiling?
Since version 6.0, dotTrace offers a new method of profiling your apps called timeline profiling. What is timeline profiling and why do you need it?
Unlike 'classic' performance profiling in dotTrace 5.5 and earlier, during timeline profiling dotTrace collects temporal call stack and thread state data. You get the same data about call times, but bound to a timeline. This way, you can analyze not only typical “what is the slowest method?” issues, but also ones where the order of events does matter, such as UI freezes, excessive garbage collections, uneven workload distribution, insufficient file I/O, and so on.
To start timeline profiling, simply choose the Timeline profiling type when configuring a session. To analyze collected timeline profiling snapshots, use a separate dotTrace component called Timeline Viewer.
In this Getting Started tutorial, we will take a detailed look at the key profiling steps and introduce you to the Timeline Viewer user interface. We will also profile a sample app and try to determine why its UI freezes, which is a very common profiling task.
Our sample app is used to reverse lines in text files, e.g., "ABC" > "CBA". With the Select Files button, a user chooses one or more text files to be processed. The Process Files button runs a separate BackgroundWorker thread which reverses lines in the files. Progress is displayed in the left-hand corner of the window. After processing is finished, the label says All files were successfully processed.
The source code for this app is available here.
The app has a serious drawback. After starting file processing, users experience long UI lags that last until processing is over.
Let’s use timeline profiling to find out why these freezes happen!*
Running the Profiler and Getting a Snapshot
- Open the MassFileProcessing.sln solution in Visual Studio.
- If you have dotTrace integrated with Visual Studio, run the profiler by choosing ReSharper | Profile | Run Startup Configuration Performance Profiling.
Otherwise, run dotTrace from the Windows Start menu. In dotTrace, select New Session | Local, Profile Application | Standalone.
- In Profiling type, select Timeline. In case you ran dotTrace as a standalone app, you should also specify the path to the release executable of our sample app in Application.
- After you click Run, dotTrace runs our app and displays a special controller window used to control the profiling process.
Now, let's try to reproduce a performance issue in our app.
- Click Select Files and choose five text files that come with the app in the Text Files folder.
- Click Process Files to start file processing.
As you can see, the app lags very badly. Actually, you are even unable to see the progress of file processing until it is finished and the All files were processed successfully message is shown.
- Collect a timeline profiling snapshot by clicking Get Snapshot’n’Wait in the controller window. The snapshot will be opened in Timeline Viewer.
- Close the app. This will also close the controller window.
First Look at Timeline User Interface
Let’s make a little digression and take a look at the Timeline UI.
The analysis workflow in Timeline Viewer is quite simple: all you do is slice and dice the collected temporal data using filters.
So, where are the filters? While most windows in Timeline Viewer display data, they are also used to set specific filters.* The result of every filter’s work is a set of time intervals or point events selected by a specific condition. For example, clicking Interval Filters | File I/O in the Filters window will Select all time intervals where threads performed file I/O operations. Clicking on the Main thread in the Threads diagram will Select lifetime of the Main thread.
Of course, filters can be chained together. If you activate the two filters mentioned above, you will get the resulting filter, Select all time intervals where the Main thread performed file I/O operations. By carefully combining filters, you can investigate almost every aspect of your application.
This is all we need to know before starting to working with Timeline Viewer. Time to try it in action!
Analyzing a Snapshot in Timeline
Look at the Threads diagram. By default, it contains all application threads excluding unmanaged threads.* Note that all filter values you see are calculated for all threads currently visible.
For further analysis, we are not interested in threads that perform no work. So, first let’s get rid of them.
- Look at the list of threads on the diagram. It consists of the Main app thread, the Finalizer thread (used to finalize objects but does no work in our app), and Garbage Collection thread (used to perform background GC). The Background thread that processes files in our app was identified as Thread Pool (ID 10104) because background threads are created by the CLR Thread Pool. There's also one more Thread Pool (ID 2900) that does no work. This is probably some auxiliary CLR thread pool.
Let's hide the Finalizer and Thread Pool (ID 2900) threads as irrelevant to our analysis.
- Select the Finalizer and Thread Pool (ID 2900) threads in the Threads diagram.
- Right-click and select Hide Selected Threads.
- Look at the Threads diagram and the status bar. The following filter is currently applied to the snapshot data: Select lifetime intervals of all threads excepting hidden.
Note how the data in other filters were affected. For example, state times in Thread States are now calculated for all threads except the hidden ones. Top Methods and Call Tree have changed too, showing calls only from the filtered threads.
- The current scale of the Threads diagram doesn't allow us to see the 10104 Thread Pool (our BackgroundWorker thread) in details. Let’s zoom in so that it fits the entire diagram.
To do this, use Ctrl+Mouse Wheel on the Threads Diagram.
This automatically adds the filter Visible time range: 1586 ms. Note how this filter affects others: all values are recalculated for the visible time range.
The following filter is now applied to the snapshot data: Select all time intervals within the visible time range for all threads excepting hidden.
- Take a look at the Threads diagram.
What you see is how thread states changed over time. For example, our BackgroundWorker thread 10104 Thread Pool was started approximately at 16.3 s (after we clicked the Process Files button). Most of the time the thread was Running (rich blue intervals). Besides, there are intervals where the thread was in the Waiting state (pale blue intervals).
Look at the Process Overview diagram.* In addition to CPU Utilization, it shows two event diagrams relevant for our performance analysis. The UI Freeze bar shows that the freeze started right after 10104 Thread Pool was created. Blocking Garbage Collection was also intensively performed on this time interval. As blocking GC suspends all managed threads, it may be the potential cause of the UI freeze.
We must take a closer look at these events.
- First, let’s remove the Visible time range filter as we no longer need it. To do this, click on the filter in the list of applied filters. The diagram will zoom back out.
- Now, let’s investigate the UI freeze event more thoroughly.
What are the main potential causes of such freezes? These are:
- long or frequent blocking GCs;
- blocking of the UI thread by some other thread (for example, due to lock contention); and/or
- excessive computational work on the UI thread.
We will proceed to exclude these causes one by one until only the true culprit remains.
- Select the UI freeze event by clicking on the corresponding bar in the Process Overview section. This will apply the filter by the UI freeze event. Note that this applies not only the filter by the freeze time range, but also the filter by the Main thread. The latter is done automatically, as the Main thread is the only one that processes the UI in our app.
Thus, the resulting filter now is Select all time intervals on the Main thread where the UI freeze event took place.
- Now, to identify the true cause of this freeze, let’s investigate values in the Filters window.
The first potential cause we should analyze is excessive blocking GCs. Take a look at the Blocking GC filter. Taking into account the currently applied filters, it shows how long the Main thread was (Blocking GC value) and was not (Exclude Blocking GC value) blocked by GC during the freeze.
The Blocking GC time is quite high (483 ms, or 11.8% of the selected interval) and probably may have some impact on performance. Nevertheless, it could hardly be the cause of the 4-second freeze. Thus, we may exclude excessive GC from our list of suspects.
- Click the Exclude Blocking GC value. The resulting filter now is Select all time intervals on the Main thread where the UI freeze event took place and no blocking GC is performed.
- Let's investigate the potential causes “Blocking by some other thread” and “Excessive work on the Main thread.”
Look at Thread State. This filter shows total time spent by threads in a certain state. Taking into account the currently applied filters, it shows states of the Main thread during the freeze.
It appears that most of the freeze time (92.1%, or 3335 ms), the thread was doing some work as it was Running. The 242 ms value of the Waiting state is too small, which automatically excludes “Blocking by some other thread” as a cause. Therefore, the cause of the freeze can only be computational work on the Main thread!
All we need to do now is find methods that were executed on the Main thread during the freeze. We can use the Top Methods and Call Tree filters for this.
- Select Running in the Thread States filter. This will make the resulting filter Select all time intervals where the Main thread was running when the UI freeze took place and no blocking GC was performed.
The list of filters will look as follows:
Now, the filters Top Methods and Call Tree contain only methods executed during these time intervals.
- Look at the Top Methods filter. It shows the plain list of methods from the stack sorted by their execution time.
In the current state, the list doesn't make a lot of sense as it is filled mostly with low-level system methods. Let's make the list more meaningful.
- Select the Hide system methods check-box. In this mode, Top Methods shows only user methods. The execution time of a user method is calculated as the sum of the method's own time and own time of all system methods it calls (down to the next user method in the stack).
We see there are only two methods left: App.Main and ProcessInProgress.
Look at the Call Tree.
As you can see, App.Main spends most of the time in a number of system methods related to processing Windows messages.* This is typical behavior for any app with a graphical UI. This indicates that the app waits for user input in a message loop. We can simply ignore these methods when analyzing the snapshot. To find out what method causes the freeze, we should look at the next user method in the stack, which turns out to be ProcessInProgress (955 ms, or 28.6%).
Since we assumed that lags took place due to some computational work in this method, let’s check its source code.
- In Call Tree, click on the ProcessInProgress method.
Look at Source View window.*
It appears that this method is just an event handler that updates the progress of file processing operation in the progress label on the main window. These computations don't look complex, so why did the freezes occur? Apparently, this event handler is called so often that the main window cannot cope with updating the label. Let’s check this out in our code.
Switch to Visual Studio and look at the code.
Further code investigation* shows that this event handler is subscribed to the ProgressChanged event of the background worker. This event occurs when the worker calls the ReportProgress method. In turn, it is called from the ProcessFiles method of the background worker.
Here is the cause of our performance issues: ReportProgress is called each time after 5 lines in a text file are processed. As lines are processed very quickly, ReportProgress is called too frequently for the system. Let’s reduce this frequency, for instance, to one call per 1000 lines. Improve the if condition in the code.
- Rebuild the solution and perform profiling one more time as described in Running the Profiler and Getting a Snapshot.
- There it is! No more lags. Timeline also doesn’t detect any UI freezes during file processing.
What we learned in this Getting Started tutorial:
- Unlike “classic” performance profiling, during timeline profiling dotTrace collects temporal call stack and thread state data.
- To analyze the results of timeline profiling, a special Timeline Viewer is used.
- Timeline Viewer is a set of filters and diagrams that visualize the event timeline of your app and allow you to slice and dice the collected temporal data.
- Each filter is dual-purpose: it both displays data and lets you set a specific condition.
- Filters can be chained together.
In the following tutorials, we will learn how to use Timeline to improve app performance in more complex scenarios, for example when excessive garbage collections or file I/O operations take place, or when you face some multithreading issue like lock contention.