log4j 1.2 - own check for verbose logs?

Question

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.

Answer 1

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

Answer 2

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);

Answer 3

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.