記一次線上超時問題的發(fā)現(xiàn)、排查、定位以及解決過程

你好，我是雨樂！

在上一篇文章問題解決了，我卻不知道原因中提到，最近從性能、監(jiān)控方面對引擎進(jìn)行優(yōu)化，這不，監(jiān)控剛上了，就發(fā)現(xiàn)了一個很嚴(yán)重的問題--超時。

今天，借助此文，分享下該問題的發(fā)現(xiàn)、排查以及解決過程！

業(yè)務(wù)背景

在廣告業(yè)務(wù)中，分為效果廣告、KA廣告以及三方廣告等。效果廣告和KA廣告一般都僅限于內(nèi)網(wǎng)，也就是說在內(nèi)網(wǎng)中通過RPC進(jìn)行訪問，而三方廣告，則需要訪問外網(wǎng)，因為外網(wǎng)環(huán)境以及每家三方廣告主的處理能力不同，導(dǎo)致性能不同。本次的超時就是針對的某個三方廣告主。

本次針對三方的業(yè)務(wù)監(jiān)控中，包括對三方廣告主的請求數(shù)、返回數(shù)、qps、rt等指標(biāo)。

收到報警

增加了監(jiān)控的業(yè)務(wù)上線后，根據(jù)引擎監(jiān)控系統(tǒng)來查看三方的基礎(chǔ)數(shù)據(jù)監(jiān)控，如下：

通過上述圖表，看了下平均rt等業(yè)務(wù)指標(biāo)，一切正常。開始著手配置超時等監(jiān)控報警指標(biāo)。鑒于業(yè)務(wù)的重要性，配置了郵件告警和短信告警兩種，配置完成后，一鍵生效。結(jié)果，過了沒幾分鐘，就收到了告警。

看到超時這么多，第一時間先ping下，看看網(wǎng)絡(luò)間耗時咋樣，結(jié)果如下：

64?bytes?from?114.67.237.131:?icmp_seq=1?ttl=49?time=7.13?ms
64?bytes?from?114.67.237.131:?icmp_seq=2?ttl=49?time=6.37?ms
64?bytes?from?114.67.237.131:?icmp_seq=3?ttl=49?time=6.10?ms
64?bytes?from?114.67.237.131:?icmp_seq=4?ttl=49?time=6.07?ms
64?bytes?from?114.67.237.131:?icmp_seq=5?ttl=49?time=6.04?ms
64?bytes?from?114.67.237.131:?icmp_seq=6?ttl=49?time=6.07?ms
64?bytes?from?114.67.237.131:?icmp_seq=7?ttl=49?time=6.03?ms
64?bytes?from?114.67.237.131:?icmp_seq=8?ttl=49?time=6.09?ms
64?bytes?from?114.67.237.131:?icmp_seq=9?ttl=49?time=6.11?ms
64?bytes?from?114.67.237.131:?icmp_seq=10?ttl=49?time=6.03?ms
64?bytes?from?114.67.237.131:?icmp_seq=11?ttl=49?time=6.07?ms

網(wǎng)絡(luò)很穩(wěn)定，看來跟網(wǎng)絡(luò)沒關(guān)系，只能通知對方。

雙方溝通

跟對方反饋其rt超時很嚴(yán)重后，對方第一反應(yīng)是內(nèi)部有些廣告主太耗時，于是其關(guān)閉了超時嚴(yán)重的廣告主，然后讓我這邊繼續(xù)觀察。

待對方關(guān)閉耗時長的廣告主后，重新打開監(jiān)控報警(之前因為報警太頻繁，暫時關(guān)閉了報警)，然后沒有幾分鐘，報警又又又來了。

趕緊在群里跟對方反饋，對方也是一臉懵逼，雙方開始一起排查問題，畢竟沒人跟錢過不去??

為了便于盡快發(fā)現(xiàn)，在測試環(huán)境嘗試將超時時間設(shè)置為2s，然后模擬發(fā)送請求，果不其然，超時。。。

看了對方的反饋，對方在服務(wù)內(nèi)部也設(shè)置了超時，如果200ms內(nèi)沒有得到有效廣告，則返回，也就是說對方也做了200ms的超時控制，很奇怪。。。

在測試環(huán)境將超時時間設(shè)置為50s，仍然有超時現(xiàn)象。。。

對接群溝通多少有點影響到別人，于是勾搭了對方的技術(shù)，開始私聊（此處開始甩鍋模式）

不過，甩鍋歸甩鍋，問題還得解決。開始嘗試使用curl來分析各個階段的耗時：

curl??-o?/dev/null?-s?-w?%{time_namelookup}::%{time_connect}::%{time_starttransfer}::%{time_total}::%{speed_download}"\n"[email protected]?https://www.baidu.com

輸出結(jié)果如下：

從上述結(jié)構(gòu)可以看出，在time_starttransfe階段，也就是說對方業(yè)務(wù)處理結(jié)果仍然會出現(xiàn)2s耗時，問題復(fù)現(xiàn)。

業(yè)務(wù)代碼

雖然該模塊的核心代碼在線上穩(wěn)定運行了5年多，但是為了保險起見，還是得再分析下，免得再遺漏了某個分支條件，導(dǎo)致這種現(xiàn)象發(fā)生。

一般情況下，log是最直接也是最有效的方式，于是在每個步驟每個運行函數(shù)中加了日志，然后編譯、運行，使用之前的測試case重新發(fā)送請求。分析日志，一切都在預(yù)期內(nèi)，看來業(yè)務(wù)代碼沒問題，只能通過其它方式進(jìn)行排查了。

線上抓包

既然業(yè)務(wù)代碼沒問題，那就只能通過tcpdump抓包來分析了，然后經(jīng)過wireshark解析后，結(jié)果如下：

從上面抓包結(jié)果來看，在序號為6的位置，對方返回了http 204，然后又重新手動發(fā)了一次curl請求，在序號10的時候，對方又返回了http 204(從發(fā)送請求到收到對方響應(yīng)耗時38ms)，但是奇怪的時候，在后面50s后，client端(發(fā)送方)開發(fā)發(fā)送FIN請求關(guān)閉連接，從代碼邏輯來分析，是因為超時導(dǎo)致的關(guān)閉連接。

從抓包現(xiàn)象只能得出上述結(jié)論，沒什么有用的結(jié)論，看來只能通過其它方式繼續(xù)分析。

同類對比

既然抓包都不能得到有用的結(jié)論，那就只能通過與其它家正常返回的做對比，看看能不能得到有用結(jié)論。

通過修改業(yè)務(wù)代碼，輸出http相關(guān)信息，如下：

curl_easy_setopt(handle_,?CURLOPT_VERBOSE,?1L);

編譯，運行，發(fā)起curl請求。

正常三方返回如下：

而超時的該家返回如下：

通過對比上述兩家的區(qū)別，發(fā)現(xiàn)超時的該家較正常的三方返回，多了Content-Length、Content-Type等字段，那么有沒有可能跟這幾個字段的返回有關(guān)呢？

問題解決

讓對方在其測試環(huán)境，在沒有廣告返回的時候，將這幾個字段去掉。然后我這邊重新發(fā)起curl請求。。。

然后發(fā)起curl請求，一切正常，在超時范圍內(nèi)返回。wrk壓測，平均rt符合預(yù)期，看來問題就在這。

跟對方溝通后，對方修改代碼，然后著手上線，上線后結(jié)果如下：

效果很明顯，看來就是這個原因?qū)е?，超時問題解決了，收入也就蹭蹭地往上漲了??。

分析原因

既然問題已經(jīng)解決了，多少得知道原因吧，于是在搜索引擎上輸入http 204 Content-Length hang，找到了有用信息，如下：

看來wget之前也存在此類問題，于是繼續(xù)搜索標(biāo)準(zhǔn)，輸出如下：

The presence of a message body in a response depends on both the request method to which it is responding and the response status code (Section 3.1.2). Responses to the HEAD request method (Section 4.3.2 of [RFC7231]) never include a message body because the associated response header fields (e.g., Transfer-Encoding, Content-Length, etc.), if present, indicate only what their values would have been if the request method had been GET (Section 4.3.1 of [RFC7231]). 2xx (Successful) responses to a CONNECT request method (Section 4.3.6 of [RFC7231]) switch to tunnel mode instead of having a message body. All 1xx (Informational), 204 (No Content), and 304 (Not Modified) responses do not include a message body. All other responses do include a message body, although the body might be of zero length.

深入源碼

從上節(jié)標(biāo)準(zhǔn)可以看出，在http 204、304的時候，不允許返回Content-Length，那么如果返回了，libcurl又是如何處理的呢？

于是在curl的issue上進(jìn)行了關(guān)鍵字搜索，得到了如下結(jié)果：

看來已經(jīng)有人提過這個問題了，于是看了下當(dāng)前線上libcurl的源碼：

switch(k->httpcode)?{
????????case?204:
???????????/*?(quote?from?RFC2616,?section?10.2.5):?The?server?has
????????????*?fulfilled?the?request?but?does?not?need?to?return?an
????????????*?entity-body?...?The?204?response?MUST?NOT?include?a
????????????*?message-body,?and?thus?is?always?terminated?by?the?first
????????????*?empty?line?after?the?header?fields.?*/
???????????/*?FALLTHROUGH?*/
????????????????case?304:
???????????/*?(quote?from?RFC2616,?section?10.3.5):?The?304?response
????????????*?MUST?NOT?contain?a?message-body,?and?thus?is?always
????????????*?terminated?by?the?first?empty?line?after?the?header
????????????*?fields.??*/
???????????if(data->set.timecondition)
?????????????data->info.timecond?=?TRUE;
???????????k->size=0;
???????????k->maxdownload=0;
???????????k->ignorecl?=?TRUE;?/*?ignore?Content-Length?headers?*/
???????????break;

線上使用的版本果然沒有處理此種情況，再跟線上做對比，改動如下：

好了，問題已經(jīng)解決，原因也已經(jīng)找到，畢竟不是大bug，為了穩(wěn)妥起見，還是不升級了，以穩(wěn)定為主，誰知道升級后又會出現(xiàn)什么意想不到的問題呢??

結(jié)語

該問題從發(fā)現(xiàn)到解決，大概用了2天的時間。其實，從文章的目錄結(jié)構(gòu)就能發(fā)現(xiàn)，整個問題發(fā)現(xiàn)以及解決過程跟文章目錄結(jié)構(gòu)一致:收到報警->雙方溝通->業(yè)務(wù)代碼->線上抓包->同類對比->問題解決->原因分析->深入源碼。

好了，今天的文章就到這，我們下期見！