一次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版本,代码如下。
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是需要升级的,勿以麻烦而不为,勿以鱼小而摸之。