slf4j-caller-info-maven-plugin

Maven plugin to inject caller-location-information to all SLF4J Logger log statement invocations (info(), etc.) in your compiled code, as a better alternative to SLF4J caller location evaluation during runtime. Also allows to inject caller-information when using wrapper classes/methods (see Configuration/injectedMethods).

Description

By default SLF4J implementations such as logback or log4j offer to log the caller-location (e.g. Logback/Layouts#method), but this comes at a huge performance loss (see Apache/Log4j2-Performance-Caller-Location).

Instead of evaluating the caller-location (method, source code line number) during runtime, this plugin injects the caller-location info to all log statements when building the project. The injection is done with a MDC.put(...) call before every SLF4J log invocation, putting the class name, line number (optionally also method name) into the MDC in the compiled .class files. This allows to conveniently print out where exactly in the code the log statement originates from for every single log statement, without any overhead or performance loss, by simply adding the Mapped Diagnostic Context (MDC) parameter callerInformation to your logging-pattern configuration. It can therefore be used with any SLF4J implementation, such as logback, log4j2, etc.

Since this plugin adds the necessary code during the build stage, there is nearly no performance loss by injecting the caller-location-information in comparison to using e.g. the %class or %line pattern parameters (see Log4j2 manual or Logback manual in your logging pattern, which look for the caller-information on the stacktrace during runtime which is very costly.

Usage

Add the plugin to your pom.xml:

<build>
    <plugins>
        <plugin>
            <groupId>io.github.philkes</groupId>
            <artifactId>slf4j-caller-info-maven-plugin</artifactId>
            <version>1.1.0</version>
            <executions>
                <execution>
                    <goals>
                        <goal>inject</goal>
                    </goals>
                </execution>
            </executions>
        </plugin>
    </plugins>
</build>

Note: JDK 8 or higher required

The plugin is executed in the process-classes phase or can be explicitly run with:

mvn slf4j-caller-info:inject

Note: The inject goal is idempotent

Code Example

See logback.xml:

...
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <!-- Example log pattern including the needed 'callerInformation' MDC parameter -->
        <pattern>%d{HH:mm:ss.SSS} %-5level %logger{36} \(%X{callerInformation}\) - %msg%n</pattern>
    </encoder>
</appender>
...

See LoggingTest.java:

1   package io.github.philkes.slf4j.callerinfo;
2
3   import org.slf4j.Logger;
4   import org.slf4j.LoggerFactory;
5
6   /**
7    * Example Class using an SLF4J Logger on different Levels
8    */
9   public class LoggingTest {
10      private final Logger log = LoggerFactory.getLogger(LoggingTest.class);
11
12      public void log(String msg) {
13          log.info(msg);
14          log.warn(msg);
15          log.error(msg);
16          log.debug(msg);
17          log.trace(msg);
18      }
19  }

Log Output of LoggingTest.log("This is a test message"):

(Screenshot from IntelliJ, automatically detects class + linenumber as links to jump directly into the source code)

Performance at runtime

As you can see using the slf4j-caller-info-maven-plugin (orange bars) printing the caller location is about 4x faster than using Log4j2's or Logback's caller-location built-in pattern (red bars). In total there is a performance loss of only ~9% for Log4j2 and ~8% for Logback in comparison to not logging the caller-location at all (blue bars).

System specs for the benchmarks: JDK 17 on Linux Mint 20.3 with 8 cores CPU AMD Ryzen 2700X@3.7Ghz

The benchmarking was done with JMH based on log4j's log4j-perf module. For more details about the benchmarks see the benchmark module.

Performance at compiletime

As for the time it takes the inject goal to execute, the compilation time of the plugin is evaluated by generating Java projects with n classes, that all contain 5 SLF4J log-statements and running the plugin on these projects and averaging the plugin's execution time.

We can see that the plugin's execution time obviously goes up the more classes and SLF4J log statements there are in the source code, but even for a project with 10,000 classes the compilation time is ~2 seconds, which is only about twice as long as with only 1 class.

Configuration

There are several parameters you can overwrite:

<configuration>
<!-- All parameters are optional, the shown default values are used if they are not overwritten in your pom.xml --> 
    <!-- Injection format which can include conversion words: class,line,method -->
    <injection>%class:%line</injection>
    <!-- MDC parameter name for the injection, this parameter has to be present in your logging.pattern ('%X{callerInformation}') -->
    <injectionMdcParameter>callerInformation</injectionMdcParameter>
    <!-- Regex for specifying which packages/classfiles should be injected into (path and class-file name) -->
    <filters>
        <includes>
            <include>.*</include>
        </includes>
        <excludes></excludes>
    </filters>
    <!-- Method descriptors to configure for which method calls the caller-information should be injected to -->
    <!-- By default all common SLF4J log methods are injected into, but this parameter also allows to inject to custom methods, e.g. when using wrapper classes for logging -->
    <injectedMethods>
        <injectedMethod>org/slf4j/Logger#info</injectedMethod>
        <injectedMethod>org/slf4j/Logger#warn</injectedMethod>
        <injectedMethod>org/slf4j/Logger#error</injectedMethod>
        <injectedMethod>org/slf4j/Logger#debug</injectedMethod>
        <injectedMethod>org/slf4j/Logger#trace</injectedMethod>
    </injectedMethods>
    <!-- Whether or not to print the package-name of the class, if '%class' is present in 'injection' parameter -->
    <includePackageName>false</includePackageName>
    <!-- Target directory which contains the compiled '.class' files -->
    <target>${project.build.outputDirectory}</target>
</configuration>

Compiled .class File of Code Example

// import ...
public class LoggingTest {
    //...
    public void log(String msg) {
        Logger var10000 = this.log;
        MDC.put("callerInformation", "LoggingTest.class:13");
        var10000.info(msg);
        MDC.remove("callerInformation");
        var10000 = this.log;
        MDC.put("callerInformation", "LoggingTest.class:14");
        var10000.warn(msg);
        ...
    }
}

Dependencies

• ASM for Java bytecode manipulation
• Apache Commons IO for FileUtils
• Built with Java 17
• JMH for benchmarks

This project is licensed under the terms of the Apache 2.0 license.