Recently I’ve had on my mind, what is the most performant way to do optional logging, e.g. Tracing in particular, where by default it is turned off, but by using some sort of switch/command line argument, I can turn it on for extra info when trying to debug something on a users machine, and therefore cannot recompile.

In this post I will be concentrating on comparing the performance for the following methods of achieving this:

• IObservable // RxIObservable
• if (LogLevel <= LogLevel.Trace) // IfMoreThanOrEq
• if (LogLevel < LogLevel.Debug) // IfMoreThanEnum
• _traceDelegate = new delegate { } // NoOpDelegate
• if (_traceDelegate != null) // IfTraceDelegate
• if (IsTraceEnabled) // IfIsTraceProp
• if (IsTraceEnabled) // IfIsTraceField

The reason I am interested is because there may arise a situation where I may occasionally want to turn on tracing, for operations which happen 1000’s of times per second. Of course once you turn it on it would be negligible which method you choose as the time taken for output of the log would be far higher, but ideally I would never be turning this logging on, only in rare occasions.

First suite of tests I did was run it with Logging Off, so I could see the effect that each method would have on the performance. I run each method 1,000,000 times as well as doing a multiplication and keeping a total to mimic some very light work.

As you can see using a boolean field to represent whether it should log or not is fastest, and almost as fast as doing nothing where as using a property for this, took the longest. Don’t get me wrong, for doing these checks 1 million times, it is pretty pointless going and changing your loggers to use this if they are not already, but it is worth noting should you need to optimize some mission critical code in the future.

I also run the tests with the Trace turned on for completeness. The following is a relative representation of how long each test method took.

Let me start of with the code that was being run 1,000,000 times:

for (int i = 0; i < Size; i++)
{
    methodToLog(i);
    total += DoSomeWork(i);
}

and

public int DoSomeWork(int i)
{
    return i*2;
}

So as you can see it was really simple stuff. Ofcourse normally you would have heavier work load and the impact would be marginal. But none the less, let me continue.

The implementations of each logging method are as follows in relative performance impact ascending when logging was turned of.

public class IfIsTraceField // 6% Impact
{
    public static bool IsTraceEnabled;

    public static void Trace(int x)
    {
        if (IsTraceEnabled) TraceLog.Add(x);
    }
}

Followed by

public class IfTraceDelegate // 16% Impact
{
    public static Log TraceHandler = null;

    public static void Trace(int x)
    {
        if (TraceHandler != null) TraceHandler(x);
    }
}

In Third Place:

public class RxIObservable // 36% Impact
{
    private static readonly Subject<int> TraceSubject = new Subject<int>();

    public static IObservable<int> TraceObservable
    {
        get { return TraceSubject; }
    }

    public static void Trace(int x)
    {
        TraceSubject.OnNext(x);
    }
}

And the remainder as they were all very close:

public class IfLessThanEnum // 64%
{
    public static LogLevel LogLevel { get; set; }

    public static void Trace(int x)
    {
        if (LogLevel < LogLevel.Debug) TraceLog.Add(x);
    }
}

public class NoOpDelegate // 66% Impact
{
    public static Log TraceHandler = delegate { };

    public static void Trace(int x)
    {
        TraceHandler(x);
    }
}

public class IfLessThanOrEq // 69% Impact
{
    public static LogLevel LogLevel { get; set; }

    public static void Trace(int x)
    {
        if (LogLevel <= LogLevel.Trace) TraceLog.Add(x);
    }
}

public class IfIsTraceProp // 69% Impact
{
    public static bool IsTraceEnabled { get; set; }

    public static void Trace(int x)
    {
        if (IsTraceEnabled) TraceLog.Add(x);
    }
}

Conclusions, a private field is fastest, where as property is slowest (I am assuming that this is due to the stack push/pop and/or context switching. Will need to look into the generated IL and blog about it one day.

Anyhow the code will be available on GitHub shortly.