• Use AB_LogicalOperatorScope to analyze performance using System.Diagnostics.Trace

Use AB_LogicalOperatorScope to analyze performance using System.Diagnostics.Trace

  • 285 Views
  • Last Post 18 March 2016
dwebb posted this 29 January 2016

If your code is performing slowly and you're not sure why, a useful analysis technique is to add some diagnostic logging around blocks of code you suspect might be slow and to report how much time is spent in those code blocks. System.Diagnostics provides a number of tools which can be used, including the Stopwatch class for high-resolution timing and the Trace class for sending output to various TraceListeners. When an application is running in debug mode, Visual Studio attaches a ConsoleTraceListener to the Output window for you, so any trace output, such as from calling System.Diagnostics.Trace.WriteLine(), will be visible there. It's also possible, using settings in App.Config or Web.Config, to send trace output to other places, such as text files or the Windows Event log.

The AB_LogicalOperationScope class makes it easy to wrap a block of code with tracing, with a start time, end time, duration, and nested logging. To use it, wrap the code to diagnose in a using block. These blocks can be nested, which will cause the log entries to be indented to show the nesting:

protected override void am_AsyncSearchCompleted(System.Collections.IList EntityRecords, AB_SelectReturnArgs SelectReturnArgs)
{
    using (new AB_LogicalOperationScope("am_AsyncSearchCompleted"))
    {
        using (new AB_LogicalOperationScope("Call base.am_AsyncSearchCompleted"))
        {
            base.am_AsyncSearchCompleted(EntityRecords, SelectReturnArgs);
        }

        using (new AB_LogicalOperationScope("Call _LoadTree after async search"))
        {
            // Load Tree
            _LoadTree();
        }

        if (_SelectedModule == null)
            return;

        using (new AB_LogicalOperationScope("Set ap_SelectedItem properties after async search"))
        {
            foreach (AB_BusinessObjectEntityBase item in ap_DataPresenter.ap_Items.Cast<ab_businessobjectentitybase>().Where(item =&gt; item.ap_CompleteUniqueKey == _SelectedModule.ap_CompleteUniqueKey))
            {
                ap_DataPresenter.ap_SelectedItem = item;
                break;
            }
        }
    } 
}</ab_businessobjectentitybase>

This method's log trace will look like this:


[171318832883] START am_AsyncSearchCompleted
    [171318888188] START Call base.am_AsyncSearchCompleted
    [171319062011] FINISH (66.916909ms) Call base.am_AsyncSearchCompleted
    [171319074116] START Call _LoadTree after async search
        [171319095415] START _LoadTree - 142ab766-fc33-43be-8032-8331bba53513
            [171319104210] START Set expanded flag and event handler - 142ab766-fc33-43be-8032-8331bba53513
            [171319114309] FINISH (3.891454ms) Set expanded flag and event handler - 142ab766-fc33-43be-8032-8331bba53513
            [171319131723] START Add modules to recordSet - 142ab766-fc33-43be-8032-8331bba53513
            [171319143700] FINISH (4.614388ms) Add modules to recordSet - 142ab766-fc33-43be-8032-8331bba53513
            [171319171338] START Call ap_DataTransform for 3 records - 142ab766-fc33-43be-8032-8331bba53513
            [171319216930] FINISH (17.554848ms) Call ap_DataTransform for 3 records - 142ab766-fc33-43be-8032-8331bba53513
        [171319230210] FINISH (51.892719ms) _LoadTree - 142ab766-fc33-43be-8032-8331bba53513
    [171319236621] FINISH (62.559667ms) Call _LoadTree after async search
[171319240466] FINISH (156.903067ms) am_AsyncSearchCompleted

performance
DerekMaciak posted this 18 March 2016

The numbers in square brackets are the timestamp of each entry, in 'ticks'. There are 10 million ticks per second, but the frequency that the counter is updated varies across different operating systems and platforms.

The tick counter is useful for low-precision ordering of events, but not for measuring high-precision durations. A Stopwatch is used to provide durations instead; it is started when the AB_LogicalOperationScope object is created (when the START log entry is written) and stopped when the using block is exited. The duration in milliseconds is calculated using the precision that the operating system makes available (0, 3, or 6 decimal places) and displayed in parentheses in the FINISH log entry.

A point-in-time log entry can also be written; this is a wrapper around Trace.WriteLine(string message) that provides the same timestamp formatting and indenting that the using() block provides:

    AB_LogicalOperationScope.WriteLine("Something happened here");

Tracing can also be used to show the program's execution flow, especially in complex asynchronous situations. I've attached an example trace (the full version of the trace log above) which shows an out-of-control UI element that's performing slowly. From the trace it is easy to see that the control is sending and reacting to too many events, and it doing far more unnecessary work than it should be doing.

Categories
Search
Popular Tags
Hot Topics
Close