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++）也會出現偶發性長耗時。

關于作者

杜云杰，高級架構師，轉轉架構部負責人，轉轉技術委員會執行主席，騰訊云TVP。負責服務治理、MQ、云平臺、APM、分布式調用鏈路追蹤、監控系統、配置中心、分布式任務調度平臺、分布式ID生成器、分布式鎖等基礎組件。