一, 引子
这要从线上的一个接口偶发异常耗时说起, 事情往往不是你想象的样子, 尤其是在排查问题的时候, 切忌有先入为主的的某些判断.
二, 问题:
接口监控图: 显示每天总会有那么几次耗时特别长的请求.
三, 排查:
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 明细:
问题就在那个一开始就认定不会有问题的逻辑里.
其实本篇的出发点并不是要描述什么疑难线上问题的排查过程, 方法, 技巧.
当我们面对问题时, 真正阻我们, 或者说会把我们引向错误方向的正式我们所固有的一种惯性认知, 思维模式.
任何时候对于未知, 不要轻易去假定任何不确定的东西, 经验可以是助益, 同时也可能成为阻碍.
问题面前, 一切都值得怀疑, 平等的怀疑.
来源: https://www.cnblogs.com/niejunlei/p/13279319.html