性能调优——小小的log大大的坑

引言

“只有被线上服务问题毒打过的人才明白日志有多重要！”
我先说结论，谁赞成，谁反对？如果你深有同感，那恭喜你是个社会人了：）

日志对程序的重要性不言而喻，轻巧、简单、无需费脑，程序代码中随处可见，帮助我们排查定位一个有一个问题问题。但看似不起眼的日志，却隐藏着各式各样的“坑”，如果使用不当，不仅不能帮助我们，反而会成为服务“杀手”。
本文主要介绍生产环境日志使用不当导致的“坑”及避坑指北，高并发系统下尤为明显。同时提供一套实现方案能让程序与日志“和谐共处”。

避坑指北

本章节我将介绍过往线上遇到的日志问题，并逐个剖析问题根因。

不规范的日志书写格式

场景

// 格式1
log.debug("get user" + uid + " from DB is Empty!");

// 格式2
if (log.isdebugEnable()) {
   
    log.debug("get user" + uid + " from DB is Empty!");
}

// 格式3
log.debug("get user {} from DB is Empty!", uid);

如上三种写法，我相信大家或多或少都在项目代码中看到过，那么他们之前有区别呢，会对性能造成什么影响？
如果此时关闭 DEBUG 日志级别，差异就出现了，格式1 依然还是要执行字符串拼接，即使它不输出日志，属于浪费。

格式2 的缺点就是就在于需要加入额外的判断逻辑，增加了废代码，一点都不优雅。
所以推荐格式3，只有在执行时才会动态的拼接，关闭相应日志级别后，不会有任何性能损耗。

生产打印大量日志消耗性能

尽量多的日志，能够把用户的请求串起来，更容易断定出问题的代码位置。由于当前分布式系统，且业务庞杂，任何日志的缺失对于程序员定位问题都是极大的障碍。所以，吃过生产问题苦的程序员，在开发代码过程中，肯定是尽量多打日志。
为了以后线上出现问题能尽快定位问题并修复，程序员在编程实现阶段，就会尽量多打关键日志。那上线后是能快速定位问题了，但是紧接着又会有新的挑战：随着业务的快速发展，用户访问不断增多，系统压力越来越大，此时线上大量的 INFO 日志，尤其在高峰期，大量的日志磁盘写入，极具消耗服务性能。
那这就变成了博弈论，日志多了好排查问题，但是服务性能被“吃了”，日志少了服务稳定性没啥影响了，但是排查问题难了，程序员“苦”啊。

提问：为何 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