这要从线上的一个接口偶发异常耗时说起,事情往往不是你想象的样子,尤其是在排查问题的时候,切忌有先入为主的的某些判断。
接口监控图:显示每天总会有那么几次耗时特别长的请求。
三、排查:
对于这种情况,第一感觉是因为服务的波动影响,因为没有服务能够达到100%的低延迟可用响应。
首先检查了相应时段的其它接口的响应情况,发现并没有相似的情景。由此可以基本上排除了服务波动的影响,但是也不是十分确定。
逻辑l3是一个存在很久的历史业务逻辑,首先假定认为了它没有问题排除掉了(呵呵)。
l2是一个比较耗时的处理,首先的关注点放在了这里。l2是有超时设定的,最大超时为2s,但是我们的监控库里看到的最大的耗时是超过两秒的,或者考虑到其它处理逻辑的耗时,最坏的情况下,总的耗时是不应该超过3s的。为了确认l2服务的稳定性,线上添加了相应的监控,观察到最大耗时是在超时限定范围内的。因此排除掉此处的问题,
经过以上几步的排查,现有的信息已经不足以定位问题了。只能把接口里的每一步逻辑耗时全部统计记录来进一步排查(其实,内心是非常拒绝的)。
StopWatch很多地方都提供了,Spring、Apache、Guava。
1、Spring示例:
♣ id标识当前的StopWatch,比如统计一个接口的耗时,可以使用接口名称作为标识,从而在输出端进行识别。
♣ 内部有task概念,用以表示内部每一阶段的执行逻辑,比如获取用户信息->获取资金信息->交易逻辑流转过程。
♣ 的格式化输出比较明晰,包括StopWatch标识,任务标识,每个任务的耗时及总占比。
public static void springStopWatch() throws InterruptedException {
StopWatch stopWatch = new StopWatch("spring_stopwatch");
stopWatch.start("a"); //开始任务a
Thread.sleep(1000);
stopWatch.stop(); //任务a执行完毕
stopWatch.start("b"); //开始任务b
Thread.sleep(2000);
stopWatch.stop(); //任务b执行完毕
stopWatch.start("c"); //开始任务c
Thread.sleep(100);
stopWatch.stop(); //任务c执行完毕
System.out.println(stopWatch.prettyPrint());
}
输出:
StopWatch 'spring_stopwatch': running time (millis) = 3111
-----------------------------------------
ms % Task name
-----------------------------------------
01002 032% a
02006 064% b
00103 003% c
这里有个split概念,我愿意称之为时间“锚点”,当你执行完split操作后,在下一次执行split之前,你可以在任何时候获取开始时间到执行split的时间点之间的时间间隔:
supend-resume:挂起、恢复,很容易理解,暂停计时、恢复继续计时:
public static void apacheStopWatch() throws InterruptedException {
org.apache.commons.lang3.time.StopWatch stopWatch = org.apache.commons.lang3.time.StopWatch.createStarted();
Thread.sleep(1000);
stopWatch.stop(); //结束计时
System.out.println("normal: " + stopWatch.getTime());
//split test
stopWatch.reset();
stopWatch.start();
Thread.sleep(1000);
stopWatch.split(); //时间锚点
Thread.sleep(1000);
System.out.println("split: " + stopWatch.getSplitTime()); //开始到时间锚点的间隔
//suspend
stopWatch.reset();
stopWatch.start();
Thread.sleep(1000);
stopWatch.suspend(); //挂起watch
Thread.sleep(1000); //期间的时间是不计入总时间的
stopWatch.resume(); //恢复watch
Thread.sleep(1000);
stopWatch.stop();
System.out.println("suspend_resume: " + stopWatch.getTime());
}
输出:
normal: 1002
split: 1004
suspend_resume: 2009
just StopWatch
public static void guavaStopWatch() throws InterruptedException {
Stopwatch stopwatch = Stopwatch.createStarted();
Thread.sleep(1000);
stopwatch.stop();
System.out.println(stopwatch.elapsed(TimeUnit.MILLISECONDS));
stopwatch.reset();
stopwatch.start();
Thread.sleep(2000);
stopwatch.stop();
System.out.println(stopwatch.elapsed(TimeUnit.MILLISECONDS));
}
输出:
1001
2004
这里采用的是Spring的StopWatch,四个Task,总耗时及分耗时不用额外的记录处理,对于总耗时超过一定值的请求,打印StopWatch明细: