问题再现:
  个人中心在上周四上线(2012.9.13)第一次上线,由于种种缘由,遗留了部分低级别的BUG,后于次日修复,下午4时再次上线。
  当日晚上8点,运维发现user-web 五台服务器中四台jboss僵死,无法响应用户请求。
问题分析:
  问题发生当日,运维截留了当时的日志信息并dump 了JVM内存信息,关键信息如下:
  
  java.lang.NullPointerException
Message 2012-09-15 02:47:56,992 - com.dianping.userweb.service.processor.MyInfoFavouriteModuleProcessor -235970 [myInfoThreadPoolTaskExecutor-1] ERROR - com.dianping.userweb.service.processor.MyInfoFavouriteModuleProcessor process module exception.
  ......
   
  "http-0.0.0.0-8080-271" daemon prio=10 tid=0x00002b6ef4211000 nid=0x292a waiting on condition [0x00002b6eac592000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007c4a3f0f0> (a java.util.concurrent.CountDownLatch$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207)
        at com.dianping.userweb.framework.concurrent.ConcurrentSidebarManager.execute(ConcurrentSidebarManager.java:46)
        at com.dianping.userweb.action.page.myinfo.MyInfoIndexAction.sideBarManagerExecute(MyInfoIndexAction.java:39)
        
   ......
   
   从以上日志中我们可以得到两个信息
   1.一个 process报了空指针异常,
   2.一个线程一直处在waiting状态。
   
   根据日志找到对应的代码:
   
   
     @Override
    public void execute(final UCActionContext context) throws ProjectException {
        final CountDownLatch countDownLatch = new CountDownLatch(getHeadSize() + getLeftSize() + getRightSize());
        barHandleExecute(context, countDownLatch, sideBar);
        try {
            countDownLatch.await();                            --- A 
        } catch (InterruptedException e) {
            logger.error("current handle error!", e);
            throw new ProjectException("current handle error!");
        }
    }
    
    这段是处理并行的核心代码,通过CountDownLatch来处理并行的执行,主线程通过 countDownLatch.await();等待子线程的完成。这个方法会抛除InterruptedException异常,这个异常包含三个含义:
    
    1.这是一个异常,需要业务根据时间情况处理,当然有些废话
    2.这是一个等待方法,等待的时间不根据CPU或是内存的情况,而是依赖于定时器或是磁盘IO的返回,本案是根据子线程的执行情况
    3.这个等待线程是可以中断的
    所以当一个请求过来时,主线程会在这个A处等待,直到所有子线程告诉我,所有子线程已经执行完成了。
    
    再看barHandleExecute方法的处理:
    
     protected void barHandleExecute(final UCActionContext context, final CountDownLatch countDownLatch, SideBar sideBar) {
       
       ....... 
                threadPoolTaskExecutor.execute(new Runnable() {
                    @Override
                    public void run() {
                        Transaction t = Cat.getProducer().newTransaction("Modules",
                                                                         moduleProcessor.getClass().getName());// 接入cat
                        try {
                            moduleProcessor.execute(context);
                            countDownLatch.countDown();
                            t.setStatus(Transaction.SUCCESS);
                        } catch (Throwable e) {
                            Cat.getProducer().logError(e);// 用log4j记录系统异常,以便在Logview中看到此信息
                            t.setStatus(e);
                            
                        } finally {
                            t.complete();  
                        }
                    }
                });
      .......
    }
    
    对于多个线程,通过线程池来处理,每个线程也就是moduleProcessor处理完成后, countDownLatch.countDown();告诉主线程我已经执行完成了,当主线程收到所有子线程的答复后,继续往下执行,进行页面的渲染。
    
    以上都是正常流程的流转过程,但是,若我们其中的一个moduleProcessor抛出异常后,会出现什么情况呢?这个异常会被接入CAT监控的代码会吃掉,告诉CAT一个日志信息,然后就什么都不做了。那countDownLatch.countDown();这段代码就永远不会被执行,而主线程又依赖于子线程通过countDownLatch.countDown();来告知是否执行完了。这个时候就悲剧了,主线程一直在等待子线程的消息,无法渲染页面返回结果,这个时候用户的第一反应会是是不是网络原因导致没有加载数据,不停的F5,每次都会产生一个新的请求进来,若是刷新的人越多,这些进程就永远僵死在那边,不释放内存,造成系统雪崩。
    
    一个合理的介入CAT方式是:
      Transaction t = Cat.getProducer().newTransaction("Modules",
                                                                         moduleProcessor.getClass().getName());// 接入cat
                        try {
                            // 业务处理
                            t.setStatus(Transaction.SUCCESS);
                        } catch (Throwable e) {
                            Cat.getProducer().logError(e); 
                            t.setStatus(e);
                            throw new ProjectException();  //这里必须抛出异常,有业务系统决定如何处理异常
                        } finally {
                            t.complete();  
                        }
    
几个疑问:
1.为什么processor会抛出异常?
当时在porcessor编写的时候,约定各个processor需要cacth自己的异常,不能因为自己的失败导致请求的其他模块加载失败。我们看看报空指针的地方:
.....
context.getParam(DefaultActionContext.Contant.MEMBER_ID.name)
.....
try
...
报错的是从上下文获取memberID的代码,这个操作并没有放在try catch块中。由于个人中心的所有页面都必须依赖于memberID这个字段,所以编码时就忽略了memberId为空的这种情况,而且在我们的action层也对memberID为空的情况作了处理,具体代码如下:
......
private void initMemberInfo(UCActionContext context) throws ProjectException {
        // 验证会员存在
        if (memberId == null) {
            throwException(MemberUtil.MEMBERID_INVALID_TITLE, MemberUtil.MEMBERID_INVALID_MSG);
        }
...... 
所以理论上来说,对于memberId为空的情况不会进入后端处理的processor,所以后端也就没有考虑到从context获取memberID会为空,但是实际情况还是发生了,这段代码也做了拦截,并抛出了异常,不过 在initMemberInfo这个方法的外层,又catch住了这个异常:
try
  ....
   initMemberInfo(context);
   
catch(){
  ....
}
所以说ACTION做的处理并没有起到拦截作用,导致这个null的memberid传递到了后端,后端出错后被接入CAT的代码抓住,导致主线程一直得不到返回。
2.为什么在压力测试过程中没有发生这个问题?
压力测试过程时,当时批量处理方法barHandleExecute的源代码如下所示,并没有介入CAT监控代码
 protected void barHandleExecute(final UCActionContext context, final CountDownLatch countDownLatch, SideBar sideBar) {
       
       ....... 
                threadPoolTaskExecutor.execute(new Runnable() {
                    @Override
                    public void run() {
                     
                            moduleProcessor.execute(context);
                            countDownLatch.countDown();
                    }
                });
      .......
    }
这个地方为什么没有做try catch,是考虑到我们一些并行的processor存在一些依赖关系,processorA出异常的话,processorB就算不出问题,也不渲染页面。所以这里就不cacth异常,由具体的processor来决定是否cacth异常。所以在压力测试过程,就算其中processor抛出异常,框架就认为这是某个依赖processor抛出的异常,就将这个异常抛到WEB,由最外层做控制,跳转到统一的错误页面。所以这主线程僵死的情况就不会出现。
3.周四上线的时候为什么没有让jboss僵死?
个人中心周四晚上9点多上线,当时访问量也不是很大,就算碰到会导致一些无效的memberID的请求进入,也不会立刻让JBOSS僵死。同时我们在周五下午又对个人中心做了一次上线,重启了应用了,所以没报出这个问题,但是在周五晚上,请求增大,各种复杂情况的请求进入后,就触发了我们代码中的缺陷,最终导致JBOSS僵死。
总结:
1.前段action拦截不合理,放入了memberId为NULL的请求,打开了系统出错的门。
2.后端processor信任前段过来的数据,并没有做防御式处理,导致空指针异常,同时又没有将这段获取数据的代码纳入try中,进一步将系统推向奔溃边缘。
3.上线前接入CAT代码,没有考虑全面,这段代码在自己本分(记录系统执行开销及异常)外干了不是它的事,cacth住了我们的系统异常,这个才是压垮系统的最后一根稻草,导致系统雪崩。
4.框架本身考虑不够全面,用一种靠扩展对自身的约束来处理异常情况,没有分开的去处理:多个无关porcessor和多个存在关联processor的两种情况。
以上四步,只要不走错一步,就不会出现周五晚上的JBOSS僵死问题。可见一个重大错误大多是由一系列的错误连锁导致的。