Java Log Performance

In any system, the log is a very important part, it is a reflection of the system operation of the important basis, but also the necessary clues to troubleshoot problems. Most people recognize the importance of the log, but how many people think carefully about how to log, the impact of the log on the performance of how much? Let's talk about the performance of Java logs today.

When it comes to Java logs, you will definitely say you want to choose a reasonable log level, reasonable control of the log content, but this is only the first step Long March ... Even some DEBUG levels of logs that are not exported to a file in a production environment can also have a small overhead. We put aside the overhead of judgment and method invocation, and in the performance document of Log4j 2.x there is a set of comparisons:

Logger.debug ("Entry number:" + i + "is" +  string.valueof (Entry[i]));  Logger.debug ("Entry number: {} is {}", I, entry[i]);

The above two statements have the same effect on the log output, but their overhead is different when the log is closed, with the DEBUG main effect being on string conversions and string stitching, which convert the variables to strings and stitch them up, regardless of whether they are in effect, and the latter will only perform these operations when needed. LOG4J's official Test concludes that the performance of the two can vary by two orders of magnitude. Imagine toString() how much resources can be saved if a method of an object is used ToStringBuilder to reflect the output of dozens of properties.

Therefore, some companies that are still using log4j 1.x or Apache Commons Logging (which do not support {} template writing) will have the appropriate coding specifications that require additional judgment before a certain level of logging (for example, DEBUG and INFO ) output:

if (logger.isdebugenabled ()) {     Logger.debug ("Entry number:" + i + "is" + string.valueof (Entry[i]));}

In addition to the log level and log messages, usually in the log will also contain some other information, such as date, thread name, class information, MDC variables, etc., according to TAKIPI Test, if added in the log class , performance will drop sharply, compared to the default configuration of Logback, the throughput of the decline of about 60%. If you must print the class information, you might consider naming it with a class name Logger .

In a distributed system, a request may go through several different subsystems, it is better to generate a UUID attached to the request, each subsystem in the print log when the UUID is placed in the MDC, to facilitate subsequent query related logs. "The Ultimate guide:5 Methods for debugging Production Servers in scale" gives a lot of advice on how to debug in a production environment, several of which are about logs, which is one of them. Another suggestion is to record all the logs that have not been captured, in fact, throw exceptions have overhead, record exceptions also bring some overhead, mainly because the Throwable method of the class fillInStackTrace is synchronized by default:

Public synchronized native Throwable Fillinstacktrace ();

General use logger.error will be out of the stack of exceptions, if the throughput has a certain requirements, when the situation is run, you can consider overwriting the method, remove synchronized native , directly return to the instance itself.

Talk about the contents of the log, and then look at it Appender . In Java, said IO operation everyone will think of NiO, to JDK 7 and AIO, at least know read and write plus Buffer , log is so, synchronous write Appender in high concurrency large flow of the system is somewhat inadequate, then it should be used AsyncAppender , The same is the use of Logback:

With 10 threads concurrently, the output of 200-character INFO logs AsyncAppender can be up to FileAppender 3.7 times times the throughput. In the case of no loss of logs, the same use AsyncAppender , the queue length will have a certain impact on performance.

If you use log4j 2.x, you AsyncAppender can also consider higher performance asynchronous Logger , because the underlying use of disruptor, no lock overhead, the performance is even more astonishing. According to the official test of the log4j 2.x, the same log4j 2.x is used:

Under 64 threads, Async Logger Appender is 12 times times faster than asynchronous, and Logger is faster than synchronous.

It is also asynchronous, and there are differences between the different libraries:

In the same hardware environment, the LOG4J 2.x is used asynchronously Logger AsyncAppender 12 times times faster than the Logback, 19 times times faster than log4j 1.x async Appender .

(Click to enlarge image)

Log4j 2.x's asynchronous Logger performance is strong, but there are different voices, think it's just a look elegant, only as a toy. It is still left to the reader to think about the problem.

If you have to use synchronous Appender , then you can consider using ConsoleAppender , and then redirect STDOUT to the file, so there will be around 10% performance improvement.

Most production systems are clustered, and for logs distributed across different servers, it's good to collect them with tools like Logstash. Many times will also deploy multiple instances on a single machine to make full use of server resources, at this time do not covet log monitoring or log query convenient, the log of multiple instances to the same log file, although Logback provides a prudent mode, to allow multiple JVMs to the same file to write logs, However, this approach also has an impact on performance, which can reduce performance by as much as 10%.

If the same log file has a large number of write requirements, you can consider splitting the log to different files, one way is to add multiple Appender , while modifying the code, different circumstances use different Logger ; Logback provides the SiftingAppender ability to split the log directly from the MDC's content. Jetty's tutorial has an example of host splitting the log according to the TAKIPI test, SiftingAppender the performance will increase with the number of split files increase together, when split into 4 files, 10 concurrent SiftingAppender throughput is about FileAppender 3 times times more.

Look at the above data, I do not know whether you think your log has a lot of improvement, you have not optimized the system to the extreme, or you have other methods of log optimization, may wish to share to you.

Java Log Performance