？本文是“我为什么建议”系列的第二篇。对开发规范的一些开发建议和要求进行了讲解、分析和解读，相信可以让你在面对高并发业务时避免一些坑。过去的回顾：为什么我建议在复杂但性能关键的表上的所有查询中添加强制索引。业务开始上线时，我们的上线日志级别为INFO，在日志内容中输出代码位置。例如，格式为：2022-03-0219:57:59.425INFO[service-apiGateway,,][35800][main][org.springframework.cloud.gateway.route.RouteDefinitionRouteLocator:88]:LoadedRoutePredicateFactory[Query]：我们使用的日志框架是Log4j2，方式是异步日志记录。Log4j2的Disruptor的WaitStrategy采用比较均衡的CPU占用比较配置了一个小Sleep：AsyncLoggerConfig.WaitStrategy=Sleep。随着业务的增长，我们发现某些实例的CPU占用率非常高（尤其是短时间内输出大量日志的实例），我们dump了JFR进一步定位：首先我们来看GC，我们的GC算法是G1，主要通过G1GarbageCollection事件进行检查：发现所有GC都是YoungGC，耗时比较正常，频率也没有明显异常。接下来，查看CPU使用率。直接查看ThreadCPULoad事件，可以看到每个线程的CPU使用率。发现reactor-http-epoll线程池中的线程占用CPU较多，加起来接近100%。这些线程就是reactor-netty处理业务的线程。观察其他实例，发现一般情况下不会出现这么高的CPU负载。那么为什么会有这么高的负载呢？通过ThreadDump查看线程栈，一探究竟。通过查看多个线程的stackdump，发现这些线程基本都在Runnable，执行的方法都是nativemethod，例如StackWalker相关（而这恰好与收集到的MethodRunnable事件比例最高JFR，基本可以确定这个线程的CPU主要是被这个栈当前对应的方法消耗的）：主要和这两个native方法有关：java.native方法。lang.StackStreamFactory$AbstractStackWalker.callStackWalk。java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames。而且需要注意的是，微服务中的线程栈会很深（150个左右），尤其是响应式代码（可能高达300个），主要是servlet和filter的设计是责任链模型，每个filter都会继续添加到堆栈中。响应式代码更是如此，层层叠叠，各种拼接观察点。上面列出的堆栈是反应堆栈。我们将介绍这两种本机方法。其实这里的代码是在做一件事，就是输出调用printlog方法的代码在log中的位置，包括类名、方法名、方法行号。在我上面给出的线程栈例子中，调用日志打印方法的代码位置信息就是这一行：at。com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，在这一行中，我们使用log.info()输出一些日志。可见Log4j2是通过获取当前线程栈来获取调用打印日志方法的代码位置。而且并不是说栈顶就是调用日志打印方法的代码位置，而是找到log4j2栈元素后的第一个栈元素就是日志打印方法的代码位置。Log4j2中如何获取栈，我们先自己想想。实现方式：首先，在Java9之前，当前线程的栈（我们这里不需要获取其他线程的栈，都是当前线程）可以通过：底层的Thread.currentThread().getStackTrace();实际上是newException().getStackTrace();所以本质是一样的。Java9之后新增了一个StackWalker接口，结合Stream接口可以更优雅的读取堆栈，即：我们来看看newException().getStackTrace();底层如何获取栈：javaClasses.cpp:然后是StackWalker，其核心底层源码是：可以看出核心是填充栈细节，不同的是一个直接填充所有信息，另一个会减少填充堆栈信息。填充栈信息，主要访问的其实是SymbolTable、StringTable等，因为我们要看的是具体的类名和方法名，而不是类和方法的地址，更不是类名的地址和方法名的地址。那么很明显：通过Exception获取栈比StackWalker需要更多的访问SymbolTable和StringTable，因为需要填充的栈更多。下面我们来测试模拟下，在不同的栈深度下，原代码会给原代码带来多大的性能下降。模拟获取调用打印日志方法的代码位置和不获取代码位置的两种方式的性能差异。下面代码我参考的Log4j2官方代码的单元测试，首先模拟了一定调用深度的栈代码：然后，编写测试代码，比较单纯执行这段代码和添加代码得到的性能差异堆。执行：查看结果：从结果可以看出，获取代码执行位置，即获取栈，会造成比较大的性能损失。同时，这种性能损失与栈填充有关。填充的堆栈越多，损失越大。可以看出StackWalker的性能优于通过异常获取栈，并且随着栈深度的增加差距越来越明显。为什么慢？String::intern带来的性能衰减程度就考验着这种性能衰减。从前面分析JVM底层源码可以看出，是因为访问了StringTable和SymbolTable。让我们模拟这种访问。其实底层访问StringTable是通过String的intern方法，也就是我们可以通过String::intern方法来模拟测试。测试代码如下：测试结果：对比StackWalkBenchmark.baseline和StackWalkBenchmark.toString的结果，可以看出bh.consume(time);本身没有性能损失。但是通过与StackWalkBenchmark.intern和StackWalkBenchmark.intern3的结果对比，发现性能下降也很严重，访问次数越多，性能下降越严重（类比之前获取stack）。结论和建议由此我们可以得出以下直观的结论：输出代码行在日志中的位置，堆栈在Java9之前是通过异常获取的，Java9之后是通过StackWalker获取的。这两种方式都需要访问SymbolTable和StringTable一样，StackWalker可以通过减少栈的填充来减少访问量。这两种方法对于性能的衰减都是非常严重的。因此，我建议：对于微服务环境，尤其是响应式微服务环境，栈深度非常深。如果大量输出日志，日志中不能包含代码位置，否则会导致严重的性能下降。我们关闭了输出代码行的位置后，在同样的压力下，CPU占用率不再那么高，整体吞吐量有了明显的提升。
