SLF4J Tutorial for Beginners (original) (raw)

In this post, we feature a comprehensive SLF4J Tutorial in order to understand how it helps addresses the problem of logging in software world.

1. SLF4J Tutorial – Introduction

Before jumping into SLF4J, we will take a short look at the reason for its existence. Logging is important aspect of any application. It can help troubleshoot common issues within our application. It can also allow gain insights on the performance of our application. In current landscape, there are lot of logging frameworks available which fulfills all our application’s needs. Each one comes with is own set of pros and cons. Each logging framework can handle certain needs and switching the logging framework should not be painful.

The Simple Logging Facade for Java (SLF4J) is an abstraction over the various logging frameworks available for Java. It provides a simple interface which will be implemented by the logging frameworks in existence. The beauty of SLF4J is that it allows end users to plug in their logging framework of choice during deployment time. Developers just need to include the logging framework dependency in the classpath and SLF4J will utilize it to append the logs. If no logging dependency is provided on the classpath, it will default to a no-operation implementation and nothing gets logged. Below is a sample architecture of application interacting with SLF4J and any suitable logging frameworks.

Let’s take a look at SLF4J Application Architecture:

Application Architecture

SLF4J Website has detailed architecture bound with the various implementations in this diagram.

2. Logging Example

We will directly dive into a logging example. We will look at the initial setup for our application below in this section. Our project uses Maven as the dependency manager and the application’s dependencies will be detailed as and when we encounter them.

pom.xml

4.0.0

<groupId>com.jcg</groupId>
<artifactId>slf4j</artifactId>
<version>1.0-SNAPSHOT</version>

<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.25</version>
    </dependency>
</dependencies>

<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <version>3.6.1</version>
            <configuration>
                <source>1.8</source>
                <target>1.8</target>
            </configuration>
        </plugin>
    </plugins>
</build>

We have specified our artifact as SLF4J in line 8.
We specify slf4j-api as dependency in lines 13-15. Maven downloads the SLF4J dependency in our classpath to enable the logging interface.
We provide Java8 as the target compiler for our application.

Single SLF4J dependency is enough for us to get started with logging. Now we will create a simple class for logging.

LoggerRoot.java

package com.jcg;

import org.slf4j.Logger; import org.slf4j.LoggerFactory;

import java.lang.invoke.MethodHandles; import java.util.stream.IntStream;

public class LoggerRoot { private static final Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getSimpleName());

public static void main(String... args) {
    IntStream.rangeClosed(1, 10).forEach(counter -> {
        logger.info("Counter:" + counter);
    });
}

}

We define our class LoggerRoot in package com.jcg.
We import LoggerFactory and Logger from SLF4J for logging use. LoggerFactory provides various factory methods to initialize an appropriate logger for the use case. The returned Logger from the factory is used to append the logs in our application.
- We have to provide a name for the logger as input to the factory method. This is one of the factory methods available as part of LoggerFactory. We use Java Core API to lookup our class name which can be useful to copy and paste in other classes. This is equivalent to LoggerRoot.class.getName() but it mandates that the correct class is specified in java file or loggers would end up with the same name.
We utilize a lambda function to run a loop from 1 to 10.
Within the lambda loop, We log the counter value. The destination is not known to the logger at this juncture and it depends on logging framework configuration.

Running this just produces the output

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder". SLF4J: Defaulting to no-operation (NOP) logger implementation SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

As explained, SLF4J has defaulted to no operation logger and nothing gets logged anywhere.

2.1 Java.Util.Logging

Now we will provide a logging framework implementation. We will use first java.util.logging. To enable this, We need to include it as a dependency.

pom.xml

org.slf4j slf4j-jdk14 1.7.25 runtime

This downloads the java.util.logging dependency to our project. The dependency is enabled only at run-time with the scope tag. This automatically uses ConsoleHandler and logs the output to console directly without any further configuration.

Running the above example produces the following output in system console.

Oct 17, 2018 8:12:50 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:1 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:2 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:3 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:4 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:5 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:6 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:7 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:8 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:9 Oct 17, 2018 8:12:51 AM com.jcg.LoggerRoot lambda$main$0 INFO: Counter:10

2.2 Logback

We will see how easy it is to switch to another logging implementation. We will introduce logback in our project. We need to comment out the existing logging dependency in our project.

pom.xml

ch.qos.logback logback-classic 1.2.3 runtime

We have defined logback as the runtime dependency. Once we comment logging dependency, SLF4J will pick up logback as the logging implementation. We will cover the logback configuration to log the output to the console.

logback.xml

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <target>System.out</target>
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>
<root level="info">
    <appender-ref ref="console"/>
</root>

We create a console appender with the target as System.Out.
W use PatternLayoutEncoder and provide a pattern containing the class name and logger name.
We specify level as INFO and tie the appender to root logger.

Running the application produces the below output.

08:24:25.816 [main] INFO LoggerRoot - Counter:1 08:24:25.816 [main] INFO LoggerRoot - Counter:2 08:24:25.816 [main] INFO LoggerRoot - Counter:3 08:24:25.816 [main] INFO LoggerRoot - Counter:4 08:24:25.816 [main] INFO LoggerRoot - Counter:5 08:24:25.816 [main] INFO LoggerRoot - Counter:6 08:24:25.816 [main] INFO LoggerRoot - Counter:7 08:24:25.816 [main] INFO LoggerRoot - Counter:8 08:24:25.816 [main] INFO LoggerRoot - Counter:9 08:24:25.816 [main] INFO LoggerRoot - Counter:10

3. Performance and Considerations

In this section, We will take a look at some of the inner details and hooks available in SLF4J. We will look at the SLF4J contract established for the logging frameworks to implement. Also, we will see ways to improve performance of SLF4J further.

3.1 Factory Methods

SLF4J provides two overloaded factory methods getLogger with slight difference in arguments.

- The first version takes a string which represents the logger name. This is the one we have used in our example above, where we get the simple name of the class. We can pass arbitarily any string as logger name.
- The second version takes the class itself as the argument. It then gets the name of the class internally and uses that as the logger name.

private static final Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());

3.2 Logger, Appender and Levels

Logger delegates the task of writing logging events to Appenders. Appenders are named references and will be used by logger to connect to appropriate appenders. Appenders utilize the doAppend method to append logs to the destinaton.

The levels supported in SLF4J according to the order of priority are:

Trace – Lowest level. Used to track the application flow.
Debug – used to add diagnostic messages of the application. Generally useful for debugging when there is an error.
Info – Used to indicate important flows of the application.
Warn – Used to indicate potential error scenarios of the application.
Error – Used to log errors and exceptions of the application.

3.3 Mapped Diagnostic Context

Mapped Diagnostic Context involves putting contextual information in each and every message being logged. This provides context on the log message along with the timestamp. For example, in a shopping application every log message will contain the Order Id so messages can be either analyzed or debugged from an order perspective.

For this purpose, SLF4J provides a MDC class which has four static methods for usage.

put– put a context and its corresponding value
get – get the value corresponding to the context
remove – remove the context
clear – clear all contexts

In this section, we will see how to use the MDC along with logback implementation.

In LoggerRoot.Java, we will add MDC.put("app","JCG"); as the first line of main method.

In logback.xml, we will change the pattern to include the context we have created above

Logback.xml

%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %X{app} %msg%n

The %X or %mdc indicates the mdc converter to be used.
{app} refers to the key name to be used to retrieve the value.

Running this produces the following output:

07:12:44.082 [main] INFO LoggerRoot - JCG Counter:1 07:12:44.082 [main] INFO LoggerRoot - JCG Counter:2 07:12:44.082 [main] INFO LoggerRoot - JCG Counter:3 07:12:44.082 [main] INFO LoggerRoot - JCG Counter:4 07:12:44.082 [main] INFO LoggerRoot - JCG Counter:5 07:12:44.084 [main] INFO LoggerRoot - JCG Counter:6 07:12:44.084 [main] INFO LoggerRoot - JCG Counter:7 07:12:44.084 [main] INFO LoggerRoot - JCG Counter:8 07:12:44.084 [main] INFO LoggerRoot - JCG Counter:9 07:12:44.084 [main] INFO LoggerRoot - JCG Counter:10

We have added the value JCG to the context and we can see the value being logged to the console.

3.4 Parameterized Logging

SLF4J supports an advanced feature called parameterized logging which boosts logging performance for disabled log statements. Typically, in production We enable only warn and error levels. In Development mode, We might have all log levels turned on right from debug. The idea is to enable certain log levels for each environment and filter out the rest of them. Generally in our log messages, We append some dynamic properties to the message and not just the static message. In the above example, We are appending the counter variable output to the message. In case of disabled logs, the string concatenation still happens adding to the performance cost. We are going to see how SLF4J improves performance in this scenario.

logback.xml

....

The level of the logger is set to Error to filter out other logging levels. Rest of the XML has been omitted for brevity

We will add some performance measures and compare the approaches.

The first variant is to do conditional logging.

LoggerRoot.java

LongStream.rangeClosed(1, count).forEach(counter -> { if (logger.isInfoEnabled()) { logger.info("Counter:"+counter); } });

This checks if the info mode is enabled or not and if enabled logs the message. This seems a simple enough solution but adds conditional checks to each and every log line. We will see the next variant of Parameterized Logging.

LoggerRoot.java

LongStream.rangeClosed(1, count).forEach(counter -> { logger.info("Counter:{]",counter); });

In this approach, we are still logging without condition but the dynamic property is passed as parameter. This avoids the string concatenation if info mode is not enabled which improves the performance.

This can be best understood by running tests for considerable volume of log messages. We are using Duration class to measure the performance and the code will be provided as part of the download section.

Log level is set to error and 100000000 info log messages are logged. The results are as follows

11:46:39.753 [main] ERROR LoggerRoot - JCG General Log->PT6.377S 11:46:39.758 [main] ERROR LoggerRoot - JCG Conditional Log->PT0.285S 11:46:39.758 [main] ERROR LoggerRoot - JCG parameterized Log->PT0.649S

Log level is set to info and 10000 info log messages are logged. The results are as follows

11:50:21.646 [main] ERROR LoggerRoot - JCG General Log->PT1.076S 11:50:21.646 [main] ERROR LoggerRoot - JCG Conditional Log->PT0.673S 11:50:21.646 [main] ERROR LoggerRoot - JCG parameterized Log->PT0.176S

In the first Scenario, Conditional logging is 23x faster than plain vanilla logging while parameterized logging is 10x faster. Conditional evaluation takes less time and is giving high performance when the logging mode is disabled.

But if the log mode is enabled, Parameterized logging is 6x faster while conditional logging is 1.5x faster. The reason being both condition and logging has to be performed and hence this increases the execution time. With no additional effort, parameterized logging brings in huge performance gains.

3.5. Implementing SLF4J

As we discussed in the above sections, SLF4J offers a facade and any framework implementing the exposed interface can be used. SLF4J outlines simple steps for framework to implement it.

Use an existing Module for reference i.e.Java.Util.Logging
Create an adapter between your logging system and org.slf4j.Logger interface.
Create a factory for the adapter created in the previous step.
Modify StaticLoggerBinder class to use the factory you created in the previous step.

The Steps above helps to roll our logger implementation. Based on production scenarios, generally we roll out custom appenders and mostly use existing logger implementations.

4. Download the Source Code

The entire code for the above sections is available in the below zip file.

Download
You can download the full source code of this example here: SLF4J Tutorial