一次CPU占用过高问题排查

品茗IT

发布于 2023-10-22 15:14:12

3330

发布于 2023-10-22 15:14:12

文章被收录于专栏：品茗IT品茗IT

一次CPU占用过高问题排查

一、背景

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

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 看日志

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

使用命令：

jps  #查看Java进程id
jstat -gcutil 30  #查看id为30的java进程gc情况

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

  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，当然要打印下线程栈了：

jstack 30 > stack.log

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

2.5 分析占用线程

分析占用线程，需要使用top命令：

top -H -p 30

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

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进制的)：

printf "%x\n" 976   #得到结果是3d0

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

"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版本，代码如下。

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中，这部分代码被优化为：

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方法了。