一次CPU占用过高问题排查

2023-10-22 15:14:12 浏览数 (1)

一次CPU占用过高问题排查

一、背景

事情是这样的:我们有一个应用跑了一段时间,一直没有报错,然后这两天突然告警起来了:

代码语言:javascript复制
Metric: pod:cpu:pod_usage_limit_rate all(#3): 0.909469 >= 0.8 
报警Note: cpu使用率大于80% 报警时间: 2022-04-26 15:06:43

一看cpu使用率,90%了,赶紧重建。然而,还不到一天,又开始告警了!

这里,记录下排查问题的过程。

如果大家正在寻找一个java的学习环境,或者在开发中遇到困难,可以加入我们的java学习圈,点击即可加入,共同学习,节约学习时间,减少很多在学习中遇到的难题。

二、初排查

2.1 看日志
代码语言:javascript复制
2022-04-26 15:00:10,665 [TID: 4c8c815720764c00b7d6c8e1b979e680.106.16509549958647375]  [ OkHttp https://XXXX.com/...:55612524 ] - [ ERROR ] -  [ com.XXX.OkHttpUtil ] failed post to: https://XXXX.com/report, reqTraceid: c6bb705778574088accdf25989f1db7a, exp: timeout

正常的接口超时,这会引起cpu过高?

我不信。难道是第三方接口超时导致线程堆积?

2.2 看监控

线程数和句柄没有显著增加,看来线程没有堆积。

2.3 看gc

使用命令:

代码语言:javascript复制
jps  #查看Java进程id
jstat -gcutil 30  #查看id为30的java进程gc情况

结果大吃一惊,竟然没有问题,并没有fullgc,ygc水平还好,如图。

代码语言:javascript复制
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00 100.00  81.82  59.98  96.58  94.77    562   33.248     0    0.000   33.248
2.4 打印线程栈

分析cpu,当然要打印下线程栈了:

代码语言:javascript复制
jstack 30 > stack.log

把stack.log下载下来,观察,然而这时候是看不出来啥的,因为你并不知道哪个线程占用高。

2.5 分析占用线程

分析占用线程,需要使用top命令:

代码语言:javascript复制
top -H -p 30

查看进程id为30的线程信息,结果是无序的,按键大写P,可以根据cpu占用率排序。TOP命令的结果如下:

代码语言:javascript复制
Threads: 292 total,   1 running, 291 sleeping,   0 stopped,   0 zombie
%Cpu0  :  92.7/0.0    93[|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||       ]
    233 root      20   0 6387.9m   1.9g   0.6  47.9   0:01.01 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    255 root      20   0 6387.9m   1.9g   0.6  47.9   0:45.05 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    334 root      20   0 6387.9m   1.9g   0.6  47.9   0:23.70 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
     60 root      20   0 6387.9m   1.9g   0.6  47.9   3:54.12 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
top - 15:46:53 up 16:13,  0 users,  load average: 1.01, 1.08, 1.01
Threads: 291 total,   1 running, 290 sleeping,   0 stopped,   0 zombie
%Cpu0  :  98.8/0.0    99[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| ]
GiB Mem : 51.4/4.0      [                                                                                                    ]
GiB Swap:  0.0/0.0      [                                                                                                    ]

    PID USER      PR  NI    VIRT    RES  %CPU  %MEM     TIME  S COMMAND                                                                                      
    964 root      20   0 6387.9m   1.9g  16.2  48.7   6:12.69 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
   1135 root      20   0 6387.9m   1.9g  14.4  48.7   0:32.53 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    976 root      20   0 6387.9m   1.9g  13.1  48.7   4:22.01 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
   1073 root      20   0 6387.9m   1.9g  11.9  48.7   2:53.95 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
   1087 root      20   0 6387.9m   1.9g  11.2  48.7   1:06.14 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    946 root      20   0 6387.9m   1.9g  10.6  48.7   6:39.02 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    937 root      20   0 6387.9m   1.9g  10.0  48.7   6:43.75 R /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    333 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.69 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    265 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.68 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    337 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.64 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    141 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.77 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    124 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.73 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf  
    140 root      20   0 6387.9m   1.9g   0.6  48.7   0:23.72 S /opt/java/openjdk/bin/java -Dskywalking_specific_conf 

从这里,我们可以看到一些占用比较高的线程。

三、找具体原因

3.1 定位代码位置

上面已经打印出了占用比较高的线程,随便选取一个976,因为我看它10几分钟前就存在了。

转换成16进制(因为jstack命令打印出的线程id是16进制的):

代码语言:javascript复制
printf "%xn" 976   #得到结果是3d0

然后到上面2.4中打印出的stack.log中搜索0x3d0的线程:

代码语言:javascript复制
"OkHttp https://XXX.com/..." #1415 prio=5 os_prio=0 tid=0x00007f254db26000 nid=0x3d0 waiting for monitor entry [0x00007f25097bb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at okhttp3.Dispatcher.finished(Dispatcher.java:201)
        - waiting to lock <0x00000006c2a9f1a0> (a okhttp3.Dispatcher)
        at okhttp3.Dispatcher.finished(Dispatcher.java:190)
        at okhttp3.RealCall$AsyncCall.execute$original$eQ9Amsnx(RealCall.java:164)
        at okhttp3.RealCall$AsyncCall.execute$original$eQ9Amsnx$accessor$FDrMXD3M(RealCall.java)
        at okhttp3.RealCall$AsyncCall$auxiliary$hQ5KC3HT.call(Unknown Source)
        at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:86)
        at okhttp3.RealCall$AsyncCall.execute(RealCall.java)
        at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

这货装逼了还不走,一下子就逮到了。

问题就出在okhttp3.Dispatcher.finished(Dispatcher.java:201)这句话,我们使用的是okhttp3的3.10.0版本,代码如下。

代码语言:javascript复制
void finished(AsyncCall call) {
  finished(runningAsyncCalls, call, true);
}
void finished(RealCall call) {
  finished(runningSyncCalls, call, false);
}
private <T> void finished(Deque<T> calls, T call, boolean promoteCalls) {
  int runningCallsCount;
  Runnable idleCallback;
  synchronized (this) { //201行
    if (!calls.remove(call)) throw new AssertionError("Call wasn't in-flight!");
    if (promoteCalls) promoteCalls();
    runningCallsCount = runningCallsCount();
    idleCallback = this.idleCallback;
  }

  if (runningCallsCount == 0 && idleCallback != null) {
    idleCallback.run();
  }
}

private void promoteCalls() {
  if (runningAsyncCalls.size() >= maxRequests) return; // Already running max capacity.
  if (readyAsyncCalls.isEmpty()) return; // No ready calls to promote.

  for (Iterator<AsyncCall> i = readyAsyncCalls.iterator(); i.hasNext(); ) {
    AsyncCall call = i.next();

    if (runningCallsForHost(call) < maxRequestsPerHost) {
      i.remove();
      runningAsyncCalls.add(call);
      executorService().execute(call);
    }

    if (runningAsyncCalls.size() >= maxRequests) return; // Reached max capacity.
  }
}
3.2 分析代码

在OkHttpClient中final Dispatcher dispatcher; 作为成员对象,而我们代码中OkHttpClient作为连接池是单例的,这里是对dispatcher做synchronized,好危险。

追踪代码发现,在finished的调用方法中,我们方法中使用的是异步AsyncCall,而这里synchronized方法中的promoteCalls被置为true。所以会调用promoteCalls()方法, 而promoteCalls()方法中会继续调用executorService().execute(call);,就是这里,问题大了,synchronized中执行http请求,那上面2.1中的超时不就长时间占用锁了?怪不得进程blocked了。

关于线程的BLOCKED,需要知道:

  • java.lang.Thread.State: BLOCKED:等待监视器锁而被阻塞的线程的线程状态,当进入 synchronized 块/方法或者在调用 wait()被唤醒/超时之后重新进入 synchronized 块/方法, 但是锁被其它线程占有,这个时候被操作系统挂起,状态为阻塞状态。若是有线程长时间处于 BLOCKED 状态,要考虑是否发生了死锁(deadlock)的情况。
  • blocked的线程不会消耗cpu,但频繁的频繁切换线程上下文会导致cpu过高。线程被频繁唤醒,而又由于抢占锁失败频繁地被挂起. 因此也会带来大量的上下文切换, 消耗系统的cpu资源。

四、解决方案

其实,okttp关于这个问题已经有过解答:

https://github.com/square/okhttp/pull/4581

https://github.com/palantir/conjure-java-runtime/pull/940

解决方案就简单多了:升级okhttp到3.14.9,虽然目前最新稳定版本为4.9.3,但是OkHttp 4发布,从Java切换到Kotlin。谨慎一点,还是小版本升级吧。

在3.14.9中,这部分代码被优化为:

代码语言:javascript复制
private boolean promoteAndExecute() {
  assert (!Thread.holdsLock(this));

  List<AsyncCall> executableCalls = new ArrayList<>();
  boolean isRunning;
  synchronized (this) {
    for (Iterator<AsyncCall> i = readyAsyncCalls.iterator(); i.hasNext(); ) {
      AsyncCall asyncCall = i.next();

      if (runningAsyncCalls.size() >= maxRequests) break; // Max capacity.
      if (asyncCall.callsPerHost().get() >= maxRequestsPerHost) continue; // Host max capacity.

      i.remove();
      asyncCall.callsPerHost().incrementAndGet();
      executableCalls.add(asyncCall);
      runningAsyncCalls.add(asyncCall);
    }
    isRunning = runningCallsCount() > 0;
  }

  for (int i = 0, size = executableCalls.size(); i < size; i  ) {
    AsyncCall asyncCall = executableCalls.get(i);
    asyncCall.executeOn(executorService());
  }

  return isRunning;
}

执行HTTP请求被移出了synchronized方法了。

五、结论

没有结论是不完整的,但是低版本的jar是需要升级的,勿以麻烦而不为,勿以鱼小而摸之。

0 人点赞