一次系统宕机之后的诊断报告及经验总结

  首先交代一下系统的基本情况，开发是J2EE架构，最流行的那种，部署架构是weblogic+oracle 。2013-11-11接到现场实施人员反馈在9日上午（周六）有宕机并发回了weblogic的server.log 。

       1.  从server.log中看到在08时25分49秒有stuck<2013-11-9 上午08时25分49秒 GMT+08:00> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '18' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "630" seconds working on the request "Http Request: /web/XXX/servlet/exportExcel", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:

        在08时25分49秒和09时28分31秒之间有四次导出，造成了最终的内存溢出。

        在<2013-11-9 上午09时28分31秒 GMT+08:00>Exception in thread "Thread-10" java.lang.OutOfMemoryError: Java heap space

       2. 由于系统稀烂的抛错机制，不能定位到代码，所以也不知道是哪个功能。

       3. 因为系统记录用户点菜单的操作，所以可以查询期间用户点了哪些菜单，然后看这些菜单哪个有导出，这个方法不是特别好，我决定采用另一个方案。

       4. 首先我要实施组把现场的access.log发回来，通过系统stuck的时间减去线程堵塞的时间，我找到了当时的请求是一个功能的导出，事情总算有点眉目。

       5. 这个还不算，要现场把8:00-9:00 ，9:00-10:00 之间的数据库AWR发回来，从报告上可以定位到就是此功能的导出，通过SQL_ID找到当时的执行计划和绑定变量，填上去后在现场数据库上（只是统计导出的条数），有5万多条记录，这个就是问题所在了（之前做过实验，导出4万条数据，有15个字段，消耗的内存接近400M）。注意的是，在AWR中这条SQL的执行时间可能很短，原因是AWR只记录SQL的解析和执行时间，返回记录的时间是不记录的。所以看到AWR的负载不高，也不能代表没有问题。

       6. 导出大量的数据，一是大量消耗weblogic的内存，二是产生stuck线程，堵塞系统，造成大量排队，接下来就是内存溢出。跟开发反馈这个功能的问题，开发起初说这个模块导出限制在1万条以内，有过了一会，说有个地方遗漏了。

       宕机场景回放：在某个周六，用户点了一个没有加限制的导出，等了一会后发现没有反应，在接下来的时间里，连续点了多次，直到系统宕机，看到系统没反应后说：什么破系统，又不能用了。

       总结：要总结的东西太多了，从宕机的诊断分析来说，首先从weblogic定位出大致出现的问题，如可能是网络的问题，可能是数据库不可用的问题，可能是代码级的问题等。明确方向后就要从多个维度找证据，视野要开阔，最好是懂业务，不懂也要去学。

      最应该总结的是我们系统分析师。作为系统分析师，在系统设计之初就应该能估计到数据规模的增长，有些系统分析师说我估计不出来。细想一下他的说法占不住脚，现在的系统不是凭空出来的，是实际发生的业务，都是可能通过用户使用的单据上评估出业务量，往往只是人懒罢了。最后这个功能通过系统分析师分析，限制在导出3千条数据。

      其次应该总结的是我们的开发人员，在做这个导出的时候，完全可以做出一个进度条，可以做出一个防连续点击的效果。这样用户就不会使劲的点，相当于给系统有加了一个保险。