日志带参输出 The Art of Logging: Advanced message formatting

The Art of Logging: Advanced message formatting

https://garygregory.wordpress.com/tag/org-apache-logging-log4j-logger/

In this post, I’ll show you how to format your Log4j logging message like a pro.

Let’s start with a bland and inefficient logging statement:

1

logger.debug("There are " + getUserCount() + " users logged in now.");

This is lame for three reasons:

1. You are always building the full string before calling debug()
2. You are always calling getUserCount()
3. Both of the above happens even if debug logging is disabled!

In the old days of logging, you avoided these problems with more code like this:

1

2

3

if(logger.isDebugEnabled()) {

  logger.debug("There are " + getUserCount() + " users logged in now.");

}

This is quite verbose and unnecessary if you are using Log4j 2. Instead, use this:

1

logger.debug("There are {} users logged in now.", getUserCount());

We’ve removed one level of lameness: the final string is only built when debug logging is enabled. The complete message only gets built when debug logging is enabled: the “{}” parameter marker is replaced by the value returned by getUserCount(). The getUserCount() method is still called whenever the debug() method is called. That part is still Lame.

As I point out in this post, Log4j 2.4 and Java 8 come to the rescue with lambdas to clean this up as follows:

1

logger.debug("There are {} users logged in now.", () ->; getUserCount());

All lameness is now removed:

• The getUserCount() function is only called when debug logging is enabled. This happens because the expression “() -> getUserCount()” does not call the getUserCount() method before debug() is called. Instead, Java creates a block of code that Log4j executes later, if it needs the result.
• The complete message is only built with the result of getUserCount() when debug logging is enabled.

The only possible drawback is that the getUserCount() function is called a little later in the code path which could be an issue if the method relies on precise and exact timing or position on the stack, that would be unusual but possible.

Next up is the actual format of the message.

Using “{}” parameter markers causes Log4j to call toString() on each argument you pass to logger methods like debug().

This is ugly when it comes to printing large numbers for example:

1

There are 2147483647 users logged in now.

Instead, I want something that looks civilized like this:

1

There are 2,147,483,647 users logged in now.

You can do this using a different kind of logger and a format string:

1

2

Logger logger = LogManager.getFormatterLogger();

logger.debug("There are %,d users logged in now.", () -> getUserCount());

A formatter logger let’s you use patterns like “%,d” and all the power of the stock Javajava.util.Formatter class.

You can format numbers like this as well:

1

logger.debug("Gain or loss: $ %(,.2f", delta);

Gives you:

1

Gain or loss: $ (12,582.19)

You can get extra fancy with dates:

1

2

Calendar c = newGregorianCalendar(1918, MAY, 11);

logger.info("Richard Feynman's Birthday: %1$tb %1$te, %1$tY", c);

Gives you:

1

Richard Feynman's: May 11, 1918

Super powerful, super nice.

The only caveat is that you will not get the same performance out of a formatter logger as you would out of the default logger. Still, pretty neat.