关于java:为什么我建议线上高并发量的日志输出的时候不能带有代码位置

2次阅读

共计 3315 个字符，预计需要花费 9 分钟才能阅读完成。

集体创作公约：自己申明创作的所有文章皆为本人原创，如果有参考任何文章的中央，会标注进去，如果有疏漏，欢送大家批评。如果大家发现网上有剽窃本文章的，欢送举报，并且踊跃向这个 github 仓库提交 issue，谢谢反对~

本文是“为什么我倡议”系列第二篇，本系列中会针对一些在高并发场景下，我对于组内后盾开发的一些开发倡议以及开发标准的要求进行阐明和剖析解读，置信能让各位在面对高并发业务的时候避开一些坑。
往期回顾：

为什么我倡议在简单然而性能要害的表上所有查问都加上 force index

在业务一开始上线的时候，咱们线上日志级别是 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 采纳了比拟均衡 CPU 占用比拟小的 Sleep，即配置了：AsyncLoggerConfig.WaitStrategy=Sleep。随着业务的增长，咱们发现常常有的实例 CPU 占用十分之高（尤其是那种短时间内有大量日志输入的），咱们 dump 了 JFR 进行进一步定位：

首先咱们来看 GC，咱们的 GC 算法是 G1，次要通过 G1 Garbage Collection 这个事件查看：

发现 GC 全副为 Young GC，且耗时比拟失常，频率上也没有什么显著异样。

接下来来看，CPU 占用相干。间接看 Thread CPU Load 这个事件，看每个线程的 CPU 占用状况。发现 reactor-http-epoll 线程池的线程，CPU 占用很高，加在一起，靠近了 100%。

这些线程是 reactor-netty 解决业务的线程，察看其余实例，发现失常状况下，并不会有这么高的 CPU 负载。那么为啥会有这么高的负载呢？通过 Thread Dump 来看一下线程堆栈有何发现.

通过查看多个线程堆栈 dump，发现这些线程根本都处于 Runnable，并且执行的办法是原生办法，和 StackWalker 相干，例如（并且这个与 JFR 中采集的 Method Runnable 事件中占比最高的吻合，能够根本确认这个线程的 CPU 次要耗费在这个堆栈以后对应的办法上）：

次要和这 两个原生办法无关：

java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk
java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames

并且须要留神 微服务中线程堆栈会很深（150 左右），对于响应式代码更是如此（可能会到 300），次要是因为 servlet 与 filter 的设计是责任链模式，各个 filter 会一直退出堆栈。响应式的代码就更是这样了，一层套一层，各种拼接观察点。下面列出的堆栈就是响应式的堆栈。

会到那两个原生办法，其实这里的代码是在做一件事，就是日志中要输入调用打印日志办法的代码地位，包含类名，办法名，办法行数这些。在下面我给出的线程堆栈的例子中，调用打印日志办法的代码地位信息就是这一行：at com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，这一行中，咱们应用 log.info() 输入了一些日志。

能够看出，Log4j2 是通过获取以后线程堆栈来获取调用打印日志办法的代码地位的。并且并不是堆栈中的栈顶就是调用打印日志办法的代码地位，而是找到 log4j2 堆栈元素之后的第一个堆栈元素才是打印日志办法的代码地位

咱们先来本人思考下如何实现：首先 Java 9 之前，获取 以后线程（咱们这里没有要获取其余线程的堆栈的状况，都是以后线程）的堆栈能够通过：

.png)
其中 Thread.currentThread().getStackTrace(); 的底层其实就是 new Exception().getStackTrace(); 所以其实实质是一样的。

Java 9 之后，增加了新的 StackWalker 接口，联合 Stream 接口来更优雅的读取堆栈，即：
.png)

咱们先来看看 new Exception().getStackTrace(); 底层是如何获取堆栈的：

javaClasses.cpp
.png)

而后是 StackWalker，其外围底层源码是：
.png)

能够看出，外围都是填充堆栈详细信息，区别是一个间接填充所有的，一个会缩小填充堆栈信息。填充堆栈信息，次要拜访的其实就是 SymbolTable，StringTable 这些，因为咱们要看到的是具体的类名办法名，而不是类的地址以及办法的地址，更不是类名的地址以及办法名的地址。那么很显著：通过 Exception 获取堆栈对于 Symbol Table 以及 String Table 的拜访次数要比 StackWalker 的多，因为要填充的堆栈多。

咱们接下来测试下，模仿在不同堆栈深度下，获取代码执行会给本来的代码带来多少性能衰减。

以下代码 我参考的 Log4j2 官网代码的单元测试，首先是模仿某一调用深度的堆栈代码：

.png)
而后，编写测试代码，比照纯执行这个代码，以及退出获取堆栈的代码的性能差别有多大。

.png)

执行：查看后果：

.png)
从后果能够看出，获取代码执行地位，也就是获取堆栈，会造成比拟大的性能损失 。同时，这个性能损失，和堆栈填充相干。填充的堆栈越多，损失越大。能够从 StackWalker 的性能优于通过异样获取堆栈，并且随着堆栈深度减少差距越来越显著看进去。

这个性能衰减，从后面的对于底层 JVM 源码的剖析，其实能够看进去是因为对于 StringTable 以及 SymbolTable 的拜访，咱们来模仿下这个拜访，其实底层对于 StringTable 的拜访都是通过 String 的 intern 办法，即咱们能够通过 String::intern 办法进行模仿测试，测试代码如下：
.png)

测试后果：
.png)

比照 StackWalkBenchmark.baseline 与 StackWalkBenchmark.toString 的后果，咱们看出 bh.consume(time); 自身没有什么性能损失。然而通过将他们与 StackWalkBenchmark.intern 以及 StackWalkBenchmark.intern3 的后果比照，发现这个性能衰减，也是很重大的，并且拜访的越多，性能衰减越重大（类比后面获取堆栈）。

由此，咱们能够得出如下直观的论断：