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

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

8月前
1226706

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

问题现象

压测过程中发现应用服务器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

分类:
标签:
请先登录,再评论

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

为你推荐

从猫蛇之战再看内核戏CPU
连续写了几天的代码,有些疲倦,吃过晚饭,换个工作方式,继续和大家聊猫蛇之战。蛇不仅丑陋,而且可能伤人害命,是邪恶的象征。猫与蛇战,代表着讨伐奸邪,是正义之战。猫与蛇战,技艺娴熟,举重若轻,叫人拍手叫绝
那些吃CPU的大户
最近沉浸在代码的世界里,处于两耳不闻窗外事的状态。今晚偶有闲暇,看了一眼任务管理器,IDLE进程的时间居然有800多小时,还有多个进程的CPU净时间达到小时级别。如下图所示,IDLE进程的CPU净时间
记一次线上服务CPU 100%的处理过程
告警正在开会,突然钉钉告警声响个不停,同时市场人员反馈客户在投诉系统登不进了,报504错误。查看钉钉上的告警信息,几台业务服务器节点全部报CPU超过告警阈值,达100%。赶紧从会上下来,SSH登录服务
又一次生产 CPU 高负载排查实践
前言前几日早上打开邮箱收到一封监控报警邮件:某某 ip 服务器 CPU 负载较高,请研发尽快排查解决,发送时间正好是凌晨。其实早在去年我也处理过类似的问题,并记录下来:《[一次生产 CPU 100%
什么会导致Java应用程序的CPU使用率飙升?
问题 无限循环的while会导致CPU使用率飙升吗?经常使用Young GC会导致CPU占用率飙升吗?具有大量线程的应用程序的CPU使用率是否较高?CPU使用率高的应用程序的线程数是多少?处于BLOC
怎么排查CPU飙升
怎么排查CPU飙升线上有些系统,本来跑的好好的,突然有一天就会出现报警,CPU使用率飙升,然后重启之后就好了。例如,多线程操作一个线程不安全的list往往就会出现这种现象。那么怎么定位到具体的代码范围
这些排查内存问题的命令,你用过多少?
我相信大家都遇到过内存占用率过高的情况,在排查过程中,我们会用到一些命令或工具,下面来看下这些你都用过吗? top 命令首先比较常用的就是 top 命令,是性能监控的常用命令,该命令可以实时显示系统中
使用XPocket插件top_x 解决cpu高及 cpu_load高的一般思路
本文使用了xpocket工具包的插件链接xpocket地址:[https://plugin.xpocket.perfma.com](https://plugin.xpocket.perfma.com)