2022-3-27更新,感谢这些网友的留言,补充如下:
个人创作公约:本人声明创作的所有文章皆为自己原创,如果有参考任何文章的地方,会标注出来,如果有疏漏,欢迎大家批判。如果大家发现网上有抄袭本文章的,欢迎举报,并且积极向这个 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 堆栈元素之后的第一个堆栈元素才是打印日志方法的代码位置