Java logger using ... function

Question

Java logger allows the following syntax:

m_logger.info("ID: {} NAME: {}", id, name);    // 1
m_logger.info("ID: " + id + " NAME: " + name); // 2

In the first case, essentially we are calling the ... function and thus a new Object[] is created every time.

I ran through YourKit and that's what I see.

My question is that isn't the 1st case an expensive operation that we should be avoiding all the time? But yet I have seen this in a lot of codes. What are we gaining by using #1?

And I suppose we should use StringBuilder for best performance?

Andrew Tobilko · Answer 1 · 2018-02-07T12:09:23.390

5

m_logger.info("ID: {} NAME: {}", id, name);

It's lazy argument evaluation. If the INFO logging level is turned off, the string won't be processed. Actually, it's not a big deal to construct a new Object[n], n usually (=normally) is < 5.

m_logger.info("ID: " + id + " NAME: " + name);

This string will be constructed every time.

edited Feb 07 '18 at 12:09

answered Feb 07 '18 at 12:02

Andrew Tobilko

48,120
14
91
142

score 2 · Answer 2 · answered Feb 07 '18 at 12:00

My question is that isn't the 1st case an expensive operation that we should be avoiding all the time?

No, especially in the grand scheme of a program execution

What are we gaining by using #1?f

Readability, sometimes the first approach is easier to read as code. The resulting log lines are the same

And I suppose we should use StringBuilder for best performance?

No: https://stackoverflow.com/a/1532499/32090

score 2 · Answer 3 · answered Feb 07 '18 at 12:02

You are right about a new Object[] array being created for the call #1. However, there is a new StringBuilder object created for #2^*, and then toString() is called on both id and name (which is probably a String to begin with, but that's not the point).

Although similar formatting happens inside m_logger.info in #1, it may or may not be done, depending on the settings of your logger.

Therefore, as far as performance is concerned, one needs to compare a creation of Object[] plus optional formatting driven by the settings vs. eager formatting inside the call. Since one should not assume that formatting is on for all levels all the time, and because creating Object[] is relatively inexpensive, the #1 is often preferable.

^* You don't need to create StringBuilder explicitly, the compiler will do it for you. See this Q&A for an answer on how Java deals with string concatenation internally.

score 2 · Answer 4 · answered Feb 07 '18 at 12:06

There are several things hiding behind this decision.

Argument evaluation.

In first case string will not be interpolated (i.e. calculated) if info logging level is not enabled (for example only ERROR is enabled). In your second case this string will be calculated every time your program reaches this statement, which may lead to unexpected performance impacts caused by logging. As noted correctly above adding StringBuilder will not help you as compiler will do it for you.

Execution flow. Look into source code of logger (log4j 2.7)

@Override
public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message,
    final Object p0, final Object p1) {
    if (isEnabled(level, marker, message, p0, p1)) {
      logMessage(fqcn, level, marker, message, p0, p1);
  }
}

It checks in if clause that corresponding mode is enabled. Once Java will evaluate this flow once it will become faster utilizing branch prediction optimization.

score 0 · Answer 5 · answered Feb 07 '18 at 12:02

0

It is for user perspective as per my knowledge.

Some Developers may practice Case #1.
Some Developers may practice Case #2.

And that is a main characteristic of Java. Same thing in many ways.

answered Feb 07 '18 at 12:02

Prathibha Chiranthana

822
1
10
28

Java logger using ... function

5 Answers5