| JVM系列(三十五) JVM调优实战 | 您所在的位置：网站首页 › log4j2异步日志 › JVM系列(三十五) JVM调优实战 |
|
CPU过高的问题 问题定位 日志输出过多
这是一个本人线上经历的真实发生案例 我们线上3台4C 4G 4核4G内存的服务器， 项目结构采用Springboot项目, 然后 日志文件采用 log4j2 异步线程打印日志，这是我们事故后的分析，所以这里就给出了结论，就是log4j2异步日志打印日志导致的 这里使用 < AsyncLogger> xxx < /AsyncLogger> 异步线程打印日志，要特别特别的注意，如果你的对象比较大，而且打印日志文件很频繁，就可能造成CPU 100% 1.事故场景及过程分析事件过程分析 早上9：00 运维反馈项目CPU超过了60%，平时峰值在30-40左右，现在已经过半，排查下问题 首先 我们就采用Top， 查到自己进程ID， 然后看看Top -Hp pid 看看进程中最高的线程 然后分析，发现打印了10次，每次都是不同的线程消耗最高，然后很快消失掉，下一个线程一样，不是固定的某个线程消耗最高 然后 就Jstack 日志打印线程快照，并没有发现阻塞或者死锁或者等待的线程信息 ，也有可能是不够专业，没有分析出来，定位位置 然后这时候我们的排查 CPU飙升，是否此刻HTTP请求，或者RPC请求有剧增 打开统计报表，发现HTTP请求量和RPC请求量都是正常的，没有出现暴增的情况 然后开始排查其他思路 然后排查，看看是否有慢SQL, 是不是因为DB层面的慢SQL，导致进程查询时间长，未完成导致线程都在排队等待处理，最终线程没终止，系统假死 根据DB监控，发现也没有慢SQL，继续排查 然后排查这个时间段是否有大批量多线程操作，比如我们的大批量操作 归档/导出/报表开启等等操作，看是否有大客户在操作这些大事件，分析大事件 发现没有大客户在操作，继续排查 然后再排查 jstack 日志，看看到底什么东西在消耗CPU， 发现除了日志打印比较多，有一个比较大的日志在刷屏外，没有其余任何异常信息 都是正常的业务，也没有其他特殊请求时间紧，压力大，难定位 先解决问题 到这里 我们已经使用了全部手段， 时间已经过去了 大半个小时了，还没有定位到问题，所以我们现决定先解决问题 1.1 暂时解决问题这时候已经让运维重启了，但是重启后 还是100%，说明不是单个问题，应该是个共性问题 联系运维 ，扩容服务器机器，我们线上3台4C 4G 4核4G内存的服务器，扩容3台 8C 16G内存的临时节点机器 切换流量，把现在3台CPU 100%的 流量按照权重，3：7去切换， 20%流量打到现在3台机器上，80%流量请求达到新的扩容机器上 再去现在的3台服务器上，观察服务器信息，同时观察扩容节点 是否有相同现象 扩容节点 8C 16G内存，流量切过去后， CPU 20%左右，内存 5%左右，毫无压力 现在客户至少已经能正常访问了，然后我们静下心 分析这3台服务器问题 流量少了，但是CPU依旧在 80%以上， 说明不是线程的问题 因为现在请求量已经很少了，不是线程堆积造成的 然后我在查问题的时候，无意间发现 磁盘信息 是一个A字形的增长速率，也就是说刚才的1小时，磁盘容量比平时翻了3/4倍 这时候已经猜测是 日志的问题了，日志输出的问题，导致磁盘容量剧增 log4j2 异步写日志，日志量大，IO输出慢，导致线程阻塞，CPU飙高 然后找到那一个打印大日志的地方， 把日志去掉，运维重发项目 CPU开始下降，维持在20%左右 彻底解决问题原因分析 是因为一个业务场景，但是客户配置的不太对，把公司3000多个员工全都加载进来了 然后处理业务的时候，打印了日志信息，采用的是JsonUtil.toJson(obj) 3000多员工是一个 有一个超级大的对象列表, 客户创建的对象,里面大概3000个对象,序列化成Json 打印日志输出, 造成了CPU过高, 一直持续不下 |
| CopyRight 2018-2019 实验室设备网 版权所有 |