How fast is log4net logging (Debug, Info, etc.)?

Question

I am a big fan of log4net , but recently some (in my department) have questioned its inclusion in our projects, because of the apparent severity of each logging method. I would say that there are better methods than others, but that is another question.

I'm curious to know what the typical impact of a log4net DebugFormat call on your applications is. I am going to leave variables such as the number of log statements in lines of code, etc., because I'm just looking for everything that you saw in the real world.

And I know of a simple technique for adding a guard clause to long evaluative statements, for example:

if (log.IsDebug) { log.DebugFormat(...); } 

So, let this be excluded from consideration at the moment.

Answer 1

I am not familiar with log4net or log.DebugFormat (...).

But the cost of logging is valid in two areas.

The first is the call to the log, and the second is the actual storage of the log information.

Advocates help reduce the minimum logging call when logging is not actually required. It tends to be very fast, as it is a bit more than calling a method and comparing two scalars.

However, when you are not using security devices, the cost may be the cost of creating the actual logging arguments.

For example, in log4j this was a common idiom:

 log.debug("Runtime error. Order #" + order.getOrderNo() + " is not posted."); 

Here, cost is the actual evaluation of the string expression that creates the message. This is because regardless of the level of logging, this expression and the resulting string are created. Imagine if you had something like:

 log.debug("Something wrong with this list: " + longListOfData); 

This can create a large and expensive string variable that, if the log level is not set for DEBUG, will simply be wasted.

Guards:

 if (log.isDebug()) { log.debug(...); } 

Fix this problem because calling isDebug is cheap, especially compared to actually creating the argument.

In my code, I wrote a wrapper for logging, and I can create logs like this:

 log.debug("Runtime error. Order # {0} is not posted.", order.getOrderNo()); 

This is a good compromise. It depends on Java varargs, and my code checks the logging level and then formats the message accordingly. It's almost as fast as the guards, but much cleaner to write.

Now log.DebugFormat could very well do a similar thing, which I do not know about.

In addition, of course, this is the actual cost of registration (on the screen, to a file, to a socket, etc.). But this is just the cost you have to accept. My best practice for this, when practical, is to direct the actual log messages to a queue, which is then fetched and output to the correct channel using a separate thread. This, at least, helps to keep an incompatibility log with the main computers, but it does have its costs and complexity.

Answer 2

I know this is an old thread, but what about using an approach that avoids filling the code with if statements based on the log level, for example: http://www.beefycode.com/post/Extension-Methods-for-Deferred-Message- Formatting-in-Log4Net.aspx

Using the lambda expression to construct a message, you may not even fully appreciate it.

Answer 3

The log4net FAQ has the answer to this question , although it does not match the level of detail you are looking for.

In short: use those defensive offers.

Answer 4

Just Giving Will Hartung will answer the .NET perspective :)

DebugFormat Code:

 if (IsDebugEnabled) { Logger.Log(ThisDeclaringType, m_levelDebug, new SystemStringFormat(CultureInfo.InvariantCulture, format, args), null); } 

Basically, this is the same, so I believe that when using DebugFormat you do not need to use the guard clause (you may have small overheads, but I think it is small enough to be ignored)

would leave a comment, but I do not have enough reputation: /