記一次生產請求耗時的問題

2022-06-25 09:48:16 字數 2171 閱讀 4560

最近發現lb上記錄的request_time比upstream_response_time大的比較多,例如upstream_response_time記錄是0.062,request_time記錄的就是5.064等等。整個耗時很反常。而且出現這個問題基本上都是乙個返回值比較大的介面,基本上返回值是100k左右。領導讓定位一下這個問題。

先說下我們的架構的背景,是這樣的

阿里雲的slb-------我們自己的lb----------web機器

跟蹤這個問題之後,一直覺得 lb上記錄的upstream_response_time的時間有問題,個人覺得100k的請求0.0xx秒無法完成,從這個入口查了一段時間,沒有任何結果。當然也是收穫的,協助web的同事發現有些請求的cache沒有使用上。後來覺得應該鑽牛角了,第乙個nginx的upstream_response_time肯定是沒有問題的;第二個lb到web是都是內網訪問,快是必然的。後來抓包也確實證明了lb到web特別快,upstream_response_time的時間是正確無誤的。

nagle 演算法的問題?

排除掉upstream_response_time記錄錯誤之後,一直沒有發現。就看了些資料,學習了下課程。看了下極客時間

linux效能優化實戰 課程,40 | 案例篇:網路請求延遲變大了,我該怎麼辦?

看完之後,覺得可能真的是nagle 演算法的問題。解釋下nagle 演算法,nagle 演算法,是 tcp 協議中用於減少小包傳送數量的一種優化演算法,目的是為了提高實際頻寬的利用率。大概意思就是,合併tcp的小包,提高網路頻寬的利用率。覺得可能是nagle 演算法的問題,就把一台lb的tcp_nodelay 開啟了幾小時,發現問題依然存在。那基本就排除nagle 演算法的問題。

後來仔細琢磨了一下,跟nagle 演算法應該沒有關係,nagle 演算法的延遲是40ms才對,我們這個基本上是5秒。

lingering close 的問題

排除掉nagle 演算法的問題之後,又沒有任何方向了。不知道怎麼追查了。後來又抓包檢視,沒有發現有價值的線索。但是確定沒有延遲4秒的,都是延遲5秒的。這是乙個特別重要的線索。當時覺得應該有乙個預設的配置是5秒。

nginx http_core_module裡面搜尋下5s,發現了lingering_timeout 5s; lingering_timeout是個什麼鬼?後來找到一篇跟我們很類似的問題的文章。文章裡面很詳細的解釋了lingering_timeout。

的延遲關閉-lingering-close/

下面的這些解釋都來自上面的文章

該問題是由 nginx 的延遲關閉(lingering close)連線導致的。nginx 為了能夠平滑關閉連線,採用了延遲關閉,它的工作方式如下:nginx 在給客戶端傳送完最後乙個資料報後會首先關閉 tcp 連線的寫端(tcp 是全雙工協議,任何一端都即可讀也可寫),表示服務端不會再向客戶端傳送任何資料,但是不會立即關閉 tcp 連線的讀端,而是等待乙個超時,在超時到達後如果客戶端還沒有資料發來,nginx 才會關閉tcp的讀端,從而關閉整個連線,然後再輸出日誌。另一方面,nginx 是在關閉連線後才輸出日誌,所以在輸出日誌之前響應早就傳送給了使用者,因此對業務幾乎沒有影響。但是這也會導致 requset_time 值變得不準確,使其失去統計意義,開啟 keep-alive 可以部分解決這一問題。

在 nginx 傳送完資料報並進入延遲關閉連線流程後,如果客戶端在 lingering_timeout 時間內沒有進行任何操作,那麼就會關閉與客戶端的連線然後輸出日誌,這就會導致導致訪問日誌滯後 lingering_timeout 才輸出。我們線上並沒有對該引數進行配置,那麼會採用預設值,正好是5秒,與實際情況吻合。另外如果使用長連線,nignx 在請求結束後不需要關閉連線而直接輸出日誌,那麼就不會有這個問題,這也就解釋了為什麼開啟 keep-alive 後問題消失。

基本上是可以確定是lingering_timeout的問題,把生產的一台的lingering_timeout的引數改為4s,發現5s的消失,4s的出現。知道這個原因之後,就能確定,其實真正的耗時有可能是2s 3s,只不過延遲關閉了,寫日誌的時間是5s。文章也介紹了只要客戶端設定keep-alive長連線,nginx就不會關閉連線,寫日誌時間就會快很多。但是阿里雲的slb不能開啟長連線,因為這個問題,對我們來說是無解的,我們可以將lingering_timeout設定短一點,但是延時關閉的問題是不可避免的。好在是我們知道了原因,並不是真正的處理慢了,只不過是延時關閉導致日誌時間有誤。

記一次生產報too man open files

有一天私有雲無法訪問,馬上聯絡廠商,最後廠商發現好多容器不停重啟,經過日誌檢視發現平台開啟檔案控制代碼太多,很奇怪,就開始排查,最後發現乙個埠,定位到應用spring actuator.這個應用是我為了監控微服務而發布的乙個監控應用,馬上看日誌,發現應用報錯,too many open files,...

記一次生產Slor分組的bug

solr的facet有多種形式,它們的引數不盡相同。可以用於text或者string型別的字段。引數說明 facet.field 需要做facet查詢的字段,必須指定,否則其他引數無效 facet.sort 排序規則,可以是count 預設值,由大到小 或index 字典順序 facet.limit...

記一次生產環境thrift服務的配置問題

問題現象 有客戶反饋我們的產品有時反應很慢,處理會出現超時。問題分析過程 1.第一反應可能是使用者增加,併發量太大了,詢問了運營,最近使用者註冊資料並沒有猛增。2.分析access日誌,發現有隔一段時間會出現幾個連續的請求響應時長超過30秒,並且這些請求都是使用乙個thrift服務的,而連redis...