Lazy logging with log4j2 in Java

The purpose of logging is to provide information about what is happening in the system, which requires including information about the objects being manipulated. In this blog post I will show you how can we achieve lazy logging with log4j 2.x framework.

In Log4j 1.x this could be accomplished by doing

logger.debug("Welcome to " + user.getName() );
Code language: Java (java)

The Problem with the above statement is even if we are using “ERROR” level in the logging statement is evaluated which consumes some time. Imagine for debugging purpose if we are logging 100 objects it will consume even more time even though it won’t logged.

To overcome the above problem , we can explicitly check the log level enabled and then evaluate the statement like below.

if (logger.isDebugEnabled()) {
    logger.debug("Welcome to " + user.getName() );
}Code language: Java (java)

Problem with above statements in log level is being checked twice ( in Line 1 & 2) and if we have many log statements like above code looks cumbersome.

We can overcome the problem using log4j version 2 and Java 8 by lazily logging the log statements without explicitly checking the log level.

Required softwares

• JDK 1.8+
• Maven 3.0+
• Log4j2 2.4+
• Eclipse/IntelliJ Idea

Create Sample application

Open a command prompt and go to your workspace directory and use following maven command to create a Java project

mvn archetype:generate -DgroupId=com.sureshtech -DartifactId=lazy-logging -DarchetypeGroupId=com.thepracticaldeveloper -DarchetypeArtifactId=archetype-java-basic-tpd -DarchetypeVersion=1.0.0
Code language: Java (java)

Maven command will ask for confirmation before creating project. If the project details are correct type “Y” for creating the project.

Now import the project into your workspace. For steps to import maven project into eclipse IDE, please visit my previous blog post

Adding lo4j2 dependencies

First we will add the log4j2 maven dependencies in pom file. Add the following log4j2 dependencies to pom.xml

<dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.14.1</version>
      </dependency>
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.14.1</version>
      </dependency>Code language: Java (java)

Let’s add log4j2 xml configuration file to project for logging.Add the log4j2.xml file in src/main/resources folder

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
	<Appenders>
		<Console name="STDOUT" target="SYSTEM_OUT">
			<PatternLayout pattern="%d %-5p [%t] %C{2} (%F:%L) - %m%n"/>
		</Console>
	</Appenders>
	<Loggers>
		<Logger name="lazy-logger" level="info"/>
		<Root level="info">
			<AppenderRef ref="STDOUT"/>
		</Root>
	</Loggers>
</Configuration>Code language: Java (java)

Now let’s initialize the logger in App.java class and add some log statements in the class.Since lazy-looger log level is set to info. Let’s add few debug and info statements. I have added log statements getName method of User class

package com.sureshtech;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class App 
{
    private static final Logger logger = LogManager.getLogger("lazy-logger");
	
	
    public static void main( String[] args )
    { 
    	User user = new User();
    	
    	user.setId(1);    	
    	user.setName("Test");   	
    	
    	
    	logger.debug("Welcome to {}!", user.getName() );
    	
    	logger.info("Welcome to {}!",user.getName() );
       
       
    }
}Code language: Java (java)

Now if you run App.java class, you will see the following log statements. In the below image you can observe that getName is called logged twice ( one for info and one for debug statement) even though the log level is set to.INFO That means we are facing same problem as log4j 1.x

With the introduction of lambda expressions in Jdk1.8 , log4j2 added support for lambda is logging which gets evaluated lazyily.

Let’s change the log statements with lambda expressions and run the program again.

Now let’s check the logs again. Magically getName is called logged only once. Using lambdas in log statements will result lazy calls to methods. In this case since log level is set to INFO only info log statements are evaluated

You can download the source code for this blog post from GitHub