StopwatchLog – Easy Method Timing in C#

( Download Code )

Was looking for a simple and elegant way to log some metric for methods (mainly method name, start time, stop time and elapsed time) – I’ve done this in PostSharp in my article “Holy Grail of Application Profiling with AOP” – but client wasn’t using them.

I’ve used reflection with success in the past, but was having some issues with Async methods not giving their real method names, was getting “MoveNext” instead — so sleuthed around for an alternative and found some awesome C# attributes that I’d never seen…

[CallerMemeberName] – gets the method name calling the attribute
[CallerFilePathAttribute] – gets the path to the C# file
[CallerLineNumberAttribute] – gets the line of the method in code

Combining those with the C# Stopwatch Class – and using the Dispose patter that I love because you can easily code the “using” statement around what you’re looking at ( see below ) – came up with the following cool code that – as always – I love to share.

Emphasis on elegant, to call this code – you can easily do the following…

using (StopwatchLog.Track())
{
   // Your code here...
}

It collects the information about executing method and logs metrics when the stopwatch log is disposed.

Here’s the complete code in a console example with both Async and old school method calls ( Download Code ).

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;

namespace StopwatchLog
{
    internal class Program
    {
        private static void Main()
        {
            TestMethodSleep1Async();
            TestMethodSleep2Async();
            TestMethodSleep5Async();

            TestMethodSleep1();
            TestMethodSleep2();
            TestMethodSleep5();

            Console.ReadLine();
        }

        static async void TestMethodSleep1Async()
        {
            StopwatchLog log;
            using (log = StopwatchLog.Track())
            {
                await Task.Delay(1000);
            }
            // In case you want to get the values back outside of logging
            var elapsedTime = log.Stopwatch.ElapsedMilliseconds;
        }

        static async void TestMethodSleep2Async()
        {
            using (StopwatchLog.Track())
            {
                await Task.Delay(2000);
            }
        }

        static async void TestMethodSleep5Async()
        {
            using (StopwatchLog.Track())
            {
                await Task.Delay(5000);
            }
        }

        public static void TestMethodSleep5()
        {
            using (StopwatchLog.Track())
            {
                Thread.Sleep(5000);
            }
        }

        public static void TestMethodSleep2()
        {
            using (StopwatchLog.Track())
            {
                Thread.Sleep(2000);
            }
        }

        public static void TestMethodSleep1()
        {
            using (StopwatchLog.Track())
            {
                Thread.Sleep(1000);
            }
        }

        /// <summary>
        ///  Collects information about executing method and logs metrics 
        ///     when the stopwatch log is disposed.
        /// </summary>
        /// <example>
        ///   using (StopwatchLog.Track())
        ///   {
        ///     // Code here...
        ///   }
        /// </example>
        public sealed class StopwatchLog : IDisposable
        {
            public string MethodName { get; set; }
            public string FilePath { get; set; }
            public int LineNumber { get; set; }
            public Stopwatch Stopwatch { get; set; }
            public DateTime StopwatchStart { get; set; }
            public DateTime StopwatchStop { get; set; }

            private StopwatchLog(string methodName, string filePath, int lineNumber)
            {
                this.MethodName = methodName;
                this.FilePath = filePath;
                this.LineNumber = lineNumber;
                this.StopwatchStart = DateTime.UtcNow;
                this.Stopwatch = Stopwatch.StartNew();
            }

            void IDisposable.Dispose()
            {
                this.Stopwatch.Stop();
                this.StopwatchStop = DateTime.UtcNow;
                LogMetrics();
            }

            private void LogMetrics()
            {
                //TODO: Swap out with a call to your favorite Logger

                Console.WriteLine("Method '{0}' | File '{1}' | Line Number: {2}  | Started: {3} | Ended {4} | Elapsed {5} ms",
                    this.MethodName,
                    this.FilePath,
                    this.LineNumber,
                    this.StopwatchStart.ToDateTimeHighPrecision(),
                    this.StopwatchStop.ToDateTimeHighPrecision(),
                    this.Stopwatch.ElapsedMilliseconds);
            }

            public static StopwatchLog Track(
                [CallerMemberName] string callingMethodName = "",
                [CallerFilePath] string callingFilePath = "",
                [CallerLineNumber] int callingLineNumber = 0)
            {
                return new StopwatchLog(callingMethodName, callingFilePath, callingLineNumber);
            }
        }
    }

    public static class DateTimeExtentions
    {
        public static string ToDateTimeHighPrecision(this DateTime source)
        {
            return source.ToString("MM/dd/yyyy h:mm:ss.fff tt");
        }
    }
}