一次排查线上接口偶发异常耗时引起的思考！

时间：2020-07-11 09:50:01 阅读：66 评论：0 收藏：0 [点我收藏+]

标签：star nbsp 方向观察格式化认知 new 正式 col

一、引子

这要从线上的一个接口偶发异常耗时说起，事情往往不是你想象的样子，尤其是在排查问题的时候，切忌有先入为主的的某些判断。

二、问题：

接口监控图：显示每天总会有那么几次耗时特别长的请求。

技术图片

三、排查：

1、直观的认识是“偶发”，每天零星的几个，不规律。

对于这种情况，第一感觉是因为服务的波动影响，因为没有服务能够达到100%的低延迟可用响应。

首先检查了相应时段的其它接口的响应情况，发现并没有相似的情景。由此可以基本上排除了服务波动的影响，但是也不是十分确定。

2、接口逻辑

技术图片

逻辑l3是一个存在很久的历史业务逻辑，首先假定认为了它没有问题排除掉了（呵呵）。

l2是一个比较耗时的处理，首先的关注点放在了这里。l2是有超时设定的，最大超时为2s，但是我们的监控库里看到的最大的耗时是超过两秒的，或者考虑到其它处理逻辑的耗时，最坏的情况下，总的耗时是不应该超过3s的。为了确认l2服务的稳定性，线上添加了相应的监控，观察到最大耗时是在超时限定范围内的。因此排除掉此处的问题，

3、不得已而为之

经过以上几步的排查，现有的信息已经不足以定位问题了。只能把接口里的每一步逻辑耗时全部统计记录来进一步排查（其实，内心是非常拒绝的）。

四、StopWatch

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

2、Apache StopWatch：

这里有个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

3、Guava：

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));
    }

输出：