文章>记一次日志pattern参数设置不合理导致高CPU问题的排查>

记一次日志pattern参数设置不合理导致高CPU问题的排查

杭盖
cpu
日志
爬栈
1月前

此问题是在为客户的系统进行压测时发现的,为了降低性能风险,对其进行了分析和改进。分享此案例也希望能给同学们一些启发和提醒。

问题现象

压测过程中发现应用服务器CPU消耗较高

分析过程

首先根据链路/分析平台监控到的数据作出分析

问题1: 有没有哪个方法集中消耗了大量的CPU?

从XLand热点分析看到单单一个爬栈操作就占用了当前CPU使用率的30%左右

问题2: 是谁导致了爬栈操作?

从方法调用栈可以看出是logback日志组件中触发了爬栈操作
1.png

结合反编译工具或直接查看源码进行分析

问题3: 什么情况下logback会触发爬栈操作呢?

查看logback源码可以发现如下四个方法会触发爬栈操作:
2.png
3.png
4.png
5.png

如上四个方法都会调用如下方法进行爬栈操作
6.png
7.png

官方文档说明和建议

官方文档也说明这四种日志pattern参数会导致性能问题,不建议使用

转换符 作用
F / file 输出执行记录请求的java源文件名。尽量避免使用,除非执行速度不造成任何问题。
C {length } class {length } 输出执行记录请求的调用者的全限定名。参数与上面的一样。尽量避免使用,除非执行速度不造成任何问题。
M / method 输出执行日志请求的方法名。尽量避免使用,除非执行速度不造成任何问题。
L / line 输出执行日志请求的行号。尽量避免使用,除非执行速度不造成任何问题。

性能风险点

1.频繁爬栈会占用大量cpu

a)日志打印越频繁,爬栈操作也就越频繁
b)获取到方法栈后会有一个循环赋值的操作,方法栈越深,循环赋值次数就越多,单次爬栈消耗的cpu也就越多

2.频繁爬栈会影响响应时间

(1)爬栈会有一个短暂的STW(stop the world),会暂停应用线程的执行,所以在方法中打印日志越频繁,STW次数也就越多,对响应时间会有少量影响
(1)频繁爬栈会产生大量StackTraceElement[] 临时对象,进而导致更频繁的young gc,而young gc使用的是复制算法,也是会STW的。所以频繁的gc不仅会浪费更多的cpu在垃圾回收上,还会导致更多的应用线程暂停,从而影响到响应时间

优化建议

部分开发会在日志中输出行号或者方法名,是为了更快速的定位一些异常问题,而异常日志通常会被定义成ERROR或者WARN级别,所以建议将ERROR/WARN级别的日志和INFO/DEBUG级别的日志分别设置pattern,允许异常日志输出行号和方法名等信息,常规日志则不允许
8.png

11960 阅读
请先登录,再评论

评论列表

暂无回复,快来写下第一个回复吧~