由于线上业务量级比较大（日请求上亿，日活用户几十万），同时业务涉及逻辑很复杂，线上日志级别我们采用的是 info 级别，导致线上日志量非常庞大，经常遇到因为日志写入太慢导致的性能瓶颈（各微服务每小时日志量加在一起约小 1000G）。下面将我们做的日志性能提升与精简日志的规范列出，供大家参考。我们使用的日志框架是 Log4j2
1. 使用 Log4j2 异步日志
首先，推荐日志量大的时候，采用异步日志进行日志输出。好处是在 RingBuffer 满之前，调用日志 api 打印日志的时候不会阻塞。坏处是增加日志丢失的可能性，例如在进程异常退出的时候（例如 kill -9），在 RingBuffer 中的还没输出到文件的日志事件就会丢失。
这里简单说一下 Log4j2 异步日志的原理：Log4j2 异步日志基于高性能数据结构 Disruptor，Disruptor 是一个环形 buffer，做了很多性能优化（具体原理可以参考我的另一系列：高并发数据结构（disruptor）），Log4j2 对此的应用如下所示：
简单来说，多线程通过 log4j2 的门面类 org.apache.logging.log4j.Logger 进行日志输出，被封装成为一个 org.apache.logging.log4j.core.LogEvent，放入到 Disruptor 的环形 buffer 中。在消费端有一个单线程消费这些 LogEvent 写入对应的 Appender，假设我们这里只有一个 Appender，其配置是将所有日志输出到一个文件：
<RollingFile name="file" append="true" filePattern="./app.log-%d{yyyy.MM.dd.HH}" immediateFlush="false"> <PatternLayout pattern="${logFormat}"/> <Policies> <TimeBasedTriggeringPolicy interval="1" modulate="true"/> </Policies> <DirectWriteRolloverStrategy maxFiles="72"/> </RollingFile>
异步日志 logger 配置为（配置 includeLocation 为 false，避免每次打印日志需要获取调用堆栈的性能损耗，这个我们后面会提到），这里的日志级别是 info：
<Asyncroot level="info" includeLocation="false"> <appender-ref ref="file"/> </Asyncroot>
log4j component 额外配置为：
log4j2.component.properties:
# 当没有日志的时候，打印日志的单线程通过 SLEEP 等待日志事件到来。这样 CPU 占用较少的同时，也能在日志到来时唤醒打印日志的单线程延迟较低，这个后面会详细分析 # 我们还进一步将其中的 Thread.yield() 修改为了 Thread.spinWait() AsyncLoggerConfig.WaitStrategy=SLEEP
2. 关闭 includeLocation，在日志内容中加入标志位置的标记
日志中我们可能会需要输出当前输出的日志对应代码中的哪一类的哪一方法的哪一行，这个需要在运行时获取堆栈。获取堆栈，无论是在 Java 9 之前通过 Thorwable.getStackTrace()，还是通过 Java 9 之后的 StackWalker，获取当前代码堆栈，都是一个非常消耗 CPU 性能的操作。在大量输出日志的时候，会成为严重的性能瓶颈，其原因是：
- 获取堆栈属于从 Java 代码运行，切换到 JVM 代码运行，是 JNI 调用。这个切换是有性能损耗的。
- Java 9 之前通过新建异常获取堆栈，Java 9 之后通过 Stackwalker 获取。这两种方式，截止目前 Java 17 版本，都在高并发情况下，有严重的性能问题，会吃掉大量 CPU。主要是底层 JVM 符号与常量池优化的问题。
所以，我们在日志中不打印所在类方法。但是可以自己在日志中添加类名方法名用于快速定位问题代码。一般 IDE 中会有这种模本辅助，例如我在 IDEA 中就自定义了这个快捷模板：
快捷键 cm 之后按 tab 就会变成 类名-方法名 的字符串。
3. 配置 Disruptor 的等待策略为 SLEEP，但是最好能将其中的 Thread.yield 修改为 Thread.onSpinWait (这个修改仅针对 x86 机器部署)
Disruptor 的消费者做的事情其实就是不断检查是否有消息到来，其实就是某个状态位是否就绪，就绪后读取消息进行消费。至于如何不断检查，这个就是等待策略。Disruptor 中有很多等待策略，熟悉多处理器编程的对于等待策略肯定不会陌生，在这里可以简单理解为当任务没有到来时，线程应该如何等待并且让出 CPU 资源才能在任务到来时尽量快的开始工作。在 Log4j2 中，异步日志基于 Disruptor，同时使用 AsyncLoggerConfig.WaitStrategy 这个环境变量对于 Disruptor 的等待策略进行配置，目前最新版本的 Log4j2 中可以配置：
switch (strategyUp) { case "SLEEP": final long sleepTimeNs = parseAdditionalLongProperty(propertyName, "SleepTimeNs", 100L); final String key = getFullPropertyKey(propertyName, "Retries"); final int retries = PropertiesUtil.getProperties().getIntegerProperty(key, 200); return new SleepingWaitStrategy(retries, sleepTimeNs); case "YIELD": return new YieldingWaitStrategy(); case "BLOCK": return new BlockingWaitStrategy(); case "BUSYSPIN": return new BusySpinWaitStrategy(); case "TIMEOUT": return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS); default: return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS); }
我们这里使用其中策略最为均衡的 SleepingWaitStrategy。在当前的大多数应用中，线程的个数都远大于 CPU 的个数，甚至是 RUNNABLE 的线程个数都远大于 CPU 个数，使用基于 Wait 的 BusySpinWaitStrategy 会导致业务闲时突然来业务高峰的时候，日志消费线程唤醒的不够及时（CPU 一直被大量的 RUNNABLE 业务线程抢占）。如果使用比较激进的 BusySpinWaitStrategy（一直调用 Thread.onSpinWait()）或者 YieldingWaitStrategy（先 SPIN 之后一直调用 Thread.yield()），则闲时也会有较高的 CPU 占用。我们期望的是一种递进的等待策略，例如：
- 在一定次数内，不断 SPIN，应对日志量特别多的时候，减少线程切换消耗。
- 在超过一定次数之后，开始不断的调用
Thread.onSpinWait()或者Thread.yield()，使当前线程让出 CPU 资源，应对间断性的日志高峰。 - 在第二步达到一定次数后，使用 Wait，或者
Thread.sleep()这样的函数阻塞当前线程，应对日志低峰的时候，减少 CPU 消耗。
SleepingWaitStrategy 就是这样一个策略，第二步采用的是 Thread.yield()，第三步采用的是 Thread.sleep()。同时，我们修改其中的 Thread.yield() 为 Thread.onSpinWait()，原因是：我们部署到的环境是 x86 的机器，在 x86 的环境下 Thread.onSpinWait() 在被调用一定次数后，C1 编译器就会将其替换成使用 PAUSE 这个 x86 指令实现。参考 JVM 源码：
instruct onspinwait() %{ match(OnSpinWait); ins_cost(200); format %{ $$template $$emit$$"pause\t! membar_onspinwait" %} ins_encode %{ __ pause(); %} ins_pipe(pipe_slow); %}
我们知道，CPU 并不会总直接操作内存，而是以缓存行读取后，缓存在 CPU 高速缓存上。但是对于这种不断检查检查某个状态位是否就绪的代码，不断读取 CPU 高速缓存，会在当前 CPU 从总线收到这个 CPU 高速缓存已经失效之前，都认为这个状态为没有变化。在业务忙时，总线可能非常繁忙，导致 SleepingWaitStrategy 的第二步一直检查不到状态位的更新导致进入第三步。
PAUSE 指令（参考：https://www.felixcloutier.com/x86/pause）是针对这种等待策略实现而产生的一个特殊指令，它会告诉处理器所执行的代码序列是一个不断检查某个状态位是否就绪的代码（即 spin-wait loop），这样的话，然后 CPU 分支预测就会据这个提示而避开内存序列冲突，CPU 就不会将这块读取的内存进行缓存，也就是说对 spin-wait loop 不做缓存，不做指令 重新排序等动作。从而提高 spin-wait loop 的执行效率。
这个指令使得针对 spin-wait loop 这种场景，Thread.onSpinWait()的效率要比 Thread.yield() 的效率要高。所以，我们修改 SleepingWaitStrategy 的 Thread.yield() 为 Thread.onSpinWait()。
