Page Comparison - Getting Started with Timeline Profiling (v.7 vs v.8)

Versions Compared

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

...

  1. As you see, the Threads Diagram filter contains now 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.
  2. 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. 
  3. 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. 
  4. 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.
  5. 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.
  6. Remove the Time Range filter by clicking on the corresponding  button. This will zoom the diagram back out.
  7. 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 one by one exclude all reasons until we find the real one.
  8. Take a look at the States Diagram – It contains a special UI freezes section.
    Note
    iconfalse

    * 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 two-three main 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 it. We’re much more interested in the second freeze. Let’s look at it in more details.
  9. Select the second UI freeze by clicking on the corresponding bar in the States Diagram | UI freezes section.
    Note
    iconfalse

    * 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.

    The Time Range: selected 3,978 ms* and Threads: Main Thread** filters are added.
  10. Now, we should understand what our app was doing during the freeze. Let’s investigate filters in the Additional Filters window.
  11. 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). 
  12. 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.
  13. 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 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. This is a purpose of the Methods and Call Tree filters.
  14. 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 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 underlying calls in a branch.
  15. Note
    iconfalse

    * 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.
  16. In Call Tree, select MainWindow.ProcessInProgress.
  17. Look at Source Code.
    Code Block
    languagecsharp
    
    private void ProcessInProgress(object sender, ProgressChangedEventArgs e)
    {
       var upd = (ProgressUpdater) e.UserState;
    
       lblProgress.Content = "File " + upd.CurrentFileNmb + " of" + upd.TotalFiles + ": " + e.ProgressPercentage + "%";
    }
    
    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.
  18. Note
    iconfalse

    * 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.
    Code Block
    languagecsharp
    
    ...
    for (int j = 0; j < _lines.Length; j++)
    {
       var line = _lines[j];
       var stringReverser = new StringReverser(line);
       _lines[j] = stringReverser.Reverse();
    
       if (j % 10 == 0)
       {
          var p = ((float)(j + 1) / _lines.Length) * 100;
          Worker.ReportProgress((int) p, _updater);
       }
    }
    ...
    
  19. 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 fast, 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.
    Code Block
    languagecsharp
    
    ...
    if (j % 1000 == 0)
    {
       float _p = ((float)(j + 1) / _lines.Length) * 100;
       Worker.ReportProgress((int) _p, _updater);
    }
    ...
    
  20. Rebuild the solution and perform profiling one more time as described in Running the Profiler and Getting a Snapshot.
  21. Here it is! No more lags. Timeline also doesn’t detect any UI freezes during file processing.
    Image Added

Conclusion
Anchor
Conclusion
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.