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