Log Performance in a Using Block with Common.Logging

You should be using Common.Logging to share your logger between projects.

Common.Logging is a great and lightweight way to share dependencies without requiring that you also share implementation. It is how several of my projects that use Log4Net are able to shares resources with another team that uses NLog. But that is not what I am here to talk about!

How do you log performance quickly and easily?

No, I do not mean performance counters. No, I do not mean interceptors for dependency injection. I want something far more lightweight and simplistic! What I want is the ability to simply log if too much time is spent in a specific block of code. For example...

public void MyMethod1(ILog log)

{

    // If this using block takes more than 100 milliseconds,

    // then I want it to write to my Info log. However

    // if this using block takes more than 1 second,

    // then I want it to write to my Warn log instead.

    using (log.PerfElapsedTimer("MyMethod took too long!"))

    {

        var obj = GetFromApi();

        SaveToDatabase(obj);

    }

}

The PerfElapsedTimer is just a simple little extension method that I wrote, under the hood it just wraps a Stopwatch in an IDisposable. Feel free to grab the code from below and start using it yourself.

Shouldn't I check for deviations rather than arbitrary thresholds?

Yes, you might want to do that. So how about we keep a moving average of the last 10 durations for a given call, and then if a call is off by a given amount we log it? We can do that too!

public void MyMethod2(ILog log)

{

    // This takes 100 milliseconds.

    using (log.PerfElapsedTimer("MyMethod2.GetFromApi"))

        GetFromApi();

    // This takes 100 milliseconds.

    using (log.PerfElapsedTimer("MyMethod2.GetFromApi"))

        GetFromApi();

    // This takes 300 milliseconds, IT SHOULD LOG!

    using (log.PerfElapsedTimer("MyMethod2.GetFromApi"))

        GetFromApi();

}

Unit Tests and Implementation

Common.Logging.PerfTimers Source on GitHub
Common.Logging.PerfTimers Package on NuGet

Enjoy,
Tom