C# conditional logging/tracing

问题:

I want to add logging or tracing to my C# application but I don't want the overhead of formatting the string or calculating values to be logged if the log verbosity level is set so low that the message will not be logged.

In C++, you can use the preprocessor to define macros that will prevent code from being executed at all like this:

#define VLOG(level,expr) if (level >= g_log.verbosity) { g_log.output << expr; }

Used like this:

VLOG(5,"Expensive function call returns " << ExpensiveFunctionCall());

How do you do that in C#?

I've read the Microsoft docs explaining the Trace and Debug facilities here, and they claim that using #undef DEBUG and #undef TRACE removes all tracing and debugging code from the produced executable, but does it really remove the whole call? Meaning, if I write

System.Diagnostics.Trace.WriteLineIf(g_log.verbosity>=5,ExpensiveFunctionCall());

it won't call my expensive function if I undefine TRACE? Or does make the call, then decide it won't trace anything?

Anyway, even if it does remove it, this is inferior to the C++ macro because I can't make that big ugly call look like my simple VLOG() call in C++ and still avoid evaluating parameters, can I? Nor can I avoid the overhead by defining the verbosity lower at runtime like I can in C++, right?

回答1:

To answer one of your questions, all method calls that must evaluate in order to call Trace.WriteLine (or its siblings/cousins) do not get called if Trace.WriteLine is compiled out. So go ahead and put your expensive method calls in directly as parameters to the Trace call and it will be removed at compile-time if you don't define the TRACE symbol.

Now for your other question regarding changing your verbosity at runtime. The trick here is that Trace.WriteLine and similar methods take 'params object[] args' for their string formatting arguments. Only when the string is actually emitted (when verbosity is set sufficiently high) does the method call ToString on those objects to get a string out of them. So a trick I often play is to pass objects rather than fully-assembled strings to these methods, and leave the string creation in the ToString of the object I pass in. That way the runtime performance tax is only paid when logging is actually occurring, and it gives you the freedom to change verbosity without recompiling your app.

回答2:

A solution that has worked for me is using a singleton class. It can expose your logging functions and you can control its behavior efficiently. Lets call the class 'AppLogger'. Her is an example

public class AppLogger
{
   public void WriteLine(String format, params object[] args)
    {
        if ( LoggingEnabled )
        {
            Console.WriteLine( format, args );
        }
    }
}

Note, the Singleton stuff is left out of the above example. There are TONS of good examples out the tubes. NOw the interesting thing is how to support multi-threading. I've done it like this: (abbreviated for brevity, hahahaha)

public static void WriteLine( String format, params object[] args )
{
    if ( TheInstance != null )
    {
        TheInstance.TheCreatingThreadDispatcher.BeginInvoke(  Instance.WriteLine_Signal, format, args );
    }
}

In this way, any thread can log and the messages are handled on the original creating thread. Or you could create a special thread just for handling logging output.

回答3:

ConditionalAttribute is your best friend. The call will be completely removed (as though call sites were #if'd) when the #define is not set.

EDIT: someone put this in a comment (thanks!), but worth noting in the main answer body:

All the methods of Trace class are decorated with Conditional("TRACE"). Just saw this using reflector.

Which means Trace.Blah(...expensive...) does completely disappear if TRACE is not defined.

回答4:

All the info about Conditional(Trace) is good - but I assume your real question is that you want to leave the Trace calls in your production code but (usually) disable them at run-time unless you experience a problem.

If you're using TraceSource's (which I believe you should, rather than calling Trace directly because it gives you more fine-grained control over tracing at a component-level at run-time), you can do something like this:

if (Component1TraceSource.ShouldTrace(TraceEventType.Verbose))
     OutputExpensiveTraceInformation()

This assumes you are able to isolate the tracing parameters in another function (i.e. they mostly depend on members of the current class rather than expensive operations on the parameters to the function in which this code is in).

The advantage of this approach is because the JITer compiles on a function-by-function basis as it needs to, if the "if" evaluates to false, the function will not only not be called - it won't even be JITed. The downside is (a) you've separated knowledge of the tracing level between this call and the function OutputExpensiveTraceInformation (so if you e.g. change the TraceEventType there to be TraceEventType.Information, for instance, it won't work because you'll never even call it unless the TraceSource is enabled for Verbose level tracing in this example) and (b) it's more code to write.

This is a case where it would seem that a C-like preprocessor would help (since it could make sure, for instance,that the parameter to ShouldTrace and to the eventual TraceEvent call are the same), but I understand why C# doesn't include that.

Andrew's suggestion of isolating expensive operations in the .ToString methods of the objects you pass to TraceEvent is also a good one; in that case, you could for instance develop an object which is just used for Trace to which you pass the objects you want to build an expensive string representation of and isolate that code in the ToString method of the trace object rather than doing it in the parameter list to the TraceEvent call (which will cause it to be executed even if the TraceLevel is not enabled at run-time).

Hope this helps.

回答5:

have you tried a sophisticated logging api like log4net (http://logging.apache.org/log4net/index.html)?

回答6:

Two of these answers (Andrew Arnott's and Brian's) did answer part of my question. The ConditionalAttribute that is applied to the Trace and Debug class methods causes all calls to the methods to be removed if TRACE or DEBUG are #undef'd, including the expensive parameter evaluation. Thanks!

For the second part, whether you can completely remove all calls at runtime, not at compile time, I found the answer in the log4net fac. According to them, if you set a readonly property at startup time, the runtime will compile away all calls that don't pass the test! This doesn't let you change it after startup but that's fine, it's better than removing them at compile time.

回答7:

For your comment

"because I can't make that big ugly call look like my simple VLOG() call in C++ " - You could add a using statement as example below.

using System.Diagnostics;

....
Trace.WriteLineIf(.....)

As I understand, it will remove lines containing Trace, if you undefine the Trace symbol.

回答8:

I'm not sure, but you can find out the answer yourself.

Make it a REALLY expensive function (like Thread.Sleep(10000)) and time the call. If it takes a very long time, then it's calling your function anyway.

(You can wrap the Trace.WriteLineIf() call with #if TRACE and #endif and test it again for a base comparison.)

回答9:

It will invoke the expensive call because it might have side effects that are desired.

What you can do is decorate your expensive method with a [Conditional("TRACE")] or [Conditional("DEBUG")] attribute. The method will not be compiled into the final executable if the DEBUG or TRACE constant is not defined, nor will any calls to execute the expensive method.