1.背景

一個春暖花開的午后，客服技術(shù)部佩姐（P）找過來向我們反饋一個問題，如下是我們的對話：

P：云杰，我們最近在治理服務(wù)質(zhì)量，有個接口的成功率達不到公司標準5個9。
 
我：贊，你們也開始質(zhì)量治理了，詳細說說。
 
P：我們sccis有個重要的lookupWarehouseIdRandom接口，先查詢緩存，未命中的再從數(shù)據(jù)庫查并回寫到緩存，平均執(zhí)行耗時只有1.5ms。現(xiàn)在scoms在調(diào)它，超時時間配的還是100ms，結(jié)果發(fā)現(xiàn)每天還有500多個超時，成功率不到5個9，達不到公司標準。你們框架是不是有問題啊，幫忙看看！
 
我：不至于吧！？平均執(zhí)行耗時1.5ms，在調(diào)用方超時時間配100ms（60多倍！）的情況下竟然還有這么多超時？
 
P：真的！！不信你看看！！！
 
我：看看就看看！

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

2 驗證與分析

2.1 準備工作

在開始驗證之前，先簡要介紹下轉(zhuǎn)轉(zhuǎn)RPC框架SCF的調(diào)用過程，如下圖所示：

• 序列化：SCF接收到調(diào)用方的請求，做負載均衡、序列化等；
• 發(fā)送：SCF將序列化后的二進制流通過網(wǎng)絡(luò)發(fā)送給服務(wù)方結(jié)點；
• 反序列化：服務(wù)方結(jié)點接收到數(shù)據(jù)后，將數(shù)據(jù)交給SCF，做反序列化、排隊等；
• 執(zhí)行：SCF將請求交由服務(wù)方的實現(xiàn)方法進行處理；
• 序列化：SCF將服務(wù)方的處理結(jié)果序列化為二進制數(shù)據(jù)流；
• 發(fā)回：將數(shù)據(jù)發(fā)回給調(diào)用方；
• 反序列化：調(diào)用方SCF收到請求后，將二進制數(shù)據(jù)反序列化為對象交由調(diào)用方代碼，使得調(diào)用方看起來跟本地方法調(diào)用一樣。

如上是一次完整的RPC調(diào)用鏈路。

2.2 驗證

通過監(jiān)控我們發(fā)現(xiàn)接口的平均執(zhí)行耗時確實在1.5ms左右，如下圖所示：

圖片

但調(diào)用方scoms在超時時間為100ms的情況下確實仍然有很多請求超時：

圖片

太讓人震驚了！！！

2.3 問題分析

通過如上的RPC調(diào)用過程鏈路示意，我們可以看出任意一個子過程都可能會發(fā)生抖動，造成超時。但我們可以從整體上把鏈路分為框架和業(yè)務(wù)兩個部分（分界點如圖所示）：

• 框架：指底層的網(wǎng)絡(luò)和SCF耗時，屬于客觀原因，包括圖中的1、2、3、5、6、7；
• 業(yè)務(wù)：單純指業(yè)務(wù)服務(wù)的執(zhí)行4，屬于主觀原因。

因為框架耗時復(fù)雜多變，不好統(tǒng)計，我們可以統(tǒng)計業(yè)務(wù)的執(zhí)行耗時分布，以此來判斷問題出在框架上還是出在業(yè)務(wù)上。

• 如果業(yè)務(wù)的執(zhí)行耗時分布都非常低，那就說明超時花在了框架上；
• 如果業(yè)務(wù)的執(zhí)行耗時分布都有很多高耗時的，那就說明超時花在了業(yè)務(wù)邏輯上。

正好服務(wù)方的接口有耗時分布監(jiān)控，通過監(jiān)控我們發(fā)現(xiàn)絕大部分情況都在5ms內(nèi)處理完成，但仍有314個請求處理時間直接超過了100ms！！！

耗時分布

這個發(fā)現(xiàn)也讓我們大吃一驚：平均執(zhí)行耗時1.5ms的接口，竟然還會有這么多請求執(zhí)行耗時越過100ms！！ 那么這些時間都花在哪里了呢？

2.4 排查

目前的監(jiān)控都是接口的整體執(zhí)行耗時，我們需要深入接口內(nèi)部看看時間都花在哪里了。我們對接口分為如下幾個部分，并分段監(jiān)控起來。

圖片

監(jiān)控結(jié)果如下所示：

圖片

從結(jié)果可以看到：

• I/O操作容易抖動，出現(xiàn)較多次100ms+；
• 最簡單的CPU操作雖然沒有那么多100ms+，但也有不少20ms左右的情況（而且都是從1ms突變到20ms，而不是漸變）。

2.5 原因

原來我們是被1.5ms給平均了！什么原因會導(dǎo)致這種長尾效應(yīng)呢？情況可能有很多，GC（極度懷疑）、CPU時間片分配等。如下是sccis的GC監(jiān)控：

圖片

為此，我們也對比了轉(zhuǎn)轉(zhuǎn)商品服務(wù)zzproduct的getProductById()接口，發(fā)現(xiàn)也有同樣的情況：

getProductById()耗時分布

3.解決方案

至此，我們看到業(yè)務(wù)接口平均執(zhí)行耗時雖然僅有1.5ms，但仍會出現(xiàn)不少超過100ms的長尾效應(yīng)，當然框架也會出現(xiàn)。其原因有多種，GC（極有可能）、CPU時間片分配、網(wǎng)絡(luò)抖動等等。

而這，也確實刷新了我們所有人的認知。

反過來想，如果業(yè)務(wù)接口要達到公司要求的5個9要求，該怎么辦呢？其實很簡單，我們可以參照調(diào)用方的TP9999來設(shè)置超時時間。如下圖，scoms調(diào)用該接口的TP99999是123ms，而業(yè)務(wù)把超時時間配置成了100ms，那肯定達不到5個9的標準了。要么把超時時間改為123ms（簡單直接），要么優(yōu)化業(yè)務(wù)邏輯（目測很難，因為平均執(zhí)行耗時只有1.5ms）或JVM調(diào)優(yōu)（很有希望）。

圖片

3.1 框架優(yōu)化-彈性超時

基于本文分析，RPC框架也可以針對這種長尾效應(yīng)做一定優(yōu)化：不改變超時時間100ms配置情況下，允許一段時間（可配）一些量（可配）的請求在200ms（可配）時間內(nèi)返回，既提高了服務(wù)質(zhì)量，又不太影響用戶體驗，我們稱之為彈性超時方案。

3.1.1 效果

如下圖所示，我們在服務(wù)管理平臺支持按服務(wù)&函數(shù)設(shè)置彈性超時，這里我們將上文zzscoms調(diào)zzsccis的IInventoryWrapCacheFacade.lookupWarehouseIdRandom(List)函數(shù)配置成每40秒允許15個請求的超時時間延長至1300毫秒。

彈性超時配置

通過配置彈性超時，我們看到這種偶發(fā)性的超時基本被容忍消滅掉了，如下圖所示：

圖片

3.1.2 適用場景

彈性雖好，可不要貪杯！它更多適用于一些偶發(fā)性超時場景，比如網(wǎng)絡(luò)抖動、GC、CPU抖動、冷啟動等，如果是大面積的超時還是需要深入分析治理。

4 總結(jié)

本文深入分析了平均耗時僅有1.5ms的接口也會出現(xiàn)大量100ms+的前因后果，并在框架層面給出了彈性超時的解決方案。這也刷新了我們的認知，由于GC、CPU時間片等原因，一些看起來很簡單的操作（如i++）也會出現(xiàn)偶發(fā)性長耗時。

關(guān)于作者

杜云杰，高級架構(gòu)師，轉(zhuǎn)轉(zhuǎn)架構(gòu)部負責人，轉(zhuǎn)轉(zhuǎn)技術(shù)委員會執(zhí)行主席，騰訊云TVP。負責服務(wù)治理、MQ、云平臺、APM、分布式調(diào)用鏈路追蹤、監(jiān)控系統(tǒng)、配置中心、分布式任務(wù)調(diào)度平臺、分布式ID生成器、分布式鎖等基礎(chǔ)組件。