个人创作约定：本人声明所有文章均为原创，如有引用任何文章，会注明，如有疏漏，欢迎批评指正。如果您在网上发现有人抄袭本文，请举报并积极向本github仓库提交issue。感谢大家的支持~本文是《WhyISuggest》系列的第二篇，在群里对后台开发的一些开发建议和开发规范要求进行讲解、分析和解读，相信能帮助大家在面对high的时候避免一些坑-并发业务。过去回顾：为什么我建议在复杂但性能关键的表上的所有查询中添加强制索引？业务刚上线的时候，我们的上线日志级别是INFO，在日志内容中输出代码位置。例如，格式为：2022-03-0219:57:59.425INFO[service-apiGateway,,][35800][main][org.springframework.cloud.gateway.route.RouteDefinitionRouteLocator:88]:LoadedRoutePredicateFactory[查询]我们使用的日志框架是Log4j2，方法是异步日志记录。Log4j2的Disruptor的WaitStrategy采用了比较均衡的Sleep，占用CPU比较小，即配置：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相关的（而这个是和JFR中收集的Method匹配的）Runnable事件中占比最高基本可以确定该线程的CPU主要被当前栈对应的方法消耗）：主要和这两个native方法有关：java.lang.StackStreamFactory$AbstractStackWalker.callStackWalkjava.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames并且需要注意的是，微服务中的线程栈会很深（150个左右），尤其是响应式代码（可能高达300个），主要是servlet和filter的设计是责任链模型，并且每个过滤器都会继续添加到堆栈中。响应式代码更是如此，层层叠叠，各种拼接观察点。上面列出的堆栈是反应堆栈。我们将介绍这两种本机方法。其实这里的代码是在做一件事，就是输出调用printlog方法的代码在log中的位置，包括类名、方法名、方法行号。在我上面给出的线程栈例子中，调用printlog方法的代码位置信息是这一行：atcom.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，在这一行中，我们使用log.info()输出一些日志。可见Log4j2是通过获取当前线程栈来获取调用打印日志方法的代码位置。而且并不是说栈顶就是调用日志打印方法的代码位置，而是找到log4j2栈元素后的第一个栈元素就是日志打印方法的代码位置。Log4j2中如何获取栈，我们先自己想想。实现方式：首先，在Java9之前，当前线程的栈（我们这里不需要获取其他线程的栈，都是当前线程）可以通过：.png获取）whereThread.currentThread().getStackTrace();底层其实就是newException().getStackTrace();所以本质是一样的。Java9之后新增了一个StackWalker接口，结合Stream接口可以更优雅的读取堆栈，即：.png）我们先来看看newException().getStackTrace();底层如何获取栈：javaClasses。cpp.png），然后是StackWalker。其核心底层源码为：.png）可见其核心是填写堆栈细节。不同的是，一种直接填充所有信息，另一种会减少填充堆栈信息。填充栈信息，主要访问的其实是SymbolTable、StringTable等，因为我们要看的是具体的类名和方法名，而不是类和方法的地址，更不是类名的地址和方法名的地址。那么很明显：通过Exception获取栈比StackWalker需要更多的访问SymbolTable和StringTable，因为需要填充的栈更多。下面我们来测试模拟下，在不同的栈深度下，原代码会给原代码带来多大的性能下降。模拟两种方法获取调用printlog方法的代码位置，如果不获取代码位置会有多大的性能差异？以下代码我参考了Log4j2官方代码的单元测试，写测试代码，比较单纯执行这段代码和加上获取栈的代码的性能差异。.png)Execution:检查结果：.png)从结果可以看出，获取代码执行位置，即获取栈，会造成比较大的性能损失。同时，这种性能损失与栈填充有关。填充的堆栈越多，损失越大。可以看出StackWalker的性能优于通过异常获取栈，并且随着栈深度的增加差距越来越明显。为什么慢？String::intern带来的性能衰减程度就考验着这种性能衰减。从前面分析JVM底层源码可以看出，是因为访问了StringTable和SymbolTable。让我们模拟这种访问。其实底层对于StringTable的访问都是通过String的intern方法，也就是我们可以通过String::intern方法来模拟测试。测试代码如下：.png)测试结果：.png)比较StackWalkBenchmark.baseline和StackWalkBenchmark.toString的结果，我们可以看到bh.consume(time);本身没有性能损失。但是通过与StackWalkBenchmark.intern和StackWalkBenchmark.intern3的结果对比，发现性能下降也很严重，访问越多，性能下降越严重（类比之前获取stack）。结论和建议由此我们可以得出以下直观的结论：输出代码行在日志中的位置，堆栈在Java9之前是通过异常获取的，Java9之后这两种方法都需要通过StackWalker访问SymbolTable和StringTable.StackWalker可以减少所需的填充堆栈次数以减少访问次数，这对于性能下降是非常严重的。因此，我建议：对于微服务环境，尤其是响应式微服务环境，栈深度非常深。如果大量输出日志，日志中不能包含代码位置，否则会导致严重的性能下降。我们关闭了输出代码行的位置后，在同样的压力下，CPU占用率不再那么高，整体吞吐量有了明显的提升。微信搜索“全是哈希的干货”，关注公众号，天天刷，轻松提升技术，赢各种优惠：我会经常发一些各种框架的官方社区的好消息和视频资料，并加个人翻译字幕到以下地址（含上公众号），欢迎关注：知乎：https://www.zhihu.com/people/...B站：https://space.bilibili.com/31...
