分析
首先了解下这个应用大概是做什么的。
简单来说就是从 MQ
中取出数据然后丢到后面的业务线程池中做具体的业务处理。
而报警的队列正好就是这个线程池的队列。
跟踪代码发现构建线程池的方式如下:
ThreadPoolExecutor executor = new ThreadPoolExecutor(coreSize, maxSize, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<Runnable>());; put(poolName,executor);
采用的是默认的 LinkedBlockingQueue
并没有指定大小(这也是个坑),于是这个队列的默认大小为 Integer.MAX_VALUE
。
由于应用已经重启,只能从仅存的线程快照和内存快照进行分析。
内存分析
先利用 MAT
分析了内存,的到了如下报告。
其中有两个比较大的对象,一个就是之前线程池存放任务的 LinkedBlockingQueue
,还有一个则是 HashSet
。
当然其中队列占用了大量的内存,所以优先查看,HashSet
一会儿再看。
由于队列的大小给的够大,所以结合目前的情况来看应当是线程池里的任务处理较慢,导致队列的任务越堆越多,至少这是目前可以得出的结论。
线程分析
再来看看线程的分析,这里利用 fastthread.io 这个网站进行线程分析。
因为从表现来看线程池里的任务迟迟没有执行完毕,所以主要看看它们在干嘛。
正好他们都处于 RUNNABLE 状态,同时堆栈如下:
发现正好就是在处理上文提到的 HashSet
,看这个堆栈是在查询 key
是否存在。通过查看 312 行的业务代码确实也是如此。
这里的线程名字也是个坑,让我找了好久。
定位
分析了内存和线程的堆栈之后其实已经大概猜出一些问题了。
这里其实有一个前提忘记讲到:
这个告警是凌晨三点
发出的邮件,但并没有电话提醒之类的,所以大家都不知道。
到了早上上班时才发现并立即 dump
了上面的证据。
所有有一个很重要的事实:这几个业务线程在查询 HashSet
的时候运行了 6 7 个小时都没有返回。
通过之前的监控曲线图也可以看出:
操作系统在之前一直处于高负载中,直到我们早上看到报警重启之后才降低。
同时发现这个应用生产上运行的是 JDK1.7
,所以我初步认为应该是在查询 key 的时候进入了 HashMap
的环形链表导致 CPU
高负载同时也进入了死循环。
为了验证这个问题再次 review 了代码。
整理之后的伪代码如下:
//线程池 private ExecutorService executor; private Set<String> set = new hashSet(); private void execute(){ while(true){ //从 MQ 中获取数据 String key = subMQ(); executor.excute(new Worker(key)) ; } } public class Worker extends Thread{ private String key ; public Worker(String key){ this.key = key; } @Override private void run(){ if(!set.contains(key)){ //数据库查询 if(queryDB(key)){ set.add(key); return; } } //达到某种条件时清空 set if(flag){ set = null ; } } }
大致的流程如下:
- 源源不断的从 MQ 中获取数据。
- 将数据丢到业务线程池中。
- 判断数据是否已经写入了
Set
。
- 没有则查询数据库。
- 之后写入到
Set
中。
这里有一个很明显的问题,那就是作为共享资源的 Set 并没有做任何的同步处理。
这里会有多个线程并发的操作,由于 HashSet
其实本质上就是 HashMap
,所以它肯定是线程不安全的,所以会出现两个问题:
- Set 中的数据在并发写入时被覆盖导致数据不准确。
- 会在扩容的时候形成环形链表。
第一个问题相对于第二个还能接受。
通过上文的内存分析我们已经知道这个 set 中的数据已经不少了。同时由于初始化时并没有指定大小,仅仅只是默认值,所以在大量的并发写入时候会导致频繁的扩容,而在 1.7 的条件下又可能会形成环形链表。
不巧的是代码中也有查询操作(contains()
),观察上文的堆栈情况:
发现是运行在 HashMap
的 465 行,来看看 1.7 中那里具体在做什么: