服務(wù)端頻繁出現(xiàn)100毫秒延遲的原因是什么

這篇文章主要講解了“服務(wù)端頻繁出現(xiàn)100毫秒延遲的原因是什么”，文中的講解內(nèi)容簡(jiǎn)單清晰，易于學(xué)習(xí)與理解，下面請(qǐng)大家跟著小編的思路慢慢深入，一起來研究和學(xué)習(xí)“服務(wù)端頻繁出現(xiàn)100毫秒延遲的原因是什么”吧！

背景說明

陌陌的微服務(wù)框架支持Redis協(xié)議調(diào)用方式， 在使用Redis協(xié)議調(diào)用MOA服務(wù)時(shí)， 每個(gè)請(qǐng)求會(huì)被包裝為一個(gè)消息， 這個(gè)消息會(huì)用一個(gè)唯一ID來標(biāo)識(shí)，ID是由機(jī)器名稱+進(jìn)程ID+消息產(chǎn)生的時(shí)間戳組成，當(dāng)請(qǐng)求消息經(jīng)過網(wǎng)絡(luò)到達(dá)服務(wù)端應(yīng)用后，MOA框架在處理消息前會(huì)先用當(dāng)前時(shí)間減去消息的產(chǎn)生時(shí)間，如果差值大于100毫秒則會(huì)記錄該請(qǐng)求到慢請(qǐng)求文件中。正常請(qǐng)求下該文件幾乎不會(huì)產(chǎn)生數(shù)據(jù)，但是最近多名業(yè)務(wù)側(cè)同學(xué)反饋慢請(qǐng)求文件數(shù)據(jù)較多，導(dǎo)致TP90數(shù)據(jù)飆高，希望幫忙排查原因。

排查過程

是否是容器問題？

陌陌的應(yīng)用層全部跑在Docker容器上，為了排查容器自身因素，將該服務(wù)的部分實(shí)例遷到了VM上，對(duì)比發(fā)現(xiàn)VM上的實(shí)例基本上沒有慢請(qǐng)求日志，所有基本確定該問題跟Docker容器相關(guān)。

網(wǎng)絡(luò)不穩(wěn)？

2018-12-18 12:23:40,822 REQUEST: Command [id=xxxxxxx-kube-node-web-php-

198861545107020.6728, action=/service/xxxx-action-service, source=127.0.0.1, thread=, params={args=[ap6896299708], m=getXxxRecReadNum}]  ### waitedTime: 103 ms

對(duì)比消息產(chǎn)生時(shí)間和服務(wù)端接收到數(shù)據(jù)包時(shí)間可知消息傳遞的網(wǎng)絡(luò)耗時(shí)幾乎可忽略，排除網(wǎng)絡(luò)不穩(wěn)定帶來的影響。

網(wǎng)卡到socket讀緩存區(qū)慢了？

通過上面tcpdump結(jié)果來說，數(shù)據(jù)從網(wǎng)卡到ReveiveQ再到用戶態(tài)獲取數(shù)據(jù)這一個(gè)過程也是及時(shí)的，為了再次驗(yàn)證這個(gè)結(jié)論，運(yùn)維同學(xué)通過systemtap工具在tcp_v4_do_rcv調(diào)用時(shí)，將skb的內(nèi)容打印出來，并將調(diào)用時(shí)間打印出來，通過比較系統(tǒng)調(diào)用時(shí)間和skb中的消息時(shí)間比對(duì)發(fā)現(xiàn)基本一致。 

//probe kernel.statement("tcp_rcv_established@net/ipv4/tcp_input.c:5256") {

probe kernel.function("tcp_v4_do_rcv").return {

	saddr = ip_ntop(@entry($sk->__sk_common->skc_daddr))

	daddr = ip_ntop(@entry($sk->__sk_common->skc_rcv_saddr)){

	if (saddr == "{source Addr}" && daddr == "{target Addr}")

		printf("taptime:%d, pid: %d,  %s:%d --> %s, %s\n", 

		gettimeofday_ms(),

		tid(),

		saddr,

		ntohs(@entry($sk->__sk_common->skc_dport)),

		daddr,

		__buffer_data(@entry($skb), 1)

	}

}

Read系統(tǒng)調(diào)用不及時(shí)？

hack read系統(tǒng)，在read調(diào)用時(shí)， 對(duì)比read觸發(fā)的時(shí)間和read到的消息題中的時(shí)間已經(jīng)延遲較大，這個(gè)值幾乎跟應(yīng)用層面記錄的waitedTime一致。至此可以確定是發(fā)起read調(diào)用時(shí)就已經(jīng)出現(xiàn)了時(shí)延。

probe syscall.read {

	try {

	   if (pid() == {target Pid}) {

		printf("taptime: %d, data: %s\n", gettimeofday_ms(),       

		kernel_string($buf))

	   }

	} catch (msg) {

		println("caught error ", msg)

	}

}

原因分析

一.  Read調(diào)用不及時(shí)原因

當(dāng)消息到達(dá)Socket ReceiveQ時(shí)，epollwait系統(tǒng)調(diào)用的阻塞會(huì)被喚醒，同時(shí)給應(yīng)用層返回指定socket的readable事件，Netty IO線程響應(yīng)可讀事件進(jìn)行read調(diào)用，但是實(shí)際卻沒有立刻進(jìn)行read調(diào)用。大都數(shù)情況下是因?yàn)樵贗O線程中執(zhí)行了耗時(shí)操作，導(dǎo)致worker eventloop group中沒有可用線程去拉取數(shù)據(jù)，但是顯然這和MOA的實(shí)現(xiàn)機(jī)制是沖突的，業(yè)務(wù)處理邏輯在業(yè)務(wù)線程中執(zhí)行，IO線程并沒有耗時(shí)操作。還有就是GC導(dǎo)致整個(gè)應(yīng)用STW，通過查看應(yīng)用日志的確找到了相關(guān)線索，在實(shí)例GC日志上偶爾刷出了100ms+的YoungGC日志，YGC的執(zhí)行會(huì)STW，線上服務(wù)使用的是ParNew 并發(fā)收集策略，頻率基本跟服務(wù)耗時(shí)突刺吻合。所以問題轉(zhuǎn)變?yōu)闉槭裁闯霈F(xiàn)100msGC。

二.  100ms YGC的原因

對(duì)比GC日志，發(fā)現(xiàn)單次耗時(shí)超過100ms的GC與正常較少耗時(shí)的YGC相比，GC前后的內(nèi)存占用情況并沒有較大差異，即并不是因?yàn)閱未蜧C的內(nèi)存大導(dǎo)致GC耗時(shí)增加。

在一籌莫展之際，運(yùn)維同事發(fā)現(xiàn)了一個(gè)現(xiàn)象就是ParallelGCThreads線程數(shù)出乎意料的多，調(diào)整ParallelGCThreads，限制在4個(gè)線程，問題解決！但是這個(gè)數(shù)字怎么算出來的呢？我們看下 GC 線程數(shù)據(jù)的計(jì)算規(guī)則：cpu 核數(shù)小于8 gc 線程數(shù)等于cpu核數(shù)，大于8的時(shí)候=8+(cpu數(shù)-8)*?。同時(shí)運(yùn)維同學(xué)給出信息，JDK 8u131 版本開始增加了識(shí)別 Docker 資源的改進(jìn)，但不能識(shí)別 cpu shares 或 cpu quotas 配置的 CPU 資源，內(nèi)存資源的識(shí)別也沒有默認(rèn)開啟，需指定相關(guān)參數(shù)，這個(gè)問題在JDK 8u191版本得到了改進(jìn)，能夠正確識(shí)別 Docker 的 CPU 、內(nèi)存資源配置信息。至此100msGC的原因得到了確認(rèn)是因?yàn)镴DK版本不能正確識(shí)別DockerCPU配置，導(dǎo)致整ParallelGCThreads個(gè)數(shù)異常增大，導(dǎo)致YGC突刺。為什么整ParallelGCThreads個(gè)數(shù)多導(dǎo)致YGC突刺？

三. ParallelGCThreads個(gè)數(shù)多導(dǎo)致YGC突刺的原因

發(fā)現(xiàn)linkedin同樣遇到了這樣的問題，并將詳細(xì)的原因做了描述（詳見引用一）

在CFS（引用二）中， 一個(gè)cgroup被分配確定的cpu配額（cfs_quota），這些配額快速被活躍的JVM GC多線程用盡，最終導(dǎo)致應(yīng)用資源被限制。

舉例說明：

1. 如果一個(gè)應(yīng)用在一個(gè)調(diào)度周期內(nèi)積極的使用CPU資源達(dá)到CPU配額，那么這個(gè)應(yīng)用會(huì)被限制（沒有更多的CPU給它）然后導(dǎo)致在這個(gè)應(yīng)用被暫停在整個(gè)調(diào)度周期剩余的時(shí)間中。

2. 多線程的JVM GC使得問題變的更差，因?yàn)閏fs_quota是統(tǒng)計(jì)這個(gè)應(yīng)用的所有線程，因此CPU配額會(huì)被更快的使用掉，JVM GC有多個(gè)并行階段是不會(huì)STW (stop the world)的，但是這些運(yùn)行的多線程會(huì)導(dǎo)致CPU配額更快被消耗完而受到cgroup限制，引起應(yīng)用發(fā)生STW。

作者詳細(xì)舉例闡述了上面的內(nèi)容：

理想情況下，CPU調(diào)度程序會(huì)調(diào)度應(yīng)用程序在每個(gè)CFS周期內(nèi)稀疏運(yùn)行，以便應(yīng)用程序不會(huì)長(zhǎng)時(shí)間暫停。如下圖所示，應(yīng)用程序計(jì)劃在300毫秒CFS期間運(yùn)行3次。計(jì)劃運(yùn)行之間存在應(yīng)用程序暫停，預(yù)期應(yīng)用程序暫停為70毫秒（假設(shè)應(yīng)用程序完全使用90毫秒CPU配額）。

第一個(gè)問題發(fā)生在應(yīng)用程序耗盡90ms的所有cpu配額時(shí)，例如在某些CFS時(shí)段的前90ms內(nèi)。然后，由于配額被占用，在剩余的210ms期間，應(yīng)用程序暫停，用戶經(jīng)歷210ms延遲。請(qǐng)注意，多線程應(yīng)用程序的問題更嚴(yán)重，因?yàn)镃PU配額可以更快地用完。

GC STW暫停期間，Java應(yīng)用程序更嚴(yán)重，因?yàn)镴VM可以使用多個(gè)GC線程并行收集垃圾。

對(duì)于流行的JVM垃圾收集器，如CMS和G1，GC有多個(gè)階段; 某些階段是STW，其它階段是concurrent（非STW）。盡管并發(fā)GC階段（使用并發(fā)GC線程）旨在避免JVM STW，但cgroup的使用完全違背了這個(gè)目的。在并發(fā)GC階段使用的CPU時(shí)間也會(huì)計(jì)入cgroup的CPU使用計(jì)算，這實(shí)際上會(huì)導(dǎo)致應(yīng)用程序遇到更大的STW暫停。

由于JVM GC和CFS調(diào)度之間的交互，在Linux cgroup中運(yùn)行的Java應(yīng)用程序可能會(huì)遇到更長(zhǎng)的應(yīng)用程序暫停。為緩解此問題，作者建議使用以下調(diào)整：

a: 充分配置CPU資源（即CFS配額）。顯然，分配給cgroup的CPU配額越大，cgroup被限制的可能性就越小。

b: 適當(dāng)調(diào)整GC線程。

結(jié)論總結(jié)

1. 至此，整個(gè)排查過程就結(jié)束了，導(dǎo)致應(yīng)用被暫停執(zhí)行的根本原因是：因?yàn)镴VM GC機(jī)制和CFS調(diào)度的互相影響，導(dǎo)致更長(zhǎng)的STW耗時(shí)，進(jìn)而對(duì)應(yīng)用產(chǎn)生影響。

2. 完善公司體系內(nèi)的Docker容器監(jiān)控，增加CPU受限監(jiān)控。

名詞解釋

MOA   MOA的全稱是Momo (Service) Oriented Architecture，是由陌陌技術(shù)團(tuán)隊(duì)研發(fā)的一個(gè)RPC服務(wù)框架。該框架于2012年底投入使用，目前是陌陌實(shí)現(xiàn)遠(yuǎn)程調(diào)用、跨語(yǔ)言通信等最重要的基礎(chǔ)框架之一

感謝各位的閱讀，以上就是“服務(wù)端頻繁出現(xiàn)100毫秒延遲的原因是什么”的內(nèi)容了，經(jīng)過本文的學(xué)習(xí)后，相信大家對(duì)服務(wù)端頻繁出現(xiàn)100毫秒延遲的原因是什么這一問題有了更深刻的體會(huì)，具體使用情況還需要大家實(shí)踐驗(yàn)證。這里是億速云，小編將為大家推送更多相關(guān)知識(shí)點(diǎn)的文章，歡迎關(guān)注！