Is there a need to do a if(log.isDebugEnabled()) { ... } check? [duplicate]

This question already has answers here: In log4j, does checking isDebugEnabled before logging improve performance? (16 answers) 开发者_Go百科 Closed 6 years ago.

is there a need to do an explicit if(log.isDebugEnabled()) { ... } check?

I mean i have seen some post mentioning that log.debug("something") does an implicit call to see if debug mode logging has been enabled, before it does the logging. Am i missing something or is there an intermediary step that is to be performed before this is used?

Thanks!

log.debug("ResultSet rs is retrieved from OracleTypes");

vs

if(log.isDebugEnabled()){
     log.debug("ResultSet rs is retrieved from OracleTypes");
}

Edit: Did a write up on this: http://java.sg/whether-to-do-a-isdebugenabled-checking-before-printing-out-your-log-statement/

---

The statement:

if(log.isDebugEnabled()){

Is used just for performance reasons. It's use is optional since it is called by the log method internally.

But now you ask if this check is made internally, so why should I use it? It's very simple: if you log something as simple as this:

log.debug("ResultSet rs is retrieved from OracleTypes");

Then you don't need to do any check. If you compose a string to log using the append operator (+) like this:

log.debug("[" + System.getTimeInMillis() + "] ResultSet rs is retrieved from OracleTypes");

In this case you should check if the log is enabled or not, because if it isn't, even if the log is not made, the string composition is. And I must remind you that the use of operator "+" to concatenate strings is very inefficient.

---

I know this is old, but for anyone just finding this...

If you use SLF4J, you can avoid the isDebugEnabled() call, by using messaging formatting.

For example, instead of:

Object entry = new SomeObject();
logger.debug("The entry is " + entry + ".");

Use:

Object entry = new SomeObject();
logger.debug("The entry is {}.", entry);

The message formatting will not be evaluated unless debug is enabled.

So, for simple cases, you could avoid isDebugEnabled().

But in a case where building one of the parameters might be expensive, you would still want to use isDebugEnabled() (even with SLF4J).

For example:

if (logger.isDebugEnabled()) {
    logger.debug("Here is the SQL: {}", sqlWrapper.buildSQL());  // assume buildSQL() is an expensive operation
}

In that case, you don't want to evaluate buildSQL() unless debug is actually enabled.

With SLF4J, there's some debate over using it always vs using it selectively. It really boils down to personal preference. You may want to use everywhere, to guard against another developer (unknowingly) changing your log message to something more complex/expensive in the future.

---

The recent versions of Logger streamline this, so there's not much difference.

The biggest difference is you don't have to create the stuff to log - sometimes there's a lot of string addition going on.

---

I checked with the below code by performing the check in my code vs not performing the check. Interestingly if the check is performed in our code for a 4 log statement executed a million times it takes 400 ms extra. I am using SLF4J 1.6.6. If you can afford to loose 400 ms per million request ,you don't need the check.

    long startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000000; i++) {
        if (logger.isTraceEnabled()) {
            logger.trace(request.getUserID());
            logger.trace(request.getEntitlementResource().getResourceString());
            logger.trace(request.getEntitlementResource().getActionString());
            logger.trace(request.getContextMap());
        }
    }
    long endTime = System.currentTimeMillis();
    logger.fatal("With Check Enabled : " + (endTime - startTime) + " ms");

    startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000000; i++) {

        logger.trace(request.getUserID());
        logger.trace(request.getEntitlementResource().getResourceString());
        logger.trace(request.getEntitlementResource().getActionString());
        logger.trace(request.getContextMap());

    }
    endTime = System.currentTimeMillis();
    logger.fatal("With Check Disabled : " + (endTime - startTime)  + " ms");

---OUTPUT---

*2016-01-07 10:49:11,501 ERROR [:http-bio-8080-exec-3] [com.citi.cmb.entitlement.service.EntitlementServiceImpl][]- With Check Enabled : 661 ms

2016-01-07 10:49:57,141 ERROR [:http-bio-8080-exec-3] [com.citi.cmb.entitlement.service.EntitlementServiceImpl][]- With Check Disabled : 1043 ms

---

The reason this is done is for performance reasons. If checking this first, the log.debug(... statement shouldn't be evaluated.

It is indeed functionally the same.