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

Question

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/

Out of curiosity: is there a reason that you didn't post that write up as an answer? That would be the most preferred way on SO. — Joachim Sauer, Oct 12 '11 at 11:26

score 91 · Accepted Answer · answered Jun 28 '11 at 10:13

91

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.

answered Jun 28 '11 at 10:13

Filipe Palrinhas

1,235
8
9

+1 on mentioning that the work would have already been done on what is to be debugged, before it later checked if the log statement is required to be printed at all, would i have paraphrased it correctly? – Oh Chin Boon Jun 28 '11 at 10:16
5

String concatenation internally creates a lot of temporary objects. If you have many log statements like this, even if the logs are disabled you loose performance. – Filipe Palrinhas Jun 28 '11 at 10:28
Depends on the string - if the strings are not dynamically created there is a good chance they are cached in the string pool. Anyway, I would do it as you suggested myself - it is very unlikely to always log the same strings. – Christian Jun 29 '11 at 09:25
Since we're adding a branch, I wondering whether branch mis-prediction/speculative execution can hurt us here, in particular when the value we add to the String is similarly likely to be cached (an Object id, for example) as is log.isDebugEnabled() - in this case the addition might be started anyway, and the fetch is relatively inexpensive. – Rick Moritz Jan 14 '19 at 10:25
Nice anwer, I just give my 5c opinion: Unless performance reason is really critical (thus you should ask to yourself why you are using Java) my opinion is to AVOID the check, because it creates a lot of code noise. Often readability score pay much more than some ms of performance – Fabrizio Stellato Feb 25 '21 at 10:28

score 56 · Answer 2 · answered Apr 10 '15 at 12:08

56

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.

answered Apr 10 '15 at 12:08

yngwietiger

1,044
1
11
15

You point a very good example, where, on the sake of optimization, the check operation (isDebugEnabled) comes in handy. Other think that also cames to my mind if you wanna make sure that debug messages doesn't log independently of the `logger.debug` method internal implementation... i mean, nowadays... you guys says that this method checks internally that the debug is enabled (the javadoc of the Logger class says so too)... but what happens if (it shouldn't happen) the implementors of the logger change the contract (a knife from the back) even it that case your logs won't log that information – Victor Aug 05 '15 at 15:06
I don't think this statement is true *But in a case where building one of the parameters might be expensive, you would still want to use isDebugEnabled() (even with SLF4J).* Then there is no point in using `{}` – ACV Apr 09 '19 at 11:52
1

In fact you are wrong. This is from SLF4J: `After evaluating whether to log or not, and only if the decision is affirmative, will the logger implementation format the message and replace the '{}' pair with the string value of entry. In other words, this form does not incur the cost of parameter construction in case the log statement is disabled.` – ACV Apr 09 '19 at 11:54
@ACV I see what the documentation says, but.... Test it out, and get back to me. Try something like LOGGER.trace("hello: {}", test()); and see if test() gets invoked even when trace is disabled. (Hint: it does). I just tested it. BTW, I'm using version 1.7.25, which is from March 2017, but it behaves the same with the latest beta versions. – yngwietiger Apr 09 '19 at 12:26
@yngwietiger hmm.. That's interesting. Let me try – ACV Apr 09 '19 at 14:51
2

@yngwietiger you are right! The method still gets called: `logger.debug("Hello World {}", test());` will call `test()` regardless of logger level – ACV Apr 09 '19 at 15:08
3

@yngwietiger oh wait, the scenario you outline - to call a method in the logging message is not really a normal scenario. Yes the method will be called, but objects will not have their toString() evaluated. That is in line with what the documentation says: `logger.debug("Hello World {}", test());` test will be called, but `logger.debug("Hello World {}", test);` where `test` is an object will not have its `toString()` called. So, yeah – ACV Apr 09 '19 at 15:20
I'll vote up later as SO won't allow to vote so often – ACV Apr 09 '19 at 15:21
@ACV So, in other words, everything in my original post is correct. The scenario that I outline (method call) in my original post is exactly the example that you said I was "wrong" about earlier. As for the need for "{}", I explain that in my original post as well. It's about message formatting. And I never said Object.toString() would be called if not guarded by isDebugEnabled(). – yngwietiger Apr 10 '19 at 10:41
@yngwietiger yes. You were right, but just to clarify that `toString` doesn't get evaluated – ACV Apr 16 '19 at 11:05
@yngwietiger, this info helped me, thanks - in **Logback** parametrization works in a [such](https://stackoverflow.com/questions/59737916/should-we-use-isdebugenabled-while-logging-calculated-data-with-logback) way, too – Dan Brandt Jan 14 '20 at 16:45

score 8 · Answer 3 · answered Jan 07 '16 at 16:04

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

In first block `isTraceEnabled` is checked only once for 4 statements, in reality this wont be the case, for every statement `isTraceEnabled` will be checked. Would be great if you can post results with this change. — Kartikey, Jan 16 '17 at 11:30
It's better to compare string concat, as we do not know how `request` works. — Leon, Jul 19 '18 at 02:57

score 8 · Answer 4 · answered Jun 28 '11 at 09:35

8

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.

answered Jun 28 '11 at 09:35

Bohemian

412,405
93
575
722

Would you happen to know from what version onward does the Logger start to streamline this? – Oh Chin Boon Jun 28 '11 at 09:45
I guess the problem here is not how loggers print it, But before even logger.debug goes and checks if that needs to be printed, the expressions(arguments) in side the logger.debug method gets evaluated. That's some computation whether or not debug is enabled. I dont think a logging framework could stop that from happening. @yngwietiger explains it well – Raja Anbazhagan May 02 '18 at 07:11
@raja if you check first, the expression to log is not evaluated. A better approach is to pass a supplier to a method that logs, which allows deferred calculation on demand. – Bohemian May 02 '18 at 07:14
Any specific version or flavour of logging framework that you could recommend? – Raja Anbazhagan May 02 '18 at 07:15
@raja not really. Logging in java still has no clear winner. I tend to use whatever comes bundled with the container/platform. – Bohemian May 02 '18 at 07:18

score 2 · Answer 5 · answered Jun 28 '11 at 09:34

2

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.

answered Jun 28 '11 at 09:34

wjans

10,009
5
32
43

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

5 Answers5

Linked

Related