性能调优之日志打印的坑
摘要：推荐异步+随机采样打印日志，日志能少则少，而且只打印核心信息，切勿打印无用日志内容，切勿在循环中打日志。
综述
在任何系统中，日志对服务的重要性不言而喻，它是反映系统运行情况的重要依据；它轻巧、简单，与我们形影不离，使得我们在排查问题时无需绞尽脑汁。被线上服务问题毒打过的人都认可日志的重要性，但看似不起眼的日志，却是一把双刃剑，隐藏着各式各样的“坑”，如果使用不当，不仅不能助我们一臂之力，反而会成为服务“杀手”，所以，你知道有哪些场景可能导致性能问题吗？今天楼兰胡杨和各位老铁聊聊高并发系统下 Java 日志性能那些事，同时提供一套异步+随机采样方案能让程序与日志“和谐共处”。
日志打印流程
Java 日志打印对服务的影响包括多种因素，例如日志级别、日志输出目标和日志格式等。下面的流程图展示了 Java 日志打印的一般流程和对 CPU 的影响。
根据以上流程图可以得出以下结论：
-
Java 日志打印会增加代码的执行时间，因为需要执行额外的日志打印语句。
-
日志级别的选择会影响 CPU 的占用率。较低的日志级别（如 INFO 或 DEBUG）会导致更多的日志打印语句被执行，增加 CPU 的负担。
-
日志输出目标的选择也会影响 CPU 的占用率。将日志输出到控制台会导致额外的 I/O 操作，增加 CPU 的负担。
日志格式的复杂程度也会影响 CPU 的占用率。使用更复杂的日志格式可能会导致更多的字符串操作，增加 CPU 的负担。
不合理的书写方法
本章节我将介绍过往线上遇到的日志问题，并逐个剖析问题根因。不同场景的日志书写格式：
// 格式1
log.debug("User id = " + userId);
// 格式2
if (log.isdebugEnable()) {
log.debug("User id = " + userId);
}
// 格式3
log.debug("User msg {}!", JSON.toJSONString(user));
// 格式4，既然加了开关，说明是核心日志，打印info级别
if (日志开关已开启) {
log.info("User msg {}!", JSON.toJSONString(user));
}
如上四种写法，我相信大家或多或少都在项目代码中看到过，那么它们之间有什么区别？对性能会造成什么影响？如果此时关闭 DEBUG 级别日志，差异就显露出来了。
格式1 即使它不输出日志，依然需要执行字符串拼接，属于资源浪费。
格式2 缺点是需要加入额外的判断逻辑，增加了废代码，一点不优雅。
格式3 缺点是仍然需要根据系统配置的日志级别判断是否打印日志，并且需要提前序列化对象为JSON字符串，但是，不需要拼接字符串。
格式4 推荐在高并发系统中使用，优点是根据Boolean类型日志开关判断是否走日志打印逻辑，开关关闭时，不必校验是否需要打印日志。
线上环境打印大量日志消耗性能
尽量多的日志，能够把用户的请求串起来，更容易断定出问题的代码位置。对于业务庞杂的分布式系统，任何日志的缺失对于程序员定位问题都是极大的障碍。所以，被线上问题折磨过的的程序员在开发代码过程中，为了以后线上出现问题能尽快定位问题并修复，肯定会设置合理的日志级别，而且只打印刚需日志。
提问：为何 INFO 日志打多了，性能会受损（此时 CPU 使用率很高）？根本原因：同步打印日志时，磁盘 I/O 成为瓶颈，导致大量线程 Block。
可以想象，如果日志都输出到同一个日志文件时，此时有多个线程都往文件里面写，是不是就乱了套了。那解决的办法就是加锁，保证日志文件输出不会错乱，如果是在高峰期，锁的争抢无疑是最耗性能的。当有一个线程抢到锁后，其它的线程只能 Block 等待，严重拖垮用户线程，表现就是上游调用超时，用户感觉卡顿。
如下是线程卡在写文件时的堆栈：
Stack Trace is:
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352)
- waiting to lock <0x000000063d668298> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228)
.....
提问：假设不关心 INFO 排查问题，是不是生产只打印 ERROR 日志就没性能问题了？
同样的，ERROR 日志量也不容小觑，假设线上出现大量异常数据，或者下游大量超时，瞬时会产生大量 ERROR 日志，此时还是会把磁盘 I/O 压满，导致用户线程 Block 住，最终导致 CPU 使用率快速增长。
最佳实践
去掉不必要的异常堆栈信息
对于显而易见的异常就不要打印堆栈，省点性能，任何事一旦邂逅高并发，意义就不一样了。
try {
System.out.println(Integer.parseInt(number) + 100);
} catch (Exception e) {
// 改进前
log.error("parse int error : " + number, e);
// 改进后
log.error("parse int error : {}", number);
}
如果Integer.parseInt发生异常，导致异常的原因肯定是传入的number不合法，在这种情况下，可以去掉不必要打印的异常堆栈信息，直接打印自定义异常信息。
异步随机采样打印日志
生产环境，尤其是 QPS 高的服务，小编推荐大家采用【异步+随机采样】打印策略，异步打印就不解释了，随机采样可以根据每次请求的唯一标识，如订单ID、用户ID+当前时间戳或者每次访问的请求ID等，随机打印32%或者50%等。当然开启异步打印有丢失日志的风险，比如服务器被强行终止时，没有来得及打印的日志就会丢失，但是，这些丢失的日志相对于QPS>100的整体日志而言，可以忽略不计。
优化日志的输出格式
我们看下不同日志输出模式的区别：
// 格式1
[%d{yyyy/MM/dd HH:mm:ss.SSS}[%X{traceId}] %t [%p] %C{1} (%F:%M:%L) %msg%n
// 格式2
[%d{yy-MM-dd.HH:mm:ss.SSS}] [%thread] [%-5p %-22c{0} -] %m%n
官网对这几类模式的说明中反复强调了会影响性能。如果使用了如下属性输出，将极大的损耗性能：
%C or $class, %F or %file, %l or %location, %L or %line, %M or %method
各属性解释如下：
%C - 调用者的类名（速度慢，不推荐使用）
%F - 调用者的文件名（速度极慢，不推荐使用）
%l - 调用者的函数名、文件名、行号（极度不推荐，非常耗性能）
%L - 调用者的行号（速度极慢，不推荐使用）
%M - 调用者的函数名（速度极慢，不推荐使用）
例如，log4j 为了拿到函数名称和行号信息，利用了异常机制，首先抛出一个异常，之后捕获异常并打印出异常信息的堆栈内容，再从堆栈内容中解析出行号。而实现源码中增加了锁的获取及解析过程，高并发下，性能损耗可想而知。
配置日志打印开关|done
动态调整日志级别是常规操作，不做介绍，它既满足可随时查看 INFO日志的诉求，又能满足不需要时可动态关闭的诉求，而且不影响服务性能。借鉴此设计思想，小编推荐老铁们自定义日志打印开关。如果需要排查问题，开启相关日志的开关，定位到问题后再关闭开关：
if (日志开关已开启) {
log.info("User msg {}!", JSON.toJSONString(user));
}
优点是避免JSON 序列化或者字符串拼接，而且可以减少不必要的磁盘I/O操作造成的性能损耗。
总结与展望
小编在此带你了解了日志在日常软件服务中常见的问题，以及对应的解决方法。切记，简单的东西 + 高并发 = 不简单！要对服务稳定性保持敬畏之心！
能读到结尾说明你真是铁粉了，有任何问题请私信或者评论，我看到了一定会第一时间回复。“点赞背后有感动，转发背后有收获，评论背后有认同，关注背后有价值。”如果你觉得本人提供的内容解决了你的问题，麻烦点赞、转发和关注，这是对我默默前行的最大鼓励，感谢支持！
Reference
Buy me a coffee. ☕Get red packets.
