不可思议！平均执行耗时仅1.5ms的接口在超时时间100ms下成功率竟然还不到5个9！！
1 背景
2 验证与分析
2.1 准备工作
2.2 验证
2.3 问题分析
2.4 排查
2.5 原因
3 解决方案
3.1 框架优化-弹性超时
4 总结
1 背景
一个春暖花开的午后，客服技术部佩姐（P）找过来向我们反馈一个问题，如下是我们的对话：
P：云杰，我们最近在治理服务质量，有个接口的成功率达不到公司标准5个9。 我：赞，你们也开始质量治理了，详细说说。 P：我们sccis有个重要的lookupWarehouseIdRandom接口，先查询缓存，未命中的再从数据库查并回写到缓存，平均执行耗时只有1.5ms。现在scoms在调它，超时时间配的还是100ms，结果发现每天还有500多个超时，成功率不到5个9，达不到公司标准。你们框架是不是有问题啊，帮忙看看！ 我：不至于吧！？平均执行耗时1.5ms，在调用方超时时间配100ms（60多倍！）的情况下竟然还有这么多超时？ P：真的！！不信你看看！！！ 我：看看就看看！如下开始本篇的研究之旅。
2 验证与分析
2.1 准备工作
在开始验证之前，先简要介绍下转转RPC框架SCF的调用过程，如下图所示：
序列化：SCF接收到调用方的请求，做负载均衡、序列化等；
发送：SCF将序列化后的二进制流通过网络发送给服务方结点；
反序列化：服务方结点接收到数据后，将数据交给SCF，做反序列化、排队等；
执行：SCF将请求交由服务方的实现方法进行处理；
序列化：SCF将服务方的处理结果序列化为二进制数据流；
发回：将数据发回给调用方；
反序列化：调用方SCF收到请求后，将二进制数据反序列化为对象交由调用方代码，使得调用方看起来跟本地方法调用一样。
如上是一次完整的RPC调用链路。
2.2 验证
通过监控我们发现接口的平均执行耗时确实在1.5ms左右，如下图所示：
但调用方scoms在超时时间为100ms的情况下确实仍然有很多请求超时：
太让人震惊了！！！
2.3 问题分析
通过如上的RPC调用过程链路示意，我们可以看出任意一个子过程都可能会发生抖动，造成超时。但我们可以从整体上把链路分为框架和业务两个部分（分界点如图所示）：
框架：指底层的网络和SCF耗时，属于客观原因，包括图中的1、2、3、5、6、7；
业务：单纯指业务服务的执行4，属于主观原因。
因为框架耗时复杂多变，不好统计，我们可以统计业务的执行耗时分布，以此来判断问题出在框架上还是出在业务上。
如果业务的执行耗时分布都非常低，那就说明超时花在了框架上；
如果业务的执行耗时分布都有很多高耗时的，那就说明超时花在了业务逻辑上。
正好服务方的接口有耗时分布监控，通过监控我们发现绝大部分情况都在5ms内处理完成，但仍有314个请求处理时间直接超过了100ms！！！
耗时分布
这个发现也让我们大吃一惊：平均执行耗时1.5ms的接口，竟然还会有这么多请求执行耗时越过100ms！！那么这些时间都花在哪里了呢？
2.4 排查
目前的监控都是接口的整体执行耗时，我们需要深入接口内部看看时间都花在哪里了。我们对接口分为如下几个部分，并分段监控起来。
监控结果如下所示：
从结果可以看到：
I/O操作容易抖动，出现较多次100ms+；
最简单的CPU操作虽然没有那么多100ms+，但也有不少20ms左右的情况（而且都是从1ms突变到20ms，而不是渐变）。
2.5 原因
原来我们是被1.5ms给平均了！什么原因会导致这种长尾效应呢？情况可能有很多，GC（极度怀疑）、CPU时间片分配等。如下是sccis的GC监控：
为此，我们也对比了转转商品服务zzproduct的getProductById()接口，发现也有同样的情况：
getProductById()耗时分布
3 解决方案
至此，我们看到业务接口平均执行耗时虽然仅有1.5ms，但仍会出现不少超过100ms的长尾效应，当然框架也会出现。其原因有多种，GC（极有可能）、CPU时间片分配、网络抖动等等。
而这，也确实刷新了我们所有人的认知。
反过来想，如果业务接口要达到公司要求的5个9要求，该怎么办呢？其实很简单，我们可以参照调用方的TP9999来设置超时时间。如下图，scoms调用该接口的TP99999是123ms，而业务把超时时间配置成了100ms，那肯定达不到5个9的标准了。要么把超时时间改为123ms（简单直接），要么优化业务逻辑（目测很难，因为平均执行耗时只有1.5ms）或JVM调优（很有希望）。
3.1 框架优化-弹性超时
基于本文分析，RPC框架也可以针对这种长尾效应做一定优化：不改变超时时间100ms配置情况下，允许一段时间（可配）一些量（可配）的请求在200ms（可配）时间内返回，既提高了服务质量，又不太影响用户体验，我们称之为弹性超时方案。
3.1.1 效果
如下图所示，我们在服务管理平台支持按服务&函数设置弹性超时，这里我们将上文zzscoms调zzsccis的IInventoryWrapCacheFacade.lookupWarehouseIdRandom(List)函数配置成每40秒允许15个请求的超时时间延长至1300毫秒。
弹性超时配置
通过配置弹性超时，我们看到这种偶发性的超时基本被容忍消灭掉了，如下图所示：
3.1.2 适用场景
弹性虽好，可不要贪杯！它更多适用于一些偶发性超时场景，比如网络抖动、GC、CPU抖动、冷启动等，如果是大面积的超时还是需要深入分析治理。
4 总结
本文深入分析了平均耗时仅有1.5ms的接口也会出现大量100ms+的前因后果，并在框架层面给出了弹性超时的解决方案。这也刷新了我们的认知，由于GC、CPU时间片等原因，一些看起来很简单的操作（如i++）也会出现偶发性长耗时。