Code Block/Scope Timing Snippet

You've got users complaining that it takes too long for a screen to open or for a certain piece of code to run.  Wouldn't it be handy to wrap the execution of a key block of code with some timing statistics?

The following TimeIt class is derived from IDisposable which makes it easy to wrap a code block (aka scope) with the using keyword (this will ensure that if any exceptions are raised you'll still get to final end scope logged).

The timing internals are hidden way - it's easily accessed via a static Log method:

using (TimeIt.Log("Calculate cost"))
{

    Debug.WriteLine("Retrieving price..");
    var price = pricingService.GetPrice();
    var cost = notionalCalculator.GetUSDValue(price);
}

Results in the following  being written to the console:

Start Scope [MyClass.MyMethod]: Calculate cost

Retrieving price..

  End Scope [MyClass.MyMethod]: Calculate cost (8 ms)

In this implementation WriteLog simply writes to the console, but ideally you'd use something like log4net to write to a log file.

Listing 

using System;
using System.Diagnostics;
 
public class TimeIt : IDisposable
{
    private readonly string _fullMessage;
    private readonly Stopwatch _watch;
 
    private TimeIt(string message)
    {
        const int CallerFramesToSkip = 3;
        _fullMessage = string.Format("[{0}.{1}]: {2}",
            GetTypeName(CallerFramesToSkip), 
            GetStackMethodName(CallerFramesToSkip),
            message);
 
        WriteLog("Start Scope {0}", _fullMessage);
        _watch = Stopwatch.StartNew();
    }
 
    public void Dispose()
    {
        _watch.Stop();
        WriteLog("  End Scope {0} ({1})", _fullMessage, Format(_watch.Elapsed));
    }
 
    public static IDisposable Log(string format, params object[] args)
    {
        return new TimeIt(string.Format(format, args));
    }
 
    private static void WriteLog(string message, params object[] args)
    {
        // Ideally you'd use log4net or similar logger to write the actual

        // message prefixed with a timestamp 

        Console.WriteLine(message, args);

    }
 
    private static string Format(TimeSpan span)
    {
        double part;
        string units;
 
        if (span.TotalHours > 1D)
        {
            part = span.TotalHours;
            units ="hrs";
        }
        else if (span.TotalMinutes > 1D)
        {
            part = span.TotalMinutes;
            units = "mins";
        }
        else if (span.TotalSeconds > 1D)
        {
            part = span.TotalSeconds;
            units = "secs";
        }
        else
        {
            return string.Concat(span.Milliseconds, " ms");
        }
 
        return string.Format("{0:N1} {1}", part, units);
    }
 
    private static string GetStackMethodName(int framesToSkip)
    {
        var name = "UNKNOWN_METHOD";
        try
        {
            name = new StackTrace().GetFrame(framesToSkip).GetMethod().Name;

        }
        catch { }
 
        return name;
    }
 
    private static string GetTypeName(int framesToSkip)
    {
        var name = "UNKNOWN_METHOD";
        try
        {
            name = new StackTrace().GetFrame(framesToSkip).GetMethod().DeclaringType.Name;
        }
        catch { }
 
        return name;
    }
 
}

Tests

I've added couple of simple tests that don't have an assertions.  Not of much value, but I like to use Resharper as a quick way to run snippets:





using System;

using System.Threading;

using NUnit.Framework;

[TestFixture]
class TimeItTests
{
    [Test]
    public static void Log_Level1Method()
    {
        Level1Method();
    }
 
    private static void Level1Method()
    {
        using (TimeIt.Log("Busy doing level 1 stuff"))
        {
            Thread.Sleep(1100);
        }
    }
 
    [Test]
    public static void Log_Level2Method()
    {
        CallNestedMethod();
    }
 
    private static void CallNestedMethod()
    {
        Level2Method();
    }
 
    private static void Level2Method()
    {
        using (TimeIt.Log("Busy doing level 2 stuff"))
        {
            Thread.Sleep(TimeSpan.FromMinutes(1.1));
        }
    }
 
    [Test]
    [ExpectedException(typeof(ApplicationException))]
    public static void Log_CalleeThrowsException()
    {
        using (TimeIt.Log("This will break"))
        {
            Thread.Sleep(TimeSpan.FromSeconds(2));
            throw new ApplicationException("Oops, something went wrong");
        }
    }
 } 

Test Output:

Log_CalleeThrowsException:

Start Scope [TimeItTests.Log_CalleeThrowsException]: This will break

  End Scope [TimeItTests.Log_CalleeThrowsException]: This will break (2.0 secs)
 

Log_Level1Method:

Start Scope [TimeItTests.Level1Method]: Busy doing level 1 stuff

  End Scope [TimeItTests.Level1Method]: Busy doing level 1 stuff (1.1 secs)
 

Log_Level2Method:

Start Scope [TimeItTests.Level2Method]: Busy doing level 2 stuff

  End Scope [TimeItTests.Level2Method]: Busy doing level 2 stuff (1.1 mins)