Getting Started with Timeline Profiling

Skip to end of metadata
Go to start of metadata

You are viewing an old version of this page. View the current version.

Compare with Current View Page History

« Previous Version 27 Next »

What Is Timeline Profiling?

Since the version 6.0, dotTrace offers a new method of profiling your apps – timeline profiling. What’s that 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. Thus, you get the same data about call times but now these data is bound to the timeline. This gives you a great opportunity to analyze not only typical “what is the slowest method?” issues but also the ones where the order of events does matter: UI freezes, excessive garbage collections, uneven workload distribution, insufficient file I/O, and others.
Using timeline profiling is simple: all you need is to choose the Timeline profiling type when configuring a session. To analyze collected timeline profiling snapshots, you should use a separate dotTrace component called Timeline Viewer.

What Next?

In this “Getting Started” tutorial we will take a detailed look at the main profiling steps, acquaint with the Timeline Viewer user interface and even try to solve a very common task – finding a reason of UI freezes in an app.

Contents

Sample App
Running the Profiler and Getting a Snapshot
First Look at the Timeline’s User Interface
Analyzing a Snapshot in Timeline
Conclusion

Sample App


As an example, we’ll use a small app used to reverse lines (e.g., "ABC" > "CBA") in text files. Briefly: With the Select Files button, a user specifies text files to be processed. The Process Files button runs a separate BackgroundWorker thread which reverses lines in the files. The progress of file processing is displayed in a label on the main window. After the processing is finished, the label shows the "All files were successfully processed" message.
The source code of the app is available here.

* The algorithm of fixing UI freezes shown in this tutorial contains some unnecessary steps and may seem you suboptimal. This is made intentionally as the main goal of the tutorial is to acquaint you with Timeline as maximally as possible.

The app has a serious drawback. After starting file processing, users experience long UI lags that last until the processing is over.
Let’s use Timeline to determine the cause of these freezes!*

Running the Profiler and Getting a Snapshot


  1. Open the MassFileProcessing.sln solution in Visual Studio.
  2. In case you have dotTrace integrated with Visual Studio, run the profiler by choosing ReSharper | Profile | Profile Startup Project (Performance)..
    Otherwise, run dotTrace from the Windows Start menu. In dotTrace, select New Session \ Local, Profile Application | Standalone.
  3. 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.
  4. After you click Run, dotTrace runs our app and a special controller window used to control the profiling process.

    Now, we should reproduce a performance issue in our app.
  5. Click the Select Files button and choose five text files that come with the app in the Text Files folder.
  6. Click the Process Files button 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.
  7. Collect a timeline profiling snapshot by clicking Get Snapshot’n’Wait in the controller window. The snapshot will be opened in Timeline Viewer.
  8. Close the app. This will also close the controller window.

First Look at the Timeline’s User Interface


Now, 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.

* The only window that cannot work as a filter is Source View.

So, where are the filters? Almost all windows you see inside Timeline Viewer not only display data but also are used to set a specific filter*. The result of filter’s work is always a set of time intervals or point events selected by a specific condition. For example, clicking the 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. Thus, if you turn on two filters mentioned above, you will get the resulting filter “Select all time intervals where the Main thread performed file I/O operations”. Complex filter combinations allow you to investigate almost every aspect of your application.

Actually, that's all you need to know before starting your work in Timeline Viewer. Now, it's time to try it in action!

Analyzing a Snapshot in Timeline


  1. Look at the Threads diagram. It contains all application threads including the unmanaged ones. Note that all filter values you see are calculated for all currently visible threads.
    From the point of further analysis, we are interested only in the managed threads, because they are the only ones we can affect. So, first, let’s get rid of native threads.
  2. In the Threads diagram, expand the Visible Threads list and disable the Native checkbox.

    The filter that is now applied to the snapshot data is “Select lifetime intervals of all threads excepting Native”.
  3. Look at the list of threads left on the diagram. It’s the Main app thread, the Finalizer thread (is used to finalize objects but does not do any work in our app), and Garbage Collection thread (is used to perform background GC). The Background thread that processes files in our app was identified as Thread Pool (ID 9840) because background threads are created by the CLR Thread Pool.

    Note how data in other filters were affected. For example, state times in Thread States are now calculated for all threads excepting the native ones. Top Methods and Call Tree have changed too showing calls only from the filtered threads. 
  4. The current scale of the Threads diagram doesn't allow us to see the 9840 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 Visible time range: 1705 ms filter. Note how this filter affects others: all values are recalculated for the visible time range.
    The filter that is now applied to the snapshot data is “Select all time intervals within the visible time range for all threads excepting Native”.
  5. Take a look at the Threads diagram.
    What you see is how thread states changed over time. For example, our BackgroundWorker thread 9840 Thread Pool was started approximately on 17.6 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).
  6. * The timeline pattern may look different on your computer as the execution flow depends on huge variety of factors (like a number of CPU cores, their workload during the app execution, and so on). Nevertheless, the freeze must take place regardless of your system configuration.

    Look at the Process Overview diagram*. In addition to CPU Utilization, it shows two event diagrams meaningful for performance analysis: the UI Freeze bar shows that the freeze started right after the 9840 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.

    So, it’s better to take a closer look on these events.
  7. 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. This will zoom the diagram back out.
  8. Now, let’s investigate the UI freeze event more thoroughly.
    What are the main reasons 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).
    • Excessive computational work on the UI thread.
      Therefore, all we need to do is exclude all reasons one by one until we find the real one.
  9. 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”.
  10. Now, we should understand what the real reason of this freeze was. Let’s investigate values in the Filters window.
    The first reason 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 (477 ms or 10.72% of the selected interval), but it is definitely not enough to explain the freeze. Therefore, the excessive GC reason can be excluded.
  11. Therefore, the reason of the freeze could be either “Blocking by some other thread” or “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 (79.92% or 3553 ms), the thread was doing some work as it was Running. The 815 ms value of the Waiting state is too small which automatically excludes the “Blocking by some other thread” reason. Therefore, the cause of the freeze is a computational work on the Main thread!
    All we need to do is to find methods that were executed on the Main thread during the freeze. For this purpose we can use the Top Methods and Call Tree filters.
  12. Select Running in the Thread States filter. This will make the resulting filter “Select all time intervals where the Main thread was running during the UI freeze”.
    The list of filters will look like follows:

    Now, Top Methods and Call Tree filters contain only methods executed during these time intervals.
  13. 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 the low-level system methods. Let's make the list more meaningful.
  14. Turn on the Hide system methods checkbox. In this mode, Top Methods shows only user methods. The execution time of user methods is calculated as a sum of the own user method time and the own time of all system methods it calls (down to the first user method in the stack).

    There are only two methods left: App.Main and ProcessInProgress.
  15. Look at the Call Tree.

    * By default, to simplify understanding of the call tree, Timeline Viewer folds system calls. To unfold the calls, click the  icon shown against the root system call.

    As you can see, App.Main spends most of the time in a number of system methods related to processing Windows messages*. This indicates that UI freeze takes place in the app and doesn’t bring additional details. To find out what method causes the freeze, we should look at the next user method in the stack which is ProcessInProgress (1051 ms or 29.57%).  
    We can make an assumption that lags took place due to some computational work in this method. Let’s check its source code.
  16. In Call Tree, click on the ProcessInProgress method.

    * The BackgroundWorker thread belongs to the app’s thread pool.

  17. As you see, the Threads Diagram filter contains all app threads including the system and native ones. Actually, we’re interested only in threads created by ourselves which are the main app thread and a BackgroundWorker thread. So, first, let’s get rid of all other threads.
    In the Additional Filters | Thread Types filter, click on Main and Pool* while holding the Ctrl key.
  18. Now, look at how Timeline has changed. As you see, the Filters List/Overview contains the filter you applied -- Thread Types: 2 values. Note how data in other filters were affected. For example, now state times in Thread States are calculated for the threads of selected types only. Methods and Call Tree have changed too showing calls only from the filtered threads. 
  19. Take a look at the Threads Diagram - all threads of non-selected types are greyed out. Nevertheless, for the convenience we can hide them completely.
    Select the Autohide checkbox. This will automatically hide all the threads we are not interested in. 
  20. The current scale of the Threads Diagram doesn’t allow us to see the details on what was done in Thread Pool Thread #1 (our BackgroundWorker thread). Let’s zoom in to it.
    To do this, use Ctrl+Mouse Wheel on the Threads Diagram.
    This automatically adds the Time Range: visible 2,476 ms filter. Note how this filter affects others: values in Additional Filters were recalculated for the visible time range.
  21. Take a look at the Threads Diagram.
    What you see is how thread states changed over time. For example, our BackgroundWorker thread Thread Pool Thread#1 was started approximately on 15.5 s (after we clicked the Process Files button). Thread’s work included file processing (the blue Run on CPU state), and reading/writing files (the green File I/O state). Besides, for some reasons, the thread was not working for some time: it was in the Blocked (yellow) and Idle (pale blue) states.
  22. Remove the Time Range filter by clicking on the corresponding button in Overview. This will zoom the diagram back out.
  23. Now, it’s time to deal with our UI freezes!
    What are the main reasons of such freezes? These are:
    • Excessive computational work on the main UI thread.
    • Long or frequent Garbage Collections (GC) on any thread (in workstation apps, when GC takes place all managed threads are suspended excluding the one that triggered the GC).
    • Blocking of the main UI thread by some other thread (for example, during access to some shared resources).
      Therefore, all we need to do is exclude all reasons one by one until we find the real one.
  24. Take a look at the States Diagram – It contains a special UI freezes section.

    * The timeline pattern may look different on your computer as the execution flow depends on huge variety of factors (like a number of CPU cores, their workload during the app execution, and so on). Nevertheless, both freezes should take place regardless of your system configuration.

    As you see there are several freezes detected*: one or more closer to the app start and one after we started file processing.
    Apparently, the reason of the first ones is some inevitable start-up activities and there’s nothing we can do about them. We’re much more interested in the second freeze. Let’s look at it in more details.
  25. Select the second UI freeze by clicking on it in the States Diagram | UI freezes section.

    * Now, all other filters show data only for this timeframe.
    ** The Threads: Main Thread filter is added automatically as UI freezes occur only on the main UI thread. Therefore, all filters now show data only for the Main thread.

    The Time Range: selected 3,978 ms* and Threads: Main Thread** filters are added.
  26. Now, we should understand what our app was doing during the freeze. Let’s investigate filters in the Additional Filters window.
  27. Look at the Additional Filters | CLR States filter. It shows states of the .NET runtime environment during the selected timeframe (3541 ms).

    It appears that most of the time our app was Running (81.80% and 2896 ms). The Garbage collection time is also quite high (17.50 % and 620 ms) but probably not enough to be the cause of the UI freeze (that lasted for the entire timeframe). 
  28. Select the Running state in Additional Filters | CLR States. Now, other filters will show data only for the periods of time when CLR was in the running state.
  29. Look at the Thread States filter.
    Most of the time (82.97 %) the Main thread was in the Run on CPU state. This means that during the major part of the freezing time, the main UI thread was doing some work (the Blocked state time is insignificant 302 ms). Therefore, the cause of the freeze is a computational work on the Main thread!
    Now, all we need to do is to find methods that were executed on the Main thread during the freeze. For this purpose we can use the Methods and Call Tree filters.
  30. Select Run on CPU in Additional Filters | Thread States.
    The list of filters in Filters List/Overview will look like follows:

    Now, Methods and Call Tree filters contain only methods that were executed (Run on CPU) by the Main Thread during the selected time interval (3541 ms long) when CLR was Running.

    Note that the Methods filter shows only user methods with the highest execution time. This time is a sum of the own execution time and execution times of all underlying system calls.
    Call Tree shows all calls in the stack (both to user and system methods). The time shown against a call is a sum of all times of underlying calls in a branch.
  31. * Obviously, we should not take into account the App.Main call as it is simply the entry point to our app.

    The Methods filter shows us that the main time (713 ms) was spent in the MainWindow.ProcessInProgress method*. Therefore, lags took place due to some computational work in this method. Let’s look at it in the source code window.
  32. In Call Tree, select MainWindow.ProcessInProgress.
  33. Look at Source Code.
    It appears that this method is just an event handler that updates the progress of file processing operation in a label on the main window. Definitely, this doesn’t look like complex computations.
    So, why did the freezes occur? The answer is simple. Apparently, this event handler is called so often that the main window doesn’t cope with updating of the label. Let’s check this out in code.
  34. * If you use ReSharper, you can employ a very helpful Inspect This feature (Ctrl+Shift+Alt+A combination). It is able to show you all incoming calls to the method.

    Switch to Visual Studio and look at the code.
    Further code investigation* shows us that this event handler is subscribed on 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.
  35. Here is the cause of our performance issues – ReportProgress is called each time after 10 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 for a 1000 lines. Improve the if condition in the code.
  36. Rebuild the solution and perform profiling one more time as described in Running the Profiler and Getting a Snapshot.
  37. Here it is! No more lags. Timeline also doesn’t detect any UI freezes during file processing.

Conclusion


Here is a short summary of this Getting Started tutorial:

  • Timeline is a set of filters and diagrams that visualize threads and thread-to-thread relationships.
  • Each filter not only sets a specific condition for shown data but also displays the data.
  • Filters affect each other. Setting a specific value in a filter changes values shown in other filters.

In next 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.

  • No labels