Log4j ImmediateFlush Property Example

Rajagopal ParthaSarathiFebruary 15th, 2018Last Updated: March 6th, 2018

2 1,418 4 minutes read

This article is a tutorial about log priority levels in Log4j. In this tutorial, we are going to configure log4j via property files.

1. Introduction

Log4J (Java) is a widely used logging framework for Java. It continues to grow continuously with the recent upgrade to Log4j2. Log4j supports logging via Logger, Appender and Layouts.

Logger is the interaction point for the application and carries out the logging activity. It is used to specify the logging mode and the name of the logger. It also delivers logs to the specified destination with the help of the appender. The Appender delivers the log to the logging destination i.e. console, file or database along with options to fine-tune the logging mechanism. Appenders generally have lifecycle configuration and filtering support. Filtering enables to filter the messages whose logging mode does not match the level configured. Log4j supports multiple predefined appenders and also helps create custom appenders.

Layout specifies the display format of the logs. The most commonly used layout for Log4j is PatternLayout. A sample pattern is %d [%t] %-5p (%F: %L) – %m%n. The format strings for the pattern are as follows:

Date – Full date until microseconds.
Thread – JVM thread logging the output.
Logging Mode – INFO/ERROR/DEBUG/WARN.
Class – Java Class logging the output.
Line number – Line number in java class.
Message – The message logged.
Default line separator -/n unless specified otherwise.

2. Immediate Flush

The above property controls the delivery timing of logs to the destination. If set to true, it is delivered after each method call. By default, it is set to true. Below we will cover a classic example.

Example Class

package com.jcg.examples;
import org.apache.log4j.Logger;
public class LoggerMain {
	public static final Logger logger = Logger.getLogger(LoggerMain.class);
	public static void main(String[] args) {
		int loop = 0;
		while (loop < 1000) {
			logger.warn("This is a warn log");
			loop++;
			try {
				Thread.sleep(20);
			} catch (InterruptedException e) {
				logger.error("Error occurred in sleep", e);
				Thread.currentThread().interrupt();
			}
		}
	}
}

Line 4 configures a logger with the name as com.jcg.examples.LoggerMain.
Line 8 indicates the method used ie logging level for this message.

Here we have used a thread to wait for 20 milliseconds before logging each output. This is to observe the effects of immediate flush. The next part is configuring the logger via XML file or properties. Below, we have used properties to provide a suitable configuration for the appender and the destination.

Configuration

log4j.rootLogger=DEBUG, console
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n

Here, the property is not specified at all and is defaulted. The above configuration results in logs being printed continuously. Below is an example screenshot of the same.

3. Delayed flushing

Below we will cover an example of delayed flushing. This is done by changing the configuration as below.

log4j.rootLogger=DEBUG, console
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.immediateFlush=false
log4j.appender.console.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n

The Appender now batches the logging and logs at specified intervals. The difference is not visible in a screenshot of the output, but it is visible during a run. Logs do not get immediately printed on the console but they are printed in batches. The logging timestamp is exactly similar to the previous run but the logs will get printed to console in a batched manner.

The advantage of such an approach is performance. Logs can be written to external interfaces such as a file, database and not just console. Every call to the external interface is expensive and batching of logs offers some serious performance improvements. Logging is a cross-cutting concern and it is developer’s responsibility to ensure that performance is not degraded by extensive /excessive logging.

3.1. Concerns about Delayed flushing

Delayed flushing has a serious impact in case of errors. Since logging is done in batches, it is likely that the last few log events will not be recorded in logging destination when the application exits. At that juncture, in case of an erroneous exit, we cannot inspect the latest logs which actually caused the issue. Let us observe the downside of delayed flushing with an example.

Example Class(Modified)

package com.jcg.examples;
import org.apache.log4j.Logger;
public class LoggerMain {
	public static final Logger logger = Logger.getLogger(LoggerMain.class);
	public static void main(String[] args) {
		int loop = 0;
		while (loop < 100) {
			logger.warn("This is a warn log");
			loop++;
			try {
				Thread.sleep(20);
			} catch (InterruptedException e) {
				logger.error("Error occurred in sleep", e);
				Thread.currentThread().interrupt();
			}
		}
	}
}

In this case, we are not introducing errors. We are creating a shorter loop which will exit within 100 iterations. Surprisingly, in this case, the program will run and no logs will get printed on the console. Our program has ended even before the first batch of logs are printed. The same will happen in case of errors resulting in application termination.

With Delayed flushing, we can gain performance in the range of 10 to 20%. But there is a clear possibility of losing logs during application termination. This trade-off has to be considered into account during application design.