No line left behind — log level vs. code coverage in Java

Saving resources with level-aware log message creation

If you’re using loggers that support lambda expressions in log messages such as java.util.logging, you’re rewarded with performance gains if you don’t need to log at the highest level.

To understand this, remember that the typical log level set in production environments is INFO. Done correctly, log messages on that level and beyond are pretty rare. More detailed log levels, though, tend to produce a lot of output.

With the advent of Loading...Java 8, the logger class got new instance methods that take lambda expressions as message suppliers.

Everything in such a lambda expression is only evaluated, if that, at log level — or a more detailed one set by the user.

This example shows a method from Exasol’s Virtual Schema.

protected void logTablesScan(final String catalogName, final String schemaName) {    LOGGER.fine(() -> {        final StringBuilder builder = new StringBuilder("Scanning \"");        if (catalogName == null) {            builder.append("any catalog, ");        } else {            builder.append("catalog \"");            builder.append(catalogName);            builder.append("\", ");        }        if (schemaName == null) {            builder.append("any schema ");        } else {            builder.append("schema \"");            builder.append(schemaName);            builder.append("\" ");        }        builder.append("for contained tables.");        return builder.toString();    });}

There’s a fair bit of String construction going on. It’s obvious that you don’t want to spend central processing unit (CPU) time on this code unless logging is cranked up to level fine or beyond.

The impact on code coverage

Unfortunately, this performance optimization negatively impacts measuring code coverage. Unless you do something about it.

Let’s look at the following screenshot. It shows that the whole code in the body of the lambda expression is skipped (marked in red) in the test on the default log level. And that’s what it’s supposed to do.

Funnily enough, the solution to the coverage dilemma boils down to what you tried to avoid in the first place: activate all log messages. Remember, we’re talking about a coverage check here, so completeness is more important than performance.

Take a look at these two coverage results. The first Coverage column is calculated with log messages set to the default level INFO, the second one to the most detailed level.

While the total coverage only goes up by 1% in this example, in some files with heavy use of lower level log messages the difference is more pronounced.

Take a look at com.exasol.adapter.dialects.generic. Coverage goes up from 77.6% to 97.1%. This improvement is really worth it.

Raising the log level in Maven for JaCoCo tests

Now that we know the positive impact a higher log level can have in a coverage check, let’s talk about how to use it to our advantage.

The following example is an excerpt from a Maven configuration file (pom.xml).

<build>  <plugins>    <plugin>      <groupId>org.apache.maven.plugins</groupId>      <artifactId>maven-surefire-plugin</artifactId>      <version>${surefire.and.failsafe.plugin.version}</version>      <configuration>        <argLine>-Djava.util.logging.config.file=src/test/resources/logging.properties ${argLine}</argLine>      </configuration>    </plugin>    <plugin>      <groupId>org.jacoco</groupId>      <artifactId>jacoco-maven-plugin</artifactId>      <version>0.8.3</version>      <!-- ... -->

We use the JaCoCo Maven plug-in to measure code coverage.

In the section that configures the Surefire plug-in, we chose a specific logging configuration file.

handlers=java.util.logging.ConsoleHandler, java.util.logging.FileHandler.level=INFOjava.util.logging.ConsoleHandler.level=ALLjava.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatterjava.util.logging.FileHandler.level = ALLjava.util.logging.FileHandler.pattern=/home/johndoe/logs/virtual_schema.logjava.util.logging.FileHandler.limit=50000java.util.logging.FileHandler.count=1java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatterjava.util.logging.SimpleFormatter.format=%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$-7s [%3$s] %5$s %6$s%ncom.exasol.level=ALL

There is a lot in this file, so let’s unpick things bit by bit.

In line 1 we configure the log output handlers so that the output is displayed on console and additionally written to a log file. The latter is useful in continuous builds.

The default log level is set to INFO in line 2. We selectively raise this to level ALL for the packages we want to test in the last line.

The SimpleFormatter mentioned in lines 4 and 10 is produces configurable log output in a format defined in line 12.

Line 7 tells the FileHandler where to put the log file, line 8 limits the size to 50,000 characters and line 9 keeps only the last log file.

Raising the log level in Eclipse

If you not only want to measure coverage but also plan to improve it, it’s a good idea to work coverage checking into the integrated development environment (IDE) of your choice. As shown in the coverage results screenshots earlier, you get a navigable list of files including their coverage results. From there it’s easy to check which lines aren’t yet covered and write new tests.

This example of Coverage Configurations uses the same log setup discussed in the previous section.

We added -Djava.util.logging.config.file=src/test/resources/logging.properties to the Loading...virtual machine arguments.

Every time you execute the corresponding set of unit tests, Eclipse checks the coverage configuration and sets this argument.