JVM(9)——一次应用 CPU 飙高的血案排查过程
案件背景
一个应用集群里,时不时会有几台机器出现cpu打满现象,开始没有引起重视,后来连续出现报警,开始着手对其中一台进行排查,现将破案记录如下。
cpu飙升这类案件,一般来说有几个对象嫌疑重大:
-
嫌犯A:内存泄漏,导致大量full GC
-
嫌犯B:宿主机cpu超卖
-
嫌犯C:代码存在死循环
锁定嫌犯
嫌犯A:内存泄漏?
从monitor上看到,这台机器cpu占用达到300%多,而GC一览并没有出现full GC,只是出现了一些常规的YGC。再观察堆内存使用情况,也属正常,先排出了oom的嫌疑。
嫌犯B:cpu超卖?
虚拟机和容器技术突飞猛进,一台宿主机上跑多个vm带来了很多便利,vm间大多时候都能和谐共处,但偶尔也会出现某个问题vm大量占用宿主机资源,导致其他vm受到影响,也是超卖问题
到底是不是超卖在搞鬼呢?登上机器top一把,一探究竟
这里看到Cpu(s)一栏,cpu占用主要来自us,而st(Steal Time)并不高,这说明cpu的消耗并非来自宿主机的超卖,而是应用自身的消耗。所以排出超卖的嫌疑。
锁定嫌犯C:死循环
排出了上面两位的嫌疑,看来只能继续深入应用内部,对犯案现场勘察,查明哪些线程在消耗cpu资源。
前面通过top命令拿到java应用的pid是2143,通过top -Hp pid 命令,查看进程内的线程情况:
top -Hp 2143
不看不知道,一看吓一跳,犯罪现场触目惊心!前几个线程都占用了大量cpu,并且占用cpu时间最长的一个线程(tid=32421),已经存活了5个多小时。
继续进行追查,这货到底在干啥?
printf "%x" 32421 -- 拿到十六进制
jstack pid | grep tid -- 查看线程情况
原来这个线程在HashMap.getEntry()这,线程状态显示是RUNNABLE,说明并没有出现死锁(Blocked),而是不停run了5个多小时,看来凶犯已经找到:死循环非他莫属了!
为了进一步确认,用类似方法一一盘查其他几个高cpu占用的线程,从招供来看都是类似的堆栈。同时,在psp上进行了一把dump,用Zprofiler分析了一把,除去一些正常的线程,还有不少共犯混迹其中。
作案手法
凶手已经找到,但它是如何作案的呢?也就是这个死循环是如何产生的?
HashMap的并发问题
上面的堆栈告诉我们,线程在HashMap.java:465行不停的run,从jdk7的源码(应用使用的版本)可以看到
原来问题出在e.next这个地方。
看过源码的同学都知道,jdk(6)7的HashMap是数组+链表的存储结构(jdk8优化加入了红黑树)。
为了在查询效率方面达到平衡,HashMap的size是动态变化的,size初始值是16(未指定情况下)。一般来说,Hash表这个容器当有数据要插入(put->addEntry)时,会检查容量有没有超过设定的thredhold,如果超过,需要增大Hash表的尺寸,这一过程称为resize。
resize()源码如下:
可见,在多线程同时调用put方法时,多个线程也会同时进入transfer(),也就到了并发问题的核心地带。
这段代码会重新构建数组和链表,这单线程下安全,但多个线程同时去操作链表,会出现意想不到的结果,比如A线程操作到一半被挂起,B线程对A正在操作的链表进行了挪动,然后A获得cpu资源继续操作,原先的链表元素可能已经被挪到其他位置。
这会造成部分数据丢失,有一定几率出现更糟的情况:环链表
那么回到之前的getEntry方法,出现环链表的情况下,e.next会出现无限循环,无法跳出的情况。
总结下,多线程同时put时,有一定几率导致环链表产生,导致get方法进入无限循环,进而导致了cpu飙高。
结案
到这里,真相已经浮出水面:二方包的一个工具类(静态类),使用了一个static的HashMap进行了并发操作,导致了并发问题。
多线程环境中,使用ConcurrentHashMap代替HashMap。
转载于:https://www.cnblogs.com/xushuyi/articles/9604652.html