记录一次对代码完全陌生的问题排查过程

        最近高层来参观，有个页面是重点放在屏幕上的，但是已经好几个月没维护了，前端同学在调样式的时候发现响应时间很长，有两个异步请求都在30秒左右，如果在慢速网络情况下，40秒都有可能。于是开始排查。

        但是，这个页面的逻辑我完全不清楚。

        1、用firebug看了一下，发现一次页面请求，会发送多个http请求，是到一个接口，然后通过参数不同来调用不同的逻辑，哎呀，傻了，本来逻辑就不清楚，还是通过参数动态控制的；

 

        2、找到代码，逐段分析，发现逻辑方法中初最后一行外，其余的全是内存操作，不可能耗时很长，只有最后一场是数据库的操作；

 

        3、中间试过用Btrace的工具把调用的方法栈以及响应时间占比打印出来，这样就能很快的定位那个地方慢了，但是搞了半天，也没打印出栈信息出来，于是放弃使用这个高级货了。

 

        4、进入最后一行代码的实现，发现全是DAO操作，心里大体有谱了，但是有好多DAO，是那个DAO方法慢了呢？

 

        5、观察发现这些DAO是来自一个类，然后就用housemd来进行动态追踪，打印这个类的执行情况。

1	trace  -d  -t 60 IbatisNodeTransitDAO

            这样在点击页面的过程中，打印出来这个类中各个方法的执行情况，

1 2 3 4

core/dao/ibatis/IbatisNodeTransitDAO.queryPredictWarnAllNodeTransitsLoadCount(PredictDataQueryTO,  Double, Double)    sun.misc.Launcher$AppClassLoader@63c78e57            2          328ms     core.dao.ibatis.IbatisNodeTransitDAO@564a6f2 core/dao/ibatis/IbatisNodeTransitDAO.queryPredictWarnForcastRoutineByAreaBounds(PredictDataQueryTO)        sun.misc.Launcher$AppClassLoader@63c78e57            5           <1ms     core.dao.ibatis.IbatisNodeTransitDAO@564a6f2 core/dao/ibatis/IbatisNodeTransitDAO.queryPredictWarnLineCountByNodeTransitId(Long,  String)               sun.misc.Launcher$AppClassLoader@63c78e57          184          290ms     core.dao.ibatis.IbatisNodeTransitDAO@564a6f2 core/dao/ibatis/IbatisNodeTransitDAO.queryPredictWarnNodeTransitsByAreaBounds(PredictDataQueryTO)          sun.misc.Launcher$AppClassLoader@63c78e57            5          258ms     core.dao.ibatis.IbatisNodeTransitDAO@564a6f2

 

 

        6、在上面中，发现queryPredictWarnLineCountByNodeTransitId这个方法的平均响应时间很长，而且调用次数很多，然后就找到这个DAO对应的SQL，SQL如下：

1 2 3 4 5 6 7 8 9

select             sum(ls.order_count) as lineCount         from             xxxxxx_table ls         where             ls.status = 1 and             ( ls.record_date between #beginDate# and #endDate#) and             ls.to_transit_id = #transitId#         ]]>

 

         第一反应是没有加索引，在websqlplus上面，看了一下，这个表数据不多80W左右，然后造了一个数据，用explain select_statement来看了一下情况，然后type是all，也就是全表扫描，这时候基本清楚问题怎么解决了。

 

        7、联系DBA添加索引，被DBA说了一顿，白天不能加，哀求白天，加上了。

        由于status是个常量字段，不用添加，于是在record_date和to_transit_id搞了一个组合索引。

 

        8、至此，问题解决。​

 

            总结：

            1、灵活运用动态追踪工具，因为线上环境不可能像我们线下环境那样能够debug

            2、快速阅读代码，定位可能存在的瓶颈（死循环、网络IO、数据库操作、大对象操作等）

        

        

评论

1 楼 rain2005 2014-03-19  

哈哈，这个问题还是服务监控没有做到位,housemd确实很赞