CPU飙升排查思路

2021-07-09 17:01:31 阅读：188 来源： 互联网

标签：Category 20 0.0 飙升排查 java 00.00 root CPU

最近公司有个需求是对接E签宝的，也就是CA认证，大致的情况就是我们拿着文件去E签宝做CA认定，简单的理解就是拿着合同去E签宝盖章。
因为是对接三方的吗，所以在调E签宝服务的时候我就用log.info()把请求参数给打印了出来，方便看组装的参加，排查问题，参数中就包含我们的合同文件流，所以整个参数是一个大对象。在做压测的时候发现CPU很快就飙升到100%，并且耗时很久。但是我把打印日志的log.info()去掉之后，CPU和耗时马上就降下来了。下面开始排查这个问题：

首先使用top命令查看进程运行情况：

# top
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 7020 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 AliYunDun
    1 root      20   0   43280   3300   2108 S  0.0  0.2   2:16.82 systemd
    2 root      20   0       0      0      0 S  0.0  0.0   0:01.78 kthreadd
    3 root      20   0       0      0      0 S  0.0  0.0   1:30.68 ksoftirqd/0
    5 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kworker/0:0H
    7 root      rt   0       0      0      0 S  0.0  0.0   0:00.00 migration/0
    8 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这个进程有异常，在继续查看具体异常线程。

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

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

# jstack -l 6377 > error.log

将线程ID打印成16进制形式
# printf "%x\n" 23328
5b20

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

# 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 中，logger.info等日志记录方法是同步的（使用了synchronized），大量的日志导致线程阻塞在callAppenders()这个方法，也就是这个地方导致压测阻塞，响应耗时比较久的问题。

public void callAppenders(LoggingEvent event) {
        int writes = 0;

        for(Category c = this; c != null; c = c.parent) {
            synchronized(c) {
                if (c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }

                if (!c.additive) {
                    break;
                }
            }
        }

        if (writes == 0) {
            this.repository.emitNoAppenderWarning(this);
        }

    }

标签：Category,20,0.0,飙升,排查,java,00.00,root,CPU
来源： https://blog.csdn.net/maoyeqiu/article/details/118610458

本站声明： 1. iCode9 技术分享网（下文简称本站）提供的所有内容，仅供技术学习、探讨和分享；
2. 关于本站的所有留言、评论、转载及引用，纯属内容发起人的个人观点，与本站观点和立场无关；
3. 关于本站的所有言论和文字，纯属内容发起人的个人观点，与本站观点和立场无关；
4. 本站文章均是网友提供，不完全保证技术分享内容的完整性、准确性、时效性、风险性和版权归属；如您发现该文章侵犯了您的权益，可联系我们第一时间进行删除；
5. 本站为非盈利性的个人网站，所有内容不会用来进行牟利，也不会利用任何形式的广告来间接获益，纯粹是为了广大技术爱好者提供技术内容和技术思想的分享性交流网站。

ICode9

CPU飙升排查思路

结论