前言
上文说道,笔者在优化RPC调用的逻辑,刚有眉目,进入压测阶段,发现CPU使用率及其高的问题,经过排查和反思,总结此文。
CPU使用率
**CPU使用率:**简单来讲,运行的程序占用的CPU资源,表示你的机器在某个时间点的运行程序的情况。 举个栗子::A进程占用10ms,然后B进程占用30ms,然后空闲60ms,再又是A进程占10ms,B进程占30ms,空闲60ms;如果在一段时间内都是如此,那么这段时间内的占用率为40%。
真实情况
- 真实状况(top指令 381.8%)如下图所示:
- 换成图就是。。。(CPU使用率快接近100%):
排查流程
top + jstack
- 执行
top
指令获取进程CPU使用率:
$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
883 work 20 0 22.1g 1.7g 10m S 2.7 0.9 168:10.94 java
233886 work 20 0 14960 2024 1804 R 0.3 0.0 0:00.01 top
1 work 20 0 17040 3628 2668 S 0.0 0.0 0:13.89 sh
- 找到CPU使用率最高的进程
PID
,进一步使用-H
选项观察该进程下线程的CPU使用率:
$ top -p 883 -H
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1552 work 20 0 22.1g 1.7g 10m S 0.3 0.9 1:49.06 java
1553 work 20 0 22.1g 1.7g 10m S 0.3 0.9 1:49.77 java
- 使用
jstack
打出线程栈信息,注意命令格式jstack {processId} | grep {threadId}
,其中threadId
为16进制。
# 1552的16进制为610
$ jstack 883 | grep 610 -C 10
...
"Tiresias.util.Worker[0]" prio=10 tid=0x00007ff64cd06000 nid=0x610 waiting on condition [0x00007ff4bcdcc000]
...
- 这样,就可以一步一步接近真相,根据分析线程栈信息,来一步步分析调用,查找问题。
show-busy-java-threads
- 尽管上述方法可以进行分析,但是有些繁琐,那就用线程的脚本把~
- show-busy-java-threads脚本可以直接打印出CPU使用率高的线程的调用栈。
show-busy-java-threads -p <指定的Java进程Id>
问题分析
最后,使用show-busy-java-threads
得到线程栈信息,如下图。
[1] Busy(98.9%) thread(1730/0x6c2) stack of java process(968) under user(work):
"pool-4-thread-1" prio=10 tid=0x00007fd24c005800 nid=0x6c2 runnable [0x00007fd3207c0000]
java.lang.Thread.State: RUNNABLE
at java.util.HashMap.getEntry(HashMap.java:347)
at java.util.HashMap.containsKey(HashMap.java:335)
at java.util.HashSet.contains(HashSet.java:184)
...
- 可以看到,是在
HashSet
的contains
方法出了问题,终于知道问题的根源了。
多线程环境下
HashSet
的并发问题,HashSet
是由HashMap
实现。 找了很多资料,与HashMap死循环问题有关。 笔者不擅长原理介绍,请看参考文献中https://coolshell.cn/articles/9606.html。
解决方案
- 改为
ConcurrentHashMap
, 定一个合适的initialCapacity
。 - 笔者遇到的问题,是业务逻辑,可以使用其他方式避免,这种调用。
结语
这次的代码优化感觉收获颇丰,本身对异常定位就不熟,这次总算是形成一些方法论了。
参考文献
baike.baidu.com/item/CPU使用率… www.jianshu.com/p/6d573e423… github.com/oldratlee/u… m.jb51.net/article/150… coolshell.cn/articles/96…