What is the fastest way of (not) logging?

SLF4J FAQ

What is the fastest way of (not) logging?

SLF4J supports an advanced feature called parameterized
logging which can significantly boost logging performance for
disabled logging statement.

For some Logger logger, writing,

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

incurs the cost of constructing the message parameter, that
is converting both integer i and
entry[i] to a String, and concatenating
intermediate strings. This, regardless of whether the message
will be logged or not.

One possible way to avoid the cost of parameter
construction is by surrounding the log statement with a
test. Here is an example.

if(logger.isDebugEnabled()) {
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

This way you will not incur the cost of parameter
construction if debugging is disabled for
logger. On the other hand, if the logger is
enabled for the DEBUG level, you will incur the cost of
evaluating whether the logger is enabled or not, twice: once in
debugEnabled and once in debug. This
is an insignificant overhead because evaluating a logger takes
less than 1% of the time it takes to actually log a statement.

Better yet, use parameterized messages

There exists a very convenient alternative based on message
formats. Assuming entry is an object, you can write:

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

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.

The following two lines will yield the exact same
output. However, the second form will outperform the first
form by a factor of at least 30, in case of a
disabled logging statement.

logger.debug("The new entry is "+entry+".");
logger.debug("The new entry is {}.", entry);

A two argument variant is also available. For example, you
can write:

logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry);

If three or more arguments need to be passed, you can make
use of the Object[] variant. For example, you can
write:

logger.debug("Value {} was inserted between {} and {}.", new Object[] {newVal, below, above});

Array type arguments, including multi-dimensional arrays,
are also supported.

SLF4J uses its own message formatting implementation which
differs from that of the Java platform. This is justified by
the fact that SLF4J's implementation performs about 10 times
faster but at the cost of being non-standard and less
flexible.

Escaping the "{}" pair

The "{}" pair is called the formatting anchor. It
serves to designate the location where arguments need to be
substituted within the message pattern.

SLF4J only cares about the formatting anchor, that
is the '{' character immediately followed by '}'. Thus, in
case your message contains the '{' or the '}' character, you
do not have to do anything special unless the '}' character
immediately follows '}'. For example,

logger.debug("Set {1,2} differs from {}", "3");

which will print as "Set {1,2} differs from 3".

You could have even written,

logger.debug("Set {1,2} differs from {{}}", "3");

which would have printed as "Set {1,2} differs from {3}".

In the extremely rare case where the the "{}" pair occurs
naturally within your text and you wish to disable the special
meaning of the formatting anchor, then you need to escape the
'{' character with '\', that is the backslash character. Only
the '{' character should be escaped. There is no need to
escape the '}' character. For example,

logger.debug("Set \\{} differs from {}", "3");

will print as "Set {} differs from 3". Note that within
Java code, the backslash cracacter needs to be written as
'\\'.

In the rare case where the "\{}" occurs naturally in the
message, you can double escape the formatting anchor so that
it retains its original meaning. For example,

logger.debug("File name is C:\\\\{}.", "file.zip");

will print as "File name is C:\file.zip".

---

How can
I log the string contents of a single (possibly complex)
object?

In relatively rare cases where the message to be logged
is the string form of an object, then the parameterized
printing method of the appropriate level can be
used. Assuming complexObject is an object of
certain complexity, for a log statement of level DEBUG, you
can write:

logger.debug("{}", complexObject);

The logging system will invoke
complexObject.toString() method only after it
has ascertained that the log statement was
enabled. Otherwise, the cost of
complexObject.toString() conversion will be
advantageously avoided.

---

Why doesn't the
org.slf4j.Logger interface have methods for the
FATAL level?

The Marker
interface, part of the org.slf4j package, renders
the FATAL level largely redundant. If a given error requires
attention beyond that allocated for ordinary errors, simply mark
the logging statement with a specially designated marker which
can be named "FATAL" or any other name to your liking.

Here is an example,

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

class Bar {
  void foo() {
    Marker fatal = MarkerFactory.getMarker("FATAL");
    Logger logger = LoggerFactory.getLogger("aLogger");

    try {
      ... obtain a JDBC connection
    } catch (JDBException e) {
      logger.error(fatal, "Failed to obtain JDBC connection", e);
    }
  }
}

While markers are part of the SLF4J API, only logback
supports markers off the shelf. For example, if you add the
%marker conversion word to its pattern, logback's
PatternLayout will add marker data to its
output. Marker data can be used to filter
messages or even trigger
an outgoing email at
the end of an individual transaction.

In combination with logging frameworks such as log4j and
java.util.logging which do not support markers, marker data will
be silently ignored.

Markers add a new dimension with infinite possible values for
processing log statements compared to five values, namely ERROR,
WARN, INFO, DEBUG and TRACE, allowed by levels. At present time,
only logback supports marker data. However, nothing prevents
other logging frameworks from making use of marker data.

---

Why was the TRACE level introduced only in
SLF4J version 1.4.0?

The addition of the TRACE level has been frequently and
hotly debated request. By studying various projects, we
observed that the TRACE level was used to disable logging
output from certain classes without needing to
configure logging for those classes. Indeed, the TRACE level
is by default disabled in log4j and logback as well most other
logging systems. The same result can be achieved by adding the
appropriate directives in configuration files.

Thus, in many of cases the TRACE level carried the same
semantic meaning as DEBUG. In such cases, the TRACE level
merely saves a few configuration directives. In other, more
interesting occasions, where TRACE carries a different meaning
than DEBUG, Marker
objects can be put to use to convey the desired
meaning. However, if you can't be bothered with markers and
wish to use a logging level lower than DEBUG, the TRACE level
can get the job done.

Note that while the cost of evaluating a disabled log
request is in the order of a few nanoseconds, the
use of the TRACE level (or any other level for that matter) is
discouraged in tight loops where the log request might be
evaluated millions of times. If the log request is enabled,
then it will overwhelm the target destination with massive
output. If the request is disabled, it will waste resources.

In short, although we still discourage the use of the TRACE
level because alternatives exist or because in many cases log
requests of level TRACE are wasteful, given that people kept
asking for it, we decided to bow to popular demand.

---