views:

214

answers:

4

I am looking into C# logging and I do not want my log messages to spend any time processing if the message is below the logging threshold. The best I can see log4net does is a threshold check AFTER evaluating the log parameters.

Example:

_logger.Debug( "My complicated log message " + thisFunctionTakesALongTime() + " will take a long time" )

Even if the threshold is above Debug, thisFunctionTakesALongTime will still be evaluated.

In log4net you are supposed to use _logger.isDebugEnabled so you end up with

if( _logger.isDebugEnabled )
    _logger.Debug( "Much faster" )

I want to know if there is a better solution for .net logging that does not involve a check each time I want to log.

In C++ I am allowed to do

LOG_DEBUG( "My complicated log message " + thisFunctionTakesALongTime() + " will take no time" )

since my LOG_DEBUG macro does the log level check itself. This frees me to have a 1 line log message throughout my app which I greatly prefer. Anyone know of a way to replicate this behavior in C#?

+6  A: 

If you can target .NET 3.5 (C# 3.0) you can use extension methods to wrap the if statements.

so you can do the equivalent "macro":

logger.Log_Debug("Much faster");

logger.Log_Debug(() => { "My complicated log message " + thisFunctionTakesALongTime() + " will take no time" });

by wrapping the check in this method:

public class Log4NetExtensionMethods {
    // simple string wrapper
    public void Log_Debug(this log4net.ILog logger, string logMessage) {
        if(logger.isDebugEnabled) {
             logger.Debug(logMessage);
        }
    }

    // this takes a delegate so you can delay execution
    // of a function call until you've determined it's necessary
    public void Log_Debug(this log4net.ILog logger, Func<string> logMessageDelegate) {
        if(logger.isDebugEnabled) {
             logger.Debug(logMessageDelegate());
        }
    }
}
Jeff Meatball Yang
But if I am evaluating functions to get the log message, wouldnt this be just as slow? I want to avoid all function evaluations if the log level is below my threshold.
Charles
You're correct that you'll need to delay the function evaluation. See my update that uses an anonymous delegate.
Jeff Meatball Yang
D'oh, that was my answer too. I should warn you that if you're looking for speed, you do not want to use delegates. You should just take the hit and use if `if (logger.isDebugEnabled)` around anything expensive. There is no solution which is both performant and elegant.
bobbymcr
Pretty sure that closures are faster than `thisFunctionTakesALongTime()`...
sblom
@bobbymcr: Performant is relative. Delegate invocation is on the same level as any inteface function call, where `thisFunctionTakesALongTime()` could run a Monte Carlo simulation that takes days.
Jeff Meatball Yang
@Jeff: I'm referring to the performance between using a delegate for conditional evaluation vs. a simple boolean check. See my answer below -- it's a 20%+ performance hit for using the lambda when logging is not enabled. The simple rule is if performance is critical, do not use late binding.
bobbymcr
A: 

Without a preprocessor you're SOL. Of course there's nothing preventing you from using one before feeding your code to the C# compiler.

blammo
anonymous delegates and extra classes - wow that's a lot of typing.
blammo
+1  A: 

The problem here is that all method parameters must be evaluated before the method is invoked. There is no way around this, given the syntax you are using. Since C# does not have a real preprocessor or macros, you can't do anything like "LOG_DEBUG". The best you could do is use if (logger.isDebugEnable) as suggested.

The only thing I can think of is maybe using something like a lambda expression to delay evaluation. But I would warn you that this will almost certainly have more of a performance hit in the end.

internal class Sample
{
    private static void Main(string[] args)
    {
        DelayedEvaluationLogger.Debug(logger, () => "This is " + Expensive() + " to log.");
    }

    private static string Expensive()
    {
        // ...
    }
}

internal static class DelayedEvaluationLogger
{
    public static void Debug(ILog logger, Func<string> logString)
    {
        if (logger.isDebugEnabled)
        {
            logger.Debug(logString());
        }
    }
}
bobbymcr
Are lambda expressions that expensive?
Charles
@Charles: lambdas are relatively inexpensive as far as late binding goes, but far more expensive than a boolean check and a method call. In my simple test over a billion iterations (code here: http://pastebin.com/aRtMtsxz ), I measured about 25% overhead for lambda vs. boolean check when logging was not enabled. With a cached lambda (save the lambda to a field so it doesn't get re-generated each time), there is slightly less overhead (a litter under 20%).
bobbymcr
A: 

17.4.2 The Conditional attribute

The attribute Conditional enables the definition of conditional methods. The Conditional attribute indicates a condition by testing a conditional compilation symbol. Calls to a conditional method are either included or omitted depending on whether this symbol is defined at the point of the call. If the symbol is defined, the call is included; otherwise, the call (including evaluation of the parameters of the call) is omitted.

[ Conditional("DEBUG") ]
public static void LogLine(string msg,string detail)
{
    Console.WriteLine("Log: {0} = {1}",msg,detail);
}

public static void Main(string[] args)
{
    int Total = 0;
    for(int Lp = 1; Lp < 10; Lp++)
    {
        LogLine("Total",Total.ToString());
        Total = Total + Lp;
    }
}
blammo
This is interesting, I will do some more research on it.MSDN: http://msdn.microsoft.com/en-us/library/aa664622%28VS.71%29.aspx
Charles
I would assume that the better logging libraries already use this technique.
blammo
@Blammo, just because you're calling a "logger.debug" method doesn't mean you're actually running in debug mode. The name "debug" is really just method name for an arbitrary threshold as defined by the application developer. I would be surprised if Log4Net, EnterpriseLibrary, etc... actually use any conditional attributes since the attribute relies on the presence of a compilation symbol.
Metro Smurf