log4j同步机制导致的cpu飙升排查与解决

问题

组内某业务的几个相关接口均超时，上阿里云查日志一看是Dubbo调用超时，查看网络情况未发现异常，直接上Provider的机器查看占用：

# topPID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND7020 root      20   0 2538892 164144  11856 S  90.3  8.7  61:23.54 java
11022 root      20   0 2560528 241340  11920 S  0.3 12.8 311:23.23 java
26805 root      20   0   32612   4036   2472 S  0.3  0.2  24:50.95 AliYunDunUpdate
26838 root      10 -10  134120  14524   5924 S  0.3  0.8 343:05.22 AliYunDun1 root      20   0   43280   3300   2108 S  0.0  0.2   2:16.82 systemd2 root      20   0       0      0      0 S  0.0  0.0   0:01.78 kthreadd3 root      20   0       0      0      0 S  0.0  0.0   1:30.68 ksoftirqd/05 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kworker/0:0H7 root      rt   0       0      0      0 S  0.0  0.0   0:00.00 migration/08 root      20   0       0      0      0 S  0.0  0.0   0:00.00 rcu_bh                 9 root      20   0       0      0      0 S  0.0  0.0  65:15.85 rcu_sched             10 root      rt   0       0      0      0 S  0.0  0.0   2:14.65 watchdog/0             12 root      20   0       0      0      0 S  0.0  0.0   0:00.00 kdevtmpfs             13 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 netns                 14 root      20   0       0      0      0 S  0.0  0.0   0:00.00 khungtaskd             15 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 writeback             16 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kintegrityd

查询到7020这个进程有异常，在继续查看具体异常线程

1
2
3

# top -Hp 7020PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND23328 root      20   0 2538892 164144  11856 S  90.0  8.7   0:00.00 java

找到了当前异常进程下的异常线程后使用jstack查看详细情况

1	# jsack -l 6377 > error.log

1 2	# printf "%x\n" 23328 5b20

然后从jstack里查询该线程信息

1 2	# grep '18e9' error.log --color "http-bio-6379-exec-200" #8869954 daemon prio=5 os_prio=0 tid=0x00007f74a81f6800 nid=0x5b20 waiting for monitor entry [0x00007f742457f000]

最后从jstack文件定位到堆栈信息

"http-bio-7020-exec-200" #8869954 daemon prio=5 os_prio=0 tid=0x00007f74a81f6800 nid=0x5b20 waiting for monitor entry [0x00007f742457f000]java.lang.Thread.State: BLOCKED (on object monitor)at org.apache.log4j.Category.callAppenders(Category.java:204)- waiting to lock <0x00000000800371d0> (a org.apache.log4j.spi.RootLogger)at org.apache.log4j.Category.forcedLog(Category.java:391)at org.apache.log4j.Category.log(Category.java:856)at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:368)

结论

在log4j 1.x版本中，logger.info等日志记录方法是同步的，大量的日志导致线程阻塞在callAppenders()这个方法

public void callAppenders(LoggingEvent event) {int writes = 0;for(Category c = this; c != null; c=c.parent) {// Protected against simultaneous call to addAppender, removeAppender,...synchronized(c) {if(c.aai != null) {writes += c.aai.appendLoopOnAppenders(event);}if(!c.additive) {break;}}}if(writes == 0) {repository.emitNoAppenderWarning(this);}
}

临时解决办法先把日志打印级别调高至error，后续在考虑优化方案。

优化方案

升级log4j 1.x至log4j 2.x版本，同时修改相应配置

<!-- https://mvnrepository.com/artifact/org.apache.logging.log4j/log4j-core -->
<dependency><groupId>org.apache.logging.log4j</groupId><artifactId>log4j-core</artifactId><version>2.11.2</version>
</dependency>

使用log4j 桥接类
1
log4j-1.2-api-2.6.2
如果是使用Spring Boot开发的话，就不会出现此问题，Spring Boot默认使用的时logback是不会有同步问题

参考：log4j平稳升级到log4j2

https://www.cnblogs.com/hujunzheng/p/9937097.html

log4j同步机制导致的cpu飙升排查与解决相关推荐

Java程序CPU飙升排查，找出死循环代码
windows环境下cpu飙升问题线上某台runtime机器(windows Server)cpu报警,这种情况初步就是代码里面死循环了,先把机器下线了保证不再有新的任务分配进来,然而cpu使用依然 ...
让人抓头的Java并发(四) 阻塞队列--CPU飙升排查案例
在上一篇文章中给大家介绍了牛批的AQS,大致讲解了JUC中同步的思路.本来还没想好这一篇应该写点什么,刚好上周某个同事的代码出现问题,排查后发现是使用阻塞队列不当导致的,所以本篇决定介绍下阻塞队列. ...
简单的cpu飙升排查方法
1先来一段飙升代码 public class FindJavaThreadInTaskManager {public static void main(String[] args) {Thread t ...
线上服务导致cpu飙升问题排查
一.故障说明昨晚突然收到线上服务器cpu报警,登录监控平台看了下发现cpu瞬间飙升到60%.第一反应就是使用top命令去查看,发现是一个java进程.于是立刻使用jps -l命令定位到该java进程 ...
线上频繁发生Full GC 如何调优？如何快速定位OOM、cpu飙升、线程死锁等问题
文章目录 1. jvm调优命令.工具介绍 ①:jps ②:jmap 查看应用中各实例生成情况快速定位内存突然飙升导致的OOM异常查看堆内存使用情况 ③:Jstack 检测线程死锁快速定位导致cp ...
cpu飙升死循环_记一次CPU飙升BUG
一．前言上线后,CPU飙升到100%,怎么办?马上重启?大错特错,马上重启只会让这个雷石沉大海,治标不不治本,等待你的下次的历史重演! 二．现象监控告警,某机器的CPU飙升到100% 三．分析第 ...
【Android 逆向】函数拦截 ( CPU 高速缓存机制 | CPU 高速缓存机制导致函数拦截失败 )
文章目录一.CPU 高速缓存机制二.CPU 高速缓存机制导致函数拦截失败一.CPU 高速缓存机制 CPU 架构模型中 , 指令在开始时 , 存放在内存中 , 如 : /proc/pid/m ...
cpu飙升死循环_java排查一个线上死循环cpu暴涨的过程分析
问题,打一个页面cpu暴涨,打开一次就涨100%,一会系统就卡的不行了. 排查方法,因为是线上的linux,没有用jvm监控工具rim链接上去. 只好用命令排查: top cpu排序,一个java进程 ...
下载丨8月数据库技术通讯：不合理业务设计导致CPU飙升
为了及时共享行业案例,通知共性问题,达成共享和提前预防,我们整理和编辑了<云和恩墨技术通讯>,通过对过去一段时间的知识回顾,故障归纳,以期提供有价值的信息供大家参考.同时,我们也希望能够将 ...

log4j同步机制导致的cpu飙升排查与解决

问题

结论

优化方案

log4j同步机制导致的cpu飙升排查与解决相关推荐

最新文章

热门文章