[日志]Java日志性能那些事

在任何系统中，日志都是很是重要的组成部分，它是反映系统运行状况的重要依据，也是排查问题时的必要线索。绝大多数人都承认日志的重要性，可是又有多少人仔细想过该怎么打日志，日志对性能的影响究竟有多大呢？今天就让咱们来聊聊Java日志性能那些事。

说到Java日志，你们确定都会说要选择合理的日志级别、合理控制日志内容，可是这仅是万里长征第一步……哪怕一些DEBUG级别的日志在生产环境中不会输出到文件中，也可能带来不小的开销。咱们撇开判断和方法调用的开销，在Log4J 2.x的性能文档中有这样一组对比：

logger.debug("Entry number: " + i + " is " +  String.valueOf(entry[i])); 
 logger.debug("Entry number: {} is {}", i, entry[i]);

上面两条语句在日志输出上的效果是同样的，可是在关闭DEBUG日志时，它们的开销就不同了，主要的影响在于字符串转换和字符串拼接上，不管是否生效，前者都会将变量转换为字符串并进行拼接，然后者则只会在须要时执行这些操做。Log4J官方的测试结论是二者在性能上能相差两个数量级。试想一下，若是某个对象的toString()方法里用了ToStringBuilder来反射输出几十个属性时，这时能省下多少资源。

所以，某些仍在使用Log4J 1.x或Apache Commons Logging（它们不支持{}模板的写法）的公司都会有相应的编码规范，要求在必定级别的日志（好比DEBUG和INFO）输出前增长判断：

if (logger.isDebugEnabled()) { 
    logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); 
}

除了日志级别和日志消息，一般在日志中还会包含一些其余信息，好比日期、线程名、类信息、MDC变量等等，根据Takipi的测试，若是在日志中加入class，性能会急剧降低，比起LogBack的默认配置，吞吐量的降幅在6成左右。若是必定要打印类信息，能够考虑用类名来命名Logger。

在分布式系统中，一个请求可能会通过多个不一样的子系统，这时最好生成一个UUID附在请求中，每一个子系统在打印日志时都将该UUID放在MDC里，便于后续查询相关的日志。《The Ultimate Guide: 5 Methods For Debugging Production Servers At Scale》一文中就如何在生产环境中进行调试给出了很多建议，当中好几条是关于日志的，这就是其中之一。另外一条建议是记录下全部未被捕获的日志，其实抛出异常有开销，记录异常一样会带来必定的开销，主要缘由是Throwable类的fillInStackTrace方法默认是同步的：

public synchronized native Throwable fillInStackTrace();

通常使用logger.error都会打出异常的堆栈，若是对吞吐量有必定要求，在状况运行时能够考虑覆盖该方法，去掉synchronized native，直接返回实例自己。

聊完日志内容，再来看看Appender。在Java中，提及IO操做你们都会想起NIO，到了JDK 7还有了AIO，至少都知道读写加个Buffer，日志也是如此，同步写的Appender在高并发大流量的系统里多少有些力不从心，这时就该使用AsyncAppender了，一样是使用LogBack：

在10线程并发下，输出200字符的INFO日志，AsyncAppender的吞吐量最高能是FileAppender的3.7倍。在不丢失日志的状况下，一样使用AsyncAppender，队列长度对性能也会有必定影响。

若是使用Log4J 2.x，那么除了有AsyncAppender，还能够考虑性能更高的异步Logger，因为底层用了Disruptor，没有锁的开销，性能更为惊人。根据Log4J 2.x的官方测试，一样使用Log4J 2.x：

64线程下，异步Logger比异步Appender快12倍，比同步Logger快68倍。

一样是异步，不一样的库之间也会有差别：

同等硬件环境下，Log4J 2.x所有使用异步Logger会比LogBack的AsyncAppender快12倍，比Log4J 1.x的异步Appender快19倍。

(点击放大图像)

Log4J 2.x的异步Logger性能强悍，但也有不一样的声音，以为这只是个看上去很优雅，只能当成一个玩具。关于这个问题，仍是留给读者本身来思考吧。

若是必定要用同步的Appender，那么能够考虑使用ConsoleAppender，而后将STDOUT重定向到文件里，这样大约也能有10%左右的性能提高。

大部分生产系统都是集群部署，对于分布在不一样服务器上的日志，用Logstash之类的工具收集就行了。不少时候还会在单机上部署多实例以便充分利用服务器资源，这时千万不要贪图日志监控或者日志查询方便，将多个实例的日志写到同一个日志文件中，虽然LogBack提供了prudent模式，可以让多个JVM往同一个文件里写日志，但此种方式对性能一样也有影响，大约会使性能下降10%。

若是对同一个日志文件有大量的写需求，能够考虑拆分日志到不一样的文件，作法之一是添加多个Appender，同时修改代码，不一样的状况使用不一样Logger；LogBack提供了SiftingAppender，能够直接根据MDC的内容拆分日志，Jetty的教程中就有根据host来拆分日志的范例，而根据Takipi的测试，SiftingAppender的性能会随着拆分文件数的增加一同提高，当拆分为4个文件时，10并发下SiftingAppender的吞吐量约是FileAppender的3倍多。

看了上面这么多的数据，不知您是否以为本身的日志有很多改进的余地，您尚未把系统优化到极致，亦或者您还有其余日志优化的方法，不妨分享给你们。