Performance Timing Made Simple

Luke Rogers
@lukerogers

Recently I was working on an application that utilizes Azure Service Fabric and I was doing load testing before going live and I wasn't getting the performance I was expecting. Since this application can only run under the service fabric runtime, profiling is a big challenge. Tools like ANTS Performance Profiler or dotTrace can't plug in since service fabric is hiding the application so I needed to turn to a regular C# StopWatch to track down the problem. I didn't want to go into every method, create a stopwatch, start it, stop it, and log the value so I started looking for a better way to do it. I did a quick search and came across this answer from John Skeet who was accused of either not being John Skeet or voting for his own answer. I don't know John Skeet but I doubt he needs to up-vote himself as he has mad (digital) street cred. Here is what John suggested:

public static TimeSpan Time(Action action)
{
    Stopwatch stopwatch = Stopwatch.StartNew();
    action();
    stopwatch.Stop();
    return stopwatch.Elapsed;
}

This is a very simple way to wrap a code block to get a TimeSpan back. Very concise and I never would have figured it out, but I wanted to take it further to make my life easier. I wanted to be able to drop wrap some methods in have it

Write the timing to a log (since this was in Azure)
Have the log include the class and method that was being tracked automatically.

I wanted to be able to drop this into my code and not have to customize every log instance in order to know where is was coming, from so I tweaked Mr Skeet's code to be the following:

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace PerformanceDiagnotics
{
    public class PerformanceTimer
    {
        private readonly bool _enabled;
        private readonly ILogger _logger;

        public PerformanceTimer(bool enabled, ILogger logger)
        {
            _enabled = enabled;
            _logger = logger;
        }

        public void LogTiming(Action action, string customAction = "", [CallerFilePath] string file = "", [CallerMemberName] string memberName = "")
        {
            var stopwatch = new Stopwatch();
            if (_enabled)
            {
                stopwatch = Stopwatch.StartNew();
            }
            action();

            if (!_enabled) return;

            stopwatch.Stop();

            Log(fileName, memberName, customAction, stopwatch.Elapsed.TotalMilliseconds);
        }

        public async Task LogTimingAsync(Func action, string customAction = "", [CallerFilePath] string file = "", [CallerMemberName] string memberName = "")
        {
            var stopwatch = new Stopwatch();

            if (_enabled)
            {
                stopwatch = Stopwatch.StartNew();
            }

            await action();

            if (_enabled)
            {
                stopwatch.Stop();

                Log(file, memberName, customAction, stopwatch.Elapsed.TotalMilliseconds);
            }
        }

        private void Log(string file, string memberName, string customAction, double totalMilliseconds)
        {
            var split = file.Split('\\');
            var fileName = split[split.Length - 1].Replace(".cs", "");

            if (!string.IsNullOrEmpty(customAction))
            {
                _logger.LogDebug("Class: {Class}, Method: {Method}, Action: {Action}, Timing {Timing}", fileName,
                    memberName, customAction, totalMilliseconds);
            }
            else
            {
                _logger.LogDebug("Class: {Class}, Method: {Method}, Timing {Timing}", fileName, memberName,
                    totalMilliseconds);
            }
        }
    }
}

There are a couple things of note here:

There is one method for synchronous and one for asynchronous
CallerFilePath – By using the attribute it gives us the file path to use. In my case it is a 1:1 to a class which is very convenient
CallerMemberName – This one give us the method that the call came from
I included a custom action so if i wanted to have multiple timers I could add extra metadata to know what is going on
I added an Enabled propery to turn on/off the timing to save CPU cycles. A simple application parameter canturn it on or off
I used an ILogger since this was in ASP.NET Core, but any logging mechanism could be swapped in

I was happy how this turned out as I was able to drop in timing all over the application fairly quickly. Using it is pretty simple too.

Synchronous

_timing.LogTiming(() =>
{
    DeleteLoginInfo(id);
});

Asynchronous

await _timing.LogTimingAsync(async () =>
{
    await DeleteLoginInfo(id);
});

There is likely room for improvement here but this got me out of a bind and hopefully it helps someone else too!

dotnet

Performance Timing Made Simple

Luke Rogers