背景

将log4j.xml的日志级别从error调整为info后,进行压测发现CPU占用很高达到了90%多(之前也就是50%,60%的样子).

问题排查

排查思路:  看进程中的线程到底执行的是什么,导致CPU占用较高.

1. 使用top命令查看到底是哪个应用占用的cpu比较高

左边的图是日志级别为info CPU较高的服务器, 右边为输出级别为error cpu正常的服务器.

2. 使用top -Hp pid 命令查看进程中的线程

可以看到左边运行中的线程比右边要多(实际上左边运行状态的线程常态为30左右),接下来通过jstack命令查看这些线程到底在做什么记一次排查CPU高的问题-LMLPHP

3. 将步骤2 找到的线程的pid 使用printf %x pid 转换为16进制,第四步使用

4. 使用jstack命令查找这个线程到底在做什么

jstack [进程]|grep -A 10 [线程的16进制]

示例: jstack 21125|grep -A 10 52f1 

-A 10表示查找到所在行的后10行。21233用计算器转换为16进制52f1,注意字母是小写。

这时候就可以看到具体线程执行的堆栈信息了, 可以看到有大量的线程都在执行一下的代码:

按照堆栈信息层层追踪找到了关键的属性:

记一次排查CPU高的问题-LMLPHP

查看配置文件:

记一次排查CPU高的问题-LMLPHP

该配置配置为true时log4j2将会获取堆栈的快照(snapshot),并遍历堆栈跟踪以查找位置信息,因此会消耗较多的时间.

将该配置关闭,解决了CPU高的问题

总结

排查CPU高的问题的思路:

1. 先查看对应的进程,看看是哪个进程消耗的多

2. 然后再去看进程中的线程到底在执行什么代码. 

3.找到了具体执行的代码就可以具体问题具体分析了.

11-06 00:12