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

Posted niejunlei

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了一次排查线上接口偶发异常耗时引起的思考!相关的知识,希望对你有一定的参考价值。

一、引子

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

二、问题:

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

技术图片

三、排查:

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

输出:

1001
2004

五、结论

这里采用的是Spring的StopWatch,四个Task,总耗时及分耗时不用额外的记录处理,对于总耗时超过一定值的请求,打印StopWatch明细:

技术图片 

问题就在那个一开始就认定不会有问题的逻辑里。

其实本篇的出发点并不是要描述什么疑难线上问题的排查过程、方法、技巧。

当我们面对问题时,真正阻我们,或者说会把我们引向错误方向的正式我们所固有的一种惯性认知,思维模式。

任何时候对于未知,不要轻易去假定任何不确定的东西,经验可以是助益,同时也可能成为阻碍。

问题面前,一切都值得怀疑,平等的怀疑。

 

以上是关于一次排查线上接口偶发异常耗时引起的思考!的主要内容,如果未能解决你的问题,请参考以下文章

推荐几个我近期排查线上http接口偶发415时用到的工具

一次线程池引发的线上故障分析

一次线上问题排查所引发的思考

MySQL连接池引起的FullGC问题分析

线上接口偶尔超时排查

一次线上tomcat应用请求阻塞的排查经过