搞爆storm集群的bug追踪过程

前两天，突然收到了QA的反馈，我跑程序的storm集群（20多台）所有机器CPU居高不下。这就让我非常莫名其妙了，我的程序在最近一次上线以后，已经连续运行了3天了，怎么会突然就有问题了呢？

 

这时，我还是感觉程序不会有问题的，要不然怎么会正常运行了3天呢。。。因此我就对程序进行rebalance（为什么要这么做呢？我也不知道，就好像电脑有问题了重启就行了。。。）以及重启操作，但是都无济于事，程序在跑一会以后，就出现了CPU利用率很高的情况。

 

我找QA老大亮哥说明了程序跑了3天，程序应该没有问题，应该是环境的问题，但是他却告诉我，应该是有死循环导致的这种情况，而我却对他的说法抱怀疑的态度，，，然后就去看各种storm的log没有发现异常的东西，然后就看了我近几次的代码提交，也没有发现while(true) 这样的死循环。

 

然后，又查看了机器的详细监控，发现了在CPU升高的那一刻，网络IO、连接数、内存全部都降了，我逐渐感觉亮哥的推测是正确的。然后就开始了对进程分析的过程。

 

好了，废话不说了，直接上过程。

 

Step1: jstack

首先使用top命令查看占用CPU高的进程的id，发现有很多，果然是storm的，随意选一个pid；使用jstack命令查看线程状态，保存数据到stack.log中，返回结果如下：

"BrokenConnectionDestroyer-33-1464012569600" daemon prio=10 tid=0x00007fe174040800 nid=0x9432 waiting on condition [0x00007fdfa6ae9000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000076175b998> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
	at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:317)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:662)

   Locked ownable synchronizers:
	- None

 

打出来的有3000多行，翻了一遍，没有看出来什么不正常的。。。

 

Step2：ps

 

 

ps -eL -o pid,%cpu,lwp|grep -i $pid

 使用如上命令打出该pid中所有线程所占cpu的情况，打出结果如下（只贴出来关键的几行）：

 23323  0.0  25085
 23323  0.0  27025
 23323 52.3  27057
 23323  0.0  28285
 23323 48.9  28287
 23323  0.0  28946
 23323 53.2  28949
 23323  0.0  29492
 23323 51.8  29497
 23323  0.0  29828
 23323  0.0  29829
 23323  5.5  29921
 23323  0.0  29925
 23323  0.0  29952
 23323  0.0  30008
 23323  0.0  30011

 

现在结果很明了了，可一眼看出来这几个线程特别忙，其他的都是那么清闲，那么罪魁祸首找到了。。

 

 

Step3：printf

printf 0x%x  $27057

以Step2中的27057为例，将子线程id转为16进制，输出结果如下：0x1b91

 

Step4

在jstack.log中，搜索0x1b91这个线程号，果然有收获（由于当时保存的文件有问题，并不是真的这个线程号，但是结果一致），结果如下：

"Thread-13-UserInfoRecordConsumerBolt" prio=10 tid=0x00007fe2bcb0d000 nid=0x7339 runnable [0x00007fe244a56000]
   java.lang.Thread.State: RUNNABLE
	at com.jd.ad.user.jimDao.BaseJimUtilDao.addUserCartSkuKeyData(BaseJimUtilDao.java:280)
	at com.jd.ad.user.jimDao.BaseJimUtilDao.addUserCartSkuKeyData(BaseJimUtilDao.java:128)
	at com.jd.ad.user.dao.jim.impl.UserCartSkuInfoJimDaoImpl.addUserCartSkuInfoData(UserCartSkuInfoJimDaoImpl.java:13)
	at com.jd.ad.user.service.impl.UserCartSkuInfoServiceImpl.addUserCartSkuInfoData(UserCartSkuInfoServiceImpl.java:28)
	at com.jd.ad.user.service.impl.AdUserServiceImpl.addUserInfoRecordTask(AdUserServiceImpl.java:231)
	at com.jd.ad.user.job.storm.UserInfoRecordConsumerBolt.execute(UserInfoRecordConsumerBolt.java:48)
	at backtype.storm.daemon.executor$fn__3498$tuple_action_fn__3500.invoke(executor.clj:615)
	at backtype.storm.daemon.executor$mk_task_receiver$fn__3421.invoke(executor.clj:383)
	at backtype.storm.disruptor$clojure_handler$reify__2962.onEvent(disruptor.clj:43)
	at backtype.storm.utils.DisruptorQueue.consumeBatchToCursor(DisruptorQueue.java:82)
	at backtype.storm.utils.DisruptorQueue.consumeBatchWhenAvailable(DisruptorQueue.java:61)
	at backtype.storm.disruptor$consume_batch_when_available.invoke(disruptor.clj:62)
	at backtype.storm.daemon.executor$fn__3498$fn__3510$fn__3557.invoke(executor.clj:730)
	at backtype.storm.util$async_loop$fn__444.invoke(util.clj:403)
	at clojure.lang.AFn.run(AFn.java:24)
	at java.lang.Thread.run(Thread.java:662)

   Locked ownable synchronizers:
	- None

 

显而易见，这里已经定位到了程序中的位置了，那么就应该去查看程序了，结构如下：

         List<UserCartSkuItemInfo> oldSkuItemList =  userCartSkuInfosBuilder.build().getSkuInfosList();
         for (int i = 0; oldSkuItemList != null && i < oldSkuItemList.size();) {
             UserCartSkuItemInfo item = oldSkuItemList.get(i);
             if (item.getId() == userCartSkuInfoRecord.getSkuId()) {
                userCartSkuInfosBuilder.removeSkuInfos(i);
                break;
             }
         }

 

 OMG，现在已经看出来结果了。。。。

 i 变量一直是0 ...........................

 

目前为止，问题已经找到了。

现在再回头想一下，确实现象是跟这个吻合的：

为什么刚开始会正常运行了3天呢？

    答曰：这个数据还没有正式接入，只有一些少量的测试数据，那么代码运行到这里的几率很小，所以没影响。而这一天恰好开始接入数据了，造成了这个问题的出现。而且，刚开始一个用户的数据也就只有一条，那么恰好两个id相等，跳出了循环。。可是数据积累以后，那么当i=0的时候，数据不想相等了，就进入死循环了。

 

 还有一点，确实不能够按照以前运行的状态来判断，因为具体问题，具体分析。老鸟的很大优势，就是碰到的坑比较多，有经验了，，，所以，QA大哥刚开始就判定它为“dead loop”

 

 

评论

1 楼 18942512863 2017-05-24  

Catch you