Please be careful when using Trace.WriteLineIf()

Today I ran into the performance issue again while profiling a .NET library we are using to communicate with a mainframe. The problem I found is one I encounter rather frequently, so I decided to write something on this topic.

The ting that happens is the following:

Good programmers want their code to be traceable, so when they run into some weird problem they can turn on tracing to get a complete picture on what is happening. .NET has some great classes that support this in the System.Dyagnostics namespace. This is a best practice and I encourage you to do so.

The methods that are available to you are the Trace and Debug classes that have methods like Write, WriteLine and the WriteLineIf. The last method WriteLineIf is the one that keeps popping up as a performance killer in libraries because developers misunderstand what it is doing.

The online help says the following about this method: “Writes information about the trace to the trace listeners in the Listeners collection if a condition is true”

So, WriteLineIf() will only generate output to the trace when the first argument of the method contains a Boolean value that evaluates to true. So many developers start using this method and assume they don’t get the trace overhead when not tracing. But here comes the pitfall:

While the Boolean value might be false, this still makes the arguments passed to the WriteLineIf to get evaluated. So if you e.g. provide a whole bunch of strings that need to be formatted, resolved from resources etc. this will get done for each call if it will trace or not.

One of the examples I found recently is the following:

TraceWriteLineIf(traceSwitch.Verbose, Messages.GetMessage(msg.toString() + “. Time: “ +DateTime.Now.ToString() + “Class: “ + this.GetType().AssemblyQualifiedName.ToString() + …..

This code construct means that every time WriteLineIf is called but tracing is not enabled still all method calls get evaluated to get the correct argument to be passed to WriteLineIf.

You can imagine what kind of overhead this would generate when you got a piece of library code that has extensive tracing capabilities…

I just changed all lines of code into the following code construct:

If(traceSwitch.Verbose)
{
            Trace.Write(…….)
}

This improved the overall performance of the library significantly. Even the end users noticed the performance gains of their WebPages.

So be very careful when using Trace.WriteLineIf() and all similar functions available. Always remember that before the function can be called all arguments need to get evaluated and this can indeed generate a huge overhead.