paramconcat

Parameters, concatenations or both; which logging method should you use?

A log is a log is a log. Some of us use dedicated log tools to monitor it, while others prefer going through the raw log lines with their very own eyes. It doesn’t matter how we consume it – it’s an inseparable part of our development cycle.

There are a lot of methods in which we can write to our logs, when endless debates, opinions and arguments surround the logging world. In the following post we’ve decided to focus on one of those topics – and understand which method is better: String concatenation or parameterized Logging. How do most developers write variables to their logs? Let’s find out.

Adding Up the Numbers

In our previous post we tried to understand why production logs can’t help us find the real cause of errors and exceptions. Our research returned a lot of data, and we could see a pattern regarding the use of String concatenation and parameterized logging. That lead us to the following question:

How do most developers write to their logs – String concatenation, parameterized logging or both?

We took the top 400,000 Java repositories on GitHub, sliced and diced them to get those with over 100 logging statements. Then, we removed unrelated projects and ended up with 1,461 repositories. Now, let’s see which option is the most popular among developers on GitHub.

And the Winner Is…

Use of each method across all statements
Use of each method across all statements

Well well well, what do we have here? The biggest winner is the use of no method at all. Or in other words, it seems that over 50% of statements don’t contain variables. The runner up is parameterized logging, with an appearance in a little over 30% of statements.

Now, let’s take a deeper look at the use of these methods across repositories:

Use of each method across repositories
Use of each method across repositories

Parameterized logging takes the cake (or the pie chart in this case), but it’s a small win. We can see that over 46% of repositories use a mix between the parameterized and the concatenation methods. This means that too many developers didn’t choose one method and ended up using both in the same project.

Now that we know who the clear winner is, it’s time to understand how it got the crown.

Strings or Parameters?

First thing’s first – why do we even need these methods?

When it comes to our log file, we often find ourselves wanting to merge or combine different strings and variables into a single log message. Doing so makes it easier to monitor and understand what happened when the application encounters an error or throws an exception. The 2 methods we’ve checked in this post are:

  • String concatenation – Adding parameters via the “+” operator
  • Parameterized logging – In which we use the {} variant, also known as curly brackets, braces or formatting anchor

Now that we know how they’re actually used, let’s take a deeper look and see what are the main differences between the two:

String Concatenation

String concatenation lets us add variables using the “+” operator, as you can see in the following example:

It can get a little messy, not only due to how the code looks but also since the variables are converted to strings, regardless of whether the message will be logged or not. In other words, they are evaluated immediately in every log level, even if we’re not using it, which in return might affect the overhead of the application.

For example, if we use String concatenation for DEBUG level while running in production, the variables will still convert to strings, even though DEBUG level statements are not logged.

There are ways in which we can overcome this issue, such as using the logger.isDebugEnabled() function. As you can guess, this function checks whether debug is enabled before formatting the message. This can prevent String concatenation from happening when it’s not necessary, reducing the overhead, but in return it will make the code look like this:

Now think how long your code will be if you use this function with hundreds of log messages. Yikes.

Parameterized Logging

When using parameterized logging, the variables are added with the {} variant:

This method helps clean up the code, but what’s even better is that the parameters are evaluated only if the statement is needed. Using this messaging format eliminates the need to call isDebugEnabled(), since the variables won’t convert unless they’re called.

Going back to our DEBUG log level example, it means that when we run our application in production the variables included in the DEBUG log message will not be converted to string, making this method much more efficient than String concatenation.

Diving into the Log Level

Going back to our data crunch, now that we know which method might be better for low production overhead, we’ve decided to see if it affects the choice of which one to choose per log level.

We know that the amount of variables sent to the log is pretty low, and the average number runs between 0.8 variables for an average DEBUG level message, and 0.4 variables for ERROR. So while we’re at it, we’ve decided to see which percentage of statements are sent in each method to each log level.

Average use of each method per log level in GitHub’s top Java projects
Average use of each method per log level in GitHub’s top Java projects

Many developers use String concatenations in their local environment (TRACE, DEBUG, INFO), with 33% statements for concatenations in TRACE and 22% statements in DEBUG level. Parameterized logging is the popular choice in INFO log level, with 37% of statements. The clear pattern here is that as we move towards production, the use of either method goes down.

Or in other words, developers don’t send out enough variables when it comes to their production environment. It doesn’t mean they don’t use their logs, since they might use Strings to monitor what’s going on – but wouldn’t you want to know more about when and why your code broke?

Keeping Track of the Logs

Searching through your log files for certain strings might feel like… searching for a needle in a log file. If you find yourself waste hours or even days trying to debug using your logs, you’d be happy to know that there’s a better way.

OverOps tells you when, where and why you code breaks in production. It lets you see the variables behind any exception, logged error or warning, without relying on the information that was actually logged.

It gives you the complete source code and variable state across the entire call stack for each event, error or exception – Even if it wasn’t printed to the log file. OverOps also shows you the last 250 DEBUG, TRACE and INFO level statements that were logged prior to the error, in production, even if they’re turned off and never reach the log file.

Make your logs better. Click here to schedule a demo.

OverOps

Final Thoughts

As we’ve said before, there isn’t a right (or wrong) way to write to your log files, but there are methods you should apply if you want to get the most out of it. The most important thing is that you’ll keep track of what’s going on in your code so you’ll be able to understand it. If not for your teammates, then for your future self that won’t have to deal with riddles just to solve a bug.

email
I write about Java, Scala and everything in between. Lover of gadgets, apps, technology and tea.
  • Ktoś

    `logger.debug(“This {} and {} with {}”, this, that, compute());`
    this doesn’t look like a correct Java (JUL, jslf4j?); not to mention that parametrized statement has a bit different syntax; also – could you point to the source stating, that parametrized logging is not evaluated when not needed?

    • Rob Radina

      Regardless of logging framework or correct Java syntax, here’s the the premise of using parameterized calls vs. String concatenation. A parameterized call will push four references on the stack and call the debug() method. The debug method will first check the log level. If it’s not debug, it will immediately return and reset the stack pointer. A very quick call with no garbage collection. A string concatenation call will likely create a StringBuilder, perform the concatenation, toString() the StringBuilder, push that reference on the stack, call the debug() method and then return and reset the stack pointer. In addition to all the wasted String concatenation work, two references will also need to be garbage collected. If you have hundreds of log.debug statements, your production code will be doing all this work, all the time. If it’s a public-facing web services, that means thousands or perhaps millions of calls all creating dozens (hundreds) of wasted StringBuilders and Strings. That’s a lot of production garbage collection that could be avoided by simply using parameterized debug statements.

      As the article mentions, the alternative is to surround each log.debug() with an if (isDebugEnabled) statements.

      • Mickey P

        very eloquently put

        • divp

          Thanks for sharing….good one

    • http://www.takipi.com/ Alex Zhitnitsky

      Thanks for the answer Rob! Hi Ktoś, thanks for the comment. You can refer to the slf4j FAQ about logging performance for an elaborate answer: https://www.slf4j.org/faq.html#logging_performance
      There’s a section called “What is the fastest way of (not) logging?”

      • Ktoś

        I get the idea, but the article suggests that it applies to all logging systems/frameworks but the first example of the top of my head – JUL, even parametriezed, will cause evaluation of parameters without guard so .isLoggable() is still a must (granted, using parameters instead of concat is always better but article assumes everyone on the planet uses slf4j 😉 )

  • Constantin Ungureanu

    Nice article.
    Parameterized logging instead of string concatenation is the way to go.
    Additionally should be accompanied with lambda expressions, for example instead of
    logger.debug(“This {} and {} with {} “, this, that, compute());
    use
    logger.debug(“This {} and {} with {} “, this, that, () -> compute());
    Since the debug level probably will not be activated in production, the evaluation of the compute() method is not done, that is desired.