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

        最近高层来参观，有个页面是重点放在屏幕上的，但是已经好几个月没维护了，前端同学在调样式的时候发现响应时间很长，有两个异步请求都在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、数据库操作、大对象操作等）