5
\$\begingroup\$

In my code's package, I have a flag such as:

public static final boolean LOGS_VERBOSE = false;

And in worker classes (multi threaded Runnable jobs), I have code like:

if(XYConstants.LOGS_VERBOSE){
    logger.debug("some state info var 1:" + var1 + ", var 2:" + var2);

Is this a good idea? Is there any performance gain? Developers say it avoids code going to the log4j level completely, and there is hardly any overhead to check the value of the constant.

We do plan to do performance testing, but that is a month away, and I need to show code to the client (who is a developer of 14 years) this Friday. I'm wondering if this should stay or not?

We have some debugs without the boolean check too, and those are wanted in all runs as long as log4j is configured in debug level.

This code is using log4j 1.2.16.

\$\endgroup\$
  • \$\begingroup\$ Any particular reason why trace() is not used, considering there are some debug messages that should always be shown (proper debugging?), and there are those with this boolean check (really verbose)? Also, is your team keen to explore switching to an alternative such as SLF4J that can handle these logging more fluently? You get parameterized log messages too. \$\endgroup\$ – h.j.k. Dec 3 '13 at 3:59
  • \$\begingroup\$ we are in fact using SLF4J (with log4j as the implementor, did not disclose that fact as I thought not pertinent to the questionb). Can use trace but I think we need to upgrade to the next version of SLF4j which has var args \$\endgroup\$ – tgkprog Dec 3 '13 at 14:00
6
\$\begingroup\$

This type of practice is common, and works well.

The Java JIT compiler will identify the LOGS_VERBOSE as being a constant, and will know that it is always false, and thus will compile-out the logging entirely.

There is a slight performance hit on any code that has not (yet) been compiled.... but, once the compile has happened, there is no hit at all.

It is relatively common to use a System property to determine whether to log...

public static final boolean LOGS_VERBOSE = Boolean.getBoolean("LOGS_VERBOSE");

This behaves in the exact same way (because JIT happens after the property is set)... but, if you start your program as:

java -DLOGS_VERBOSE=true ......

then suddenly you have the fully-featured logging.

In many cases this sort of checking can improve performance because it can eliminate expensive 'setup' for log messages

\$\endgroup\$
  • \$\begingroup\$ thank you will add System.getProperty("LOGS_VERBOSE"), with our own utility function to check if true (we accept Y or "1" or "T" == "true"). will keep question open for 2 days to see if anyone else has opinions they want to share. \$\endgroup\$ – tgkprog Dec 2 '13 at 13:19
  • 2
    \$\begingroup\$ How about static final boolean LOGS_VERBOSE = Boolean.getBoolean("LOGS_VERBOSE"); \$\endgroup\$ – Peter Lawrey Dec 5 '13 at 17:46
  • 1
    \$\begingroup\$ @PeterLawrey +1 You know, every now than then I learn something new.... How is it that I have not seen that before? \$\endgroup\$ – rolfl Dec 5 '13 at 17:52
  • \$\begingroup\$ @rolfl Sometimes I use int property = Integer.getInteger("property", 100); instead of int property = 100; so I can optionally change it externally. \$\endgroup\$ – Peter Lawrey Dec 5 '13 at 17:54
3
\$\begingroup\$

You want to no only check you flag but the loggers log level.

if(XYConstants.LOGS_VERBOSE && logger.isDebugEnabled())
    logger.debug("some state info var 1:" + var1 + ", var 2:" + var2);

This prevents you computing a potentially expensive String which will only be discarded anyway. More typically you would just use the debug level of the logger as there is not point turning it on if the logger doesn't print it.

if(logger.isDebugEnabled())
    logger.debug("some state info var 1:" + var1 + ", var 2:" + var2);

The log level can then be controlled by the log4j.properties file.

Most likely your Logger is a static final field, not a field which is different for every instance. In this case you can UPPER_CASE for constants

// Constants are in UPPER_CASE by convention.
private static final Logger LOGGER = Logger.getLogger(MyClass.class);

if(LOGGER.isDebugEnabled())
    LOGGER.debug("some state info var 1:" + var1 + ", var 2:" + var2);
\$\endgroup\$
1
\$\begingroup\$

A few things which were not mentioned earlier:

Is this a good idea?

It has some drawbacks:

  • You have to recompile the code to change the log settings and usually you need to restart the whole application. It could make debugging a lot harder.
  • Having one or two of these could be OK (if you have a really good reason for that, don't do premature optimizations) but it is still increases maintenance costs. It's much easier to configure logging in the usual log4j.xml (or logback.xml for Logback nowadays) than recompiling and redeploying the application. You could even change logging configuration at runtime and Log4j will reconfigure itself.
  • Note that Java inlines these constants, so you need to recompile both XYConstants and Runnables.

Other ideas:

  1. Use logger.isDebugEnabled() (as it was mentioned earlier).
  2. Use SLF4J and its {} pattern instead of string concatenation:

    logger.debug("some state info var 1: {}, var 2: {}", var1, var2);
    

    SLF4J don't call var1.toString() nor var2.toString() and don't do any string concatenation if the debug log level is not enabled.

  3. You could create a custom logger to be able to log only a subset of your log statements:

    private static final Logger logger = 
        LoggerFactory.getLogger(Foo.class.getName() + ".subset");
    

    or

    private static final Logger logger = 
        Logger.getLogger(Foo.class.getName() + ".subset");
    

    Then you can configure Log4j in the usual way although you don't have ...Foo.subset package nor class.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.