Logging in Java and in general: Best Practices?

The following is the set of guidelines I follow in all my projects to ensure good performance. I have come to form this set of guidelines based on the inputs from various sources in the internet.

As on today, I believe Log4j 2 is by far the best option for logging in Java.

The benchmarks are available here. The practice that I follow to get the best performance is as follows:

  1. I avoid using SLF4J at the moment for the following reasons:
    • It has some concurrency issues with Markers which I want to use to manage the logging of SQL statements (Markers not as powerful as slf4j - Refer to the first comment by Ralph Goers)
    • It does not support the Java 8 Lambda which, again, I want to use for better performance (Support the lambda expression in the Logger)
  2. Do all regular logging using asynchronous logger for better performance
  3. Log error messages in a separate file using synchronous logger because we want to see the error messages as soon as it occurs
  4. Do not use location information, such as filename, class name, method name, line number in regular logging because in order to derive those information, the framework takes a snapshot of the stack and walk through it. This impacts the performance. Hence use the location information only in the error log and not in the regular log
  5. For the purpose of tracking individual requests handled by separate threads, consider using thread context and random UUID as explained here
  6. Since we are logging errors in a separate file, it is very important that we log the context information also in the error log. For e.g. if the application encountered an error while processing a file, print the filename and the file record being processed in the error log file along with the stacktrace
  7. Log file should be grep-able and easy to understand. For e.g. if an application processes customer records in multiple files, each log message should be like below:
12:01:00,127 INFO FILE_NAME=file1.txt - Processing starts
12:01:00,127 DEBUG FILE_NAME=file1.txt, CUSTOMER_ID=756
12:01:00,129 INFO FILE_NAME=file1.txt - Processing ends
  1. Log all SQL statements using an SQL marker as shown below and use a filter to enable or disable it:
private static final Marker sqlMarker = 
  MarkerManager.getMarker("SQL");

private void method1() {
    logger.debug(sqlMarker, "SELECT * FROM EMPLOYEE");
}
  1. Log all parameters using Java 8 Lambdas. This will save the application from formatting message when the given log level is disabled:
int i=5, j=10;
logger.info("Sample output {}, {}", ()->i, ()->j);

  1. Do not use String concatenation. Use parameterized message as shown above

  2. Use dynamic reloading of logging configuration so that the application automatically reloads the changes in the logging configuration without the need of application restart

  3. Do not use printStackTrace() or System.out.println()

  4. The application should shut down the logger before exiting:

LogManager.shutdown();
  1. Finally, for everybody’s reference, I use the following configuration:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorinterval="300" status="info" strict="true">
    <Properties>
        <Property name="filePath">${env:LOG_ROOT}/SAMPLE</Property>
        <Property name="filename">${env:LOG_ROOT}/SAMPLE/sample
        </Property>
        <property name="logSize">10 MB</property>
    </Properties>
    <Appenders>
        <RollingFile name="RollingFileRegular" fileName="${filename}.log"
            filePattern="${filePath}/sample-%d{yyyy-dd-MM}-%i.log">
            <Filters>
                <MarkerFilter marker="SQL" onMatch="DENY"
                    onMismatch="NEUTRAL" />
            </Filters>
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />

            </Policies>
        </RollingFile>
        <RollingFile name="RollingFileError" 
            fileName="${filename}_error.log"
            filePattern="${filePath}/sample_error-%d{yyyy-dd-MM}-%i.log"
            immediateFlush="true">
            <PatternLayout>
                <Pattern>%d{HH:mm:ss,SSS} %p %c{1.}[%L] [%t] %m%n
                </Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy
                    interval="1" modulate="true" />
                <SizeBasedTriggeringPolicy
                    size="${logSize}" />
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <AsyncLogger name="com"
            level="trace">
            <AppenderRef ref="RollingFileRegular"/>
        </AsyncLogger>
        <Root includeLocation="true" level="trace">
            <AppenderRef ref="RollingFileError" level="error" />
        </Root>
    </Loggers>
</Configuration>
  1. The required Maven dependencies are here:
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.8.1</version>
</dependency>
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.3.6</version>
</dependency>
<!-- (Optional)To be used when working 
with the applications using Log4j 1.x -->
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-1.2-api</artifactId>
    <version>2.8.1</version>
</dependency>

Your conventions are pretty standard and quite fine (imho).

The one thing to watch is memory fragmentation from excessive unnedded debug calls so, with Log4J (and most other Java logging frameworks), you end up with something like this:

if (log.isDebugEnabled()) {
  log.debug("...");
}

because constructing that log message (that you probably aren't using) could be expensive, especially if done thousands or millions of times.

Your INFO level logging shouldn't be too "chatty" (and from what you say, it sounds like it isn't). INFO messages should be generally meaningful and significant, like the application being started and stopped. Things that you might want to know if you encounter a problem. Debug/fine level logging is more used for when you actually have a problem you're trying to diagnose. Debug/fine logging is typically only turned on when needed. Info is typically on all the time.

If someone doesn't want specific INFO messages from your classes, they are of course free to change your log4j configuration to not get them. Log4j is beautifully straightforward in this department (as opposed to Java 1.4 logging).

As for your HTTP thing, I've generally not found that to be an issue with Java logging because typically a single class is responsible for what you're interested in so you only need to put it in one place. In the (rare in my experience) when you want common log messages across seemingly unrelated classes, just put in some token that can easily be grepped for.

Tags:

Java

Logging

Log4J

Recent Posts