1.背景

一個(gè)春暖花開(kāi)的午后，客服技術(shù)部佩姐（P）找過(guò)來(lái)向我們反饋一個(gè)問(wèn)題，如下是我們的對(duì)話：

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

如下開(kāi)始本篇的研究之旅。

2 驗(yàn)證與分析

2.1 準(zhǔn)備工作

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

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

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

2.2 驗(yàn)證

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

圖片

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

圖片

太讓人震驚了?。?！

2.3 問(wèn)題分析

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

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

因?yàn)榭蚣芎臅r(shí)復(fù)雜多變，不好統(tǒng)計(jì)，我們可以統(tǒng)計(jì)業(yè)務(wù)的執(zhí)行耗時(shí)分布，以此來(lái)判斷問(wèn)題出在框架上還是出在業(yè)務(wù)上。

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

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

耗時(shí)分布

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

2.4 排查

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

圖片

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

圖片

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

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

2.5 原因

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

圖片

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

getProductById()耗時(shí)分布

3.解決方案

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

而這，也確實(shí)刷新了我們所有人的認(rèn)知。

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

圖片

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

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

3.1.1 效果

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

彈性超時(shí)配置

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

圖片

3.1.2 適用場(chǎng)景

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

4 總結(jié)

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

關(guān)于作者

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