一个春暖花开的午后，客服技术部佩姐（P）找过来向我们反馈一个问题，如下是我们的对话：

如下开始本篇的研究之旅。

在开始验证之前，先简要介绍下转转RPC框架SCF的调用过程，如下图所示：

• 序列化：SCF接收到调用方的请求，做负载均衡、序列化等；

• 发送：SCF将序列化后的二进制流通过网络发送给服务方结点；

• 反序列化：服务方结点接收到数据后，将数据交给SCF，做反序列化、排队等；

• 执行：SCF将请求交由服务方的实现方法进行处理；

• 序列化：SCF将服务方的处理结果序列化为二进制数据流；

• 发回：将数据发回给调用方；

• 反序列化：调用方SCF收到请求后，将二进制数据反序列化为对象交由调用方代码，使得调用方看起来跟本地方法调用一样。

如上是一次完整的RPC调用链路。

通过监控我们发现接口的平均执行耗时确实在1.5ms左右，如下图所示：

但调用方scoms在超时时间为100ms的情况下确实仍然有很多请求超时：

太让人震惊了！！！

通过如上的RPC调用过程链路示意，我们可以看出任意一个子过程都可能会发生抖动，造成超时。但我们可以从整体上把链路分为框架和业务两个部分（分界点如图所示）：

• 框架：指底层的网络和SCF耗时，属于客观原因，包括图中的1、2、3、5、6、7；

• 业务：单纯指业务服务的执行4，属于主观原因。

因为框架耗时复杂多变，不好统计，我们可以统计业务的执行耗时分布，以此来判断问题出在框架上还是出在业务上。

• 如果业务的执行耗时分布都非常低，那就说明超时花在了框架上；

• 如果业务的执行耗时分布都有很多高耗时的，那就说明超时花在了业务逻辑上。

正好服务方的接口有耗时分布监控，通过监控我们发现绝大部分情况都在5ms内处理完成，但仍有314个请求处理时间直接超过了100ms！！！

耗时分布

这个发现也让我们大吃一惊：平均执行耗时1.5ms的接口，竟然还会有这么多请求执行耗时越过100ms！！ 那么这些时间都花在哪里了呢？

目前的监控都是接口的整体执行耗时，我们需要深入接口内部看看时间都花在哪里了。我们对接口分为如下几个部分，并分段监控起来。

监控结果如下所示：

从结果可以看到：

• I/O操作容易抖动，出现较多次100ms+；

• 最简单的CPU操作虽然没有那么多100ms+，但也有不少20ms左右的情况（而且都是从1ms突变到20ms，而不是渐变）。

原来我们是被1.5ms给平均了！什么原因会导致这种长尾效应呢？情况可能有很多，GC（极度怀疑）、CPU时间片分配等。如下是sccis的GC监控：

为此，我们也对比了转转商品服务zzproduct的getProductById()接口，发现也有同样的情况：

getProductById()耗时分布

至此，我们看到业务接口平均执行耗时虽然仅有1.5ms，但仍会出现不少超过100ms的长尾效应，当然框架也会出现。其原因有多种，GC（极有可能）、CPU时间片分配、网络抖动等等。

而这，也确实刷新了我们所有人的认知。

反过来想，如果业务接口要达到公司要求的5个9要求，该怎么办呢？其实很简单，我们可以参照调用方的TP9999来设置超时时间。如下图，scoms调用该接口的TP99999是123ms，而业务把超时时间配置成了100ms，那肯定达不到5个9的标准了。要么把超时时间改为123ms（简单直接），要么优化业务逻辑（目测很难，因为平均执行耗时只有1.5ms）或JVM调优（很有希望）。

基于本文分析，RPC框架也可以针对这种长尾效应做一定优化：不改变超时时间100ms配置情况下，允许一段时间（可配）一些量（可配）的请求在200ms（可配）时间内返回，既提高了服务质量，又不太影响用户体验，我们称之为弹性超时方案。

1）效果

如下图所示，我们在服务管理平台支持按服务&函数设置弹性超时，这里我们将上文zzscoms调zzsccis的IInventoryWrapCacheFacade.lookupWarehouseIdRandom(List)函数配置成每40秒允许15个请求的超时时间延长至1300毫秒。

弹性超时配置

通过配置弹性超时，我们看到这种偶发性的超时基本被容忍消灭掉了，如下图所示：图片

2）适用场景

弹性虽好，可不要贪杯！它更多适用于一些偶发性超时场景，比如网络抖动、GC、CPU抖动、冷启动等，如果是大面积的超时还是需要深入分析治理。

本文深入分析了平均耗时仅有1.5ms的接口也会出现大量100ms+的前因后果，并在框架层面给出了弹性超时的解决方案。这也刷新了我们的认知，由于GC、CPU时间片等原因，一些看起来很简单的操作（如i++）也会出现偶发性长耗时。