Log4j2 中是如何获取堆栈的
我们先来自己思考下如何实现:首先 Java 9 之前,获取当前线程(我们这里没有要获取其他线程的堆栈的情况,都是当前线程)的堆栈可以通过:
其中 Thread.currentThread().getStackTrace();
的底层其实就是 new Exception().getStackTrace();
所以其实本质是一样的。
Java 9 之后,添加了新的 StackWalker 接口,结合 Stream 接口来更优雅的读取堆栈,即:
我们先来看看 new Exception().getStackTrace();
底层是如何获取堆栈的:
然后是 StackWalker,其核心底层源码是:
可以看出,核心都是填充堆栈详细信息,区别是一个直接填充所有的,一个会减少填充堆栈信息。填充堆栈信息,主要访问的其实就是 SymbolTable,StringTable 这些,因为我们要看到的是具体的类名方法名,而不是类的地址以及方法的地址,更不是类名的地址以及方法名的地址。那么很明显:通过 Exception 获取堆栈对于 Symbol Table 以及 String Table 的访问次数要比 StackWalker 的多,因为要填充的堆栈多。
我们接下来测试下,模拟在不同堆栈深度下,获取代码执行会给原本的代码带来多少性能衰减。
模拟两种方式获取调用打印日志方法的代码位置,与不获取代码位置会有多大性能差异
以下代码我参考的 Log4j2 官方代码的单元测试,首先是模拟某一调用深度的堆栈代码:
然后,编写测试代码,对比纯执行这个代码,以及加入获取堆栈的代码的性能差异有多大。
执行:查看结果:
从结果可以看出,获取代码执行位置,也就是获取堆栈,会造成比较大的性能损失。同时,这个性能损失,和堆栈填充相关。填充的堆栈越多,损失越大。可以从 StackWalker 的性能优于通过异常获取堆栈,并且随着堆栈深度增加差距越来越明显看出来。
为何会慢?String::intern 带来的性能衰减程度测试
这个性能衰减,从前面的对于底层 JVM 源码的分析,其实可以看出来是因为对于 StringTable 以及 SymbolTable 的访问,我们来模拟下这个访问,其实底层对于 StringTable 的访问都是通过 String 的 intern 方法,即我们可以通过 String::intern
方法进行模拟测试,测试代码如下:
测试结果:
对比 StackWalkBenchmark.baseline
与 StackWalkBenchmark.toString
的结果,我们看出 bh.consume(time);
本身没有什么性能损失。但是通过将他们与 StackWalkBenchmark.intern
以及 StackWalkBenchmark.intern3
的结果对比,发现这个性能衰减,也是很严重的,并且访问的越多,性能衰减越严重(类比前面获取堆栈)。
结论与建议
由此,我们可以得出如下直观的结论:
- 日志中输出代码行位置,Java 9 之前通过异常获取堆栈,Java 9 之后通过 StackWalker
- 两种方式都需要访问 SymbolTable 以及 StringTable,StackWalker 可以通过减少要填充的堆栈来减少访问量
- 两种方式对于性能的衰减都是很严重的。
由此,我建议:对于微服务环境,尤其是响应式微服务环境,堆栈深度非常深,如果会输出大量的日志的话,这个日志是不能带有代码位置的,否则会造成严重的性能衰减。
我们在关闭输出代码行位置之后,同样压力下,CPU 占用不再那么高,并且整体吞吐量有了明显的提升。