In log4j, does checking isDebugEnabled before logg

2019-01-03 12:24发布

I am using Log4J in my application for logging. Previously I was using debug call like:

Option 1:

logger.debug("some debug text");

but some links suggest that it is better to check isDebugEnabled() first, like:

Option 2:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text");
}

So my question is "Does option 2 improve performance any way?".

Because in any case Log4J framework have same check for debugEnabled. For option 2 it might be beneficial if we are using multiple debug statement in single method or class, where the framework does not need to call isDebugEnabled() method multiple times (on each call); in this case it calls isDebugEnabled() method only once, and if Log4J is configured to debug level then actually it calls isDebugEnabled() method twice:

  1. In case of assigning value to debugEnabled variable, and
  2. Actually called by logger.debug() method.

I don't think that if we write multiple logger.debug() statement in method or class and calling debug() method according to option 1 then it is overhead for Log4J framework in comparison with option 2. Since isDebugEnabled() is a very small method (in terms of code), it might be good candidate for inlining.

15条回答
孤傲高冷的网名
2楼-- · 2019-01-03 12:35

Since in option 1 the message string is a constant, there is absolutely no gain in wrapping the logging statement with a condition, on the contrary, if the log statement is debug enabled, you will be evaluating twice, once in the isDebugEnabled() method and once in debug() method. The cost of invoking isDebugEnabled() is in the order of 5 to 30 nanoseconds which should be negligible for most practical purposes. Thus, option 2 is not desirable because it pollutes your code and provides no other gain.

查看更多
地球回转人心会变
3楼-- · 2019-01-03 12:35

In Java 8, you don't have to use isDebugEnabled() to improve the performance.

https://logging.apache.org/log4j/2.0/manual/api.html#Java_8_lambda_support_for_lazy_logging

import java.util.logging.Logger;
...
Logger.getLogger("hello").info(() -> "Hello " + name);
查看更多
姐就是有狂的资本
4楼-- · 2019-01-03 12:35

I would recommend using Option 2 as de facto for most as it's not super expensive.

Case 1: log.debug("one string")

Case2: log.debug("one string" + "two string" + object.toString + object2.toString)

At the time either of these are called, the parameter string within log.debug (be it CASE 1 or Case2) HAS to be evaluated. That's what everyone means by 'expensive.' If you have a condition before it, 'isDebugEnabled()', these don't have to be evaluated which is where the performance is saved.

查看更多
来,给爷笑一个
5楼-- · 2019-01-03 12:38

Since many people are probably viewing this answer when searching for log4j2 and nearly all current answers do not consider log4j2 or recent changes in it, this should hopefully answer the question.

log4j2 supports Suppliers (currently their own implementation, but according to the documentation it is planned to use Java's Supplier interface in version 3.0). You can read a little bit more about this in the manual. This allows you to put expensive log message creation into a supplier which only creates the message if it is going to be logged:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());
查看更多
ゆ 、 Hurt°
6楼-- · 2019-01-03 12:41

Using the isDebugEnabled() is reserved for when you're building up log messages by concatenating Strings:

Var myVar = new MyVar();
log.debug("My var is " + myVar + ", value:" + myVar.someCall());

However, in your example there is no speed gain as you're just logging a String and not performing operations such as concatenation. Therefore you're just adding bloat to your code and making it harder to read.

I personally use the Java 1.5 format calls in the String class like this:

Var myVar = new MyVar();
log.debug(String.format("My var is '%s', value: '%s'", myVar, myVar.someCall()));

I doubt there's much optimisation but it's easier to read.

Do note though that most logging APIs offer formatting like this out of the box: slf4j for example provides the following:

logger.debug("My var is {}", myVar);

which is even easier to read.

查看更多
啃猪蹄的小仙女
7楼-- · 2019-01-03 12:42

Short Version: You might as well do the boolean isDebugEnabled() check.

Reasons:
1- If complicated logic / string concat. is added to your debug statement you will already have the check in place.
2- You don't have to selectively include the statement on "complex" debug statements. All statements are included that way.
3- Calling log.debug executes the following before logging:

if(repository.isDisabled(Level.DEBUG_INT))
return;

This is basically the same as calling log. or cat. isDebugEnabled().

HOWEVER! This is what the log4j developers think (as it is in their javadoc and you should probably go by it.)

This is the method

public
  boolean isDebugEnabled() {
     if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }

This is the javadoc for it

/**
*  Check whether this category is enabled for the <code>DEBUG</code>
*  Level.
*
*  <p> This function is intended to lessen the computational cost of
*  disabled log debug statements.
*
*  <p> For some <code>cat</code> Category object, when you write,
*  <pre>
*      cat.debug("This is entry number: " + i );
*  </pre>
*
*  <p>You incur the cost constructing the message, concatenatiion in
*  this case, regardless of whether the message is logged or not.
*
*  <p>If you are worried about speed, then you should write
*  <pre>
*    if(cat.isDebugEnabled()) {
*      cat.debug("This is entry number: " + i );
*    }
*  </pre>
*
*  <p>This way you will not incur the cost of parameter
*  construction if debugging is disabled for <code>cat</code>. On
*  the other hand, if the <code>cat</code> is debug enabled, you
*  will incur the cost of evaluating whether the category is debug
*  enabled twice. Once in <code>isDebugEnabled</code> and once in
*  the <code>debug</code>.  This is an insignificant overhead
*  since evaluating a category takes about 1%% of the time it
*  takes to actually log.
*
*  @return boolean - <code>true</code> if this category is debug
*  enabled, <code>false</code> otherwise.
*   */
查看更多
登录 后发表回答