隐藏的性能杀手：为什么日志中的代码位置会摧毁你的微服务性能#
当我们首次启动服务时，我们将生产日志级别配置为 INFO，并在日志输出中包含代码位置信息。格式看起来像这样：
2022-03-02 19:57:59.425 INFO [service-apiGateway,,] [35800] [main][org.springframework.cloud.gateway.route.RouteDefinitionRouteLocator:88]: Loaded RoutePredicateFactory [Query]
我们使用 Log4j2 作为日志框架，并启用了异步日志。对于 Log4j2 的 Disruptor WaitStrategy，我们通过设置 AsyncLoggerConfig.WaitStrategy=Sleep 选择了对 CPU 友好的 Sleep 选项。随着业务增长，我们注意到一些实例经历了极高的 CPU 使用率，特别是在大量日志记录期间。为了彻底解决这个问题，我们捕获了 JFR 转储以进行进一步调查。
让我们从检查垃圾收集模式开始。我们使用 G1GC，所以我们专注于 G1 垃圾收集事件：
分析显示所有 GC 活动都包括正常执行时间和没有异常频率模式的 Young GC。
接下来，我们深入 CPU 使用率分析。查看 Thread CPU Load 事件向我们显示了每个线程的 CPU 消耗。我们发现的情况相当令人担忧 - reactor-http-epoll 线程池线程总共消耗了近 100% 的 CPU。
这些线程处理 reactor-netty 中的业务逻辑。当我们将其与其他健康实例进行比较时，我们发现正常操作不应该产生如此高的 CPU 负载。那么是什么导致了这种过度的负载？是时候进行一些线程转储分析了！
在检查多个线程堆栈转储后，我们发现这些线程一致处于 Runnable 状态，执行与 StackWalker 相关的原生方法。这与我们 JFR 数据中的 Method Runnable 事件完美对齐，确认 CPU 主要由这些特定方法调用消耗：
罪魁祸首是两个原生方法：
java.lang.StackStreamFactory$AbstractStackWalker.callStackWalkjava.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames
这里有一个关键的理解：微服务线程堆栈可能非常深（大约 150 层），响应式代码使这变得更糟（可能达到 300 层）。这是因为 servlet 和过滤器使用责任链模式，每个过滤器都会添加到堆栈中。响应式代码通过其分层方法和各种观察点放大了这一点。上面的堆栈跟踪是响应式堆栈深度的完美示例。
这些原生方法正在做一件特定的事情：确定调用日志记录方法的代码位置。这包括类名、方法名和行号。在我们的堆栈跟踪示例中，实际的日志记录调用位置是：at com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，我们使用 log.info() 输出一些日志。
显然，Log4j2 通过遍历当前线程的堆栈来获取调用代码位置。它不仅仅是堆栈的顶部 - 它需要找到 log4j2 框架元素之后的第一个堆栈元素，以识别实际的日志记录调用位置。
Log4j2 如何检索堆栈信息#
让我们思考如何自己实现这个。在 Java 9 之前，获取当前线程的堆栈（我们这里不处理其他线程）可以通过以下方式完成：
注意 Thread.currentThread().getStackTrace(); 本质上在底层是 new Exception().getStackTrace();，所以它们在功能上是等价的。
Java 9 引入了新的 StackWalker 接口，它提供了一种更优雅的方式来使用 Stream 接口读取堆栈：
让我们检查 new Exception().getStackTrace(); 如何在内部工作：
这是 StackWalker 的核心实现：
两种方法基本上都填充堆栈详细信息，但一种填充所有内容，而另一种减少填充的堆栈信息量。填充堆栈信息主要涉及访问 SymbolTable 和 StringTable，因为我们需要实际的类和方法名而不是内存地址。显然：基于异常的堆栈检索比 StackWalker 更频繁地访问 Symbol Table 和 String Table，因为它需要填充更多堆栈帧。
让我们通过模拟检索代码执行位置如何影响我们原始代码的性能在不同堆栈深度下测试这一点。
性能影响比较：代码位置检索 vs 无位置#
以下代码基于 Log4j2 的官方单元测试。首先，让我们模拟各种深度的堆栈调用：
然后我们将编写测试代码来比较纯执行和执行与堆栈检索之间的性能差异：
运行测试给我们这些结果：
结果清楚地表明检索代码执行位置（即获取堆栈）会导致显著的性能下降。此外，这种性能损失与堆栈填充相关 - 更多填充的帧意味着更大的损失。我们可以从 StackWalker 相比基于异常的堆栈检索的优越性能中看到这一点，随着堆栈深度增加，性能差距扩大。
为什么它很慢？测试 String::intern 性能影响#
这种性能下降源于 StringTable 和 SymbolTable 访问，正如我们在 JVM 源代码分析中看到的。我们可以模拟这种访问，因为底层 StringTable 操作使用 String 的 intern 方法。这是我们使用 String::intern 的模拟测试：
测试结果：
比较 StackWalkBenchmark.baseline 与 StackWalkBenchmark.toString 显示 bh.consume(time); 本身的性能影响可以忽略不计。然而，将这些与 StackWalkBenchmark.intern 和 StackWalkBenchmark.intern3 进行比较，揭示了严重的性能下降，随着访问频率增加（类似于堆栈检索）而恶化。
结论和建议#
从这个分析中，我们可以得出一些明确的结论：
- 日志中的代码位置输出在 Java 9 之前使用基于异常的堆栈检索，之后使用 StackWalker
- 两种方法都需要访问 SymbolTable 和 StringTable，StackWalker 通过限制填充的堆栈帧来减少访问
- 两种方法都会导致严重的性能下降。
因此，我强烈建议：对于微服务环境，特别是具有非常深堆栈的响应式微服务环境，避免在高量日志中包含代码位置，因为它会导致严重的性能下降。
在禁用日志中的代码位置输出后，我们在相同负载条件下观察到显著降低的 CPU 使用率，以及整体吞吐量的明显改善。
