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


最近發現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秒。http://nginx.org/en/docs/http/ngx_http_core_module.html#
nginx http_core_module里面搜索下5s,發現了lingering_timeout 5s; lingering_timeout是個什么鬼?后來找到一篇跟我們很類似的問題的文章。文章里面很詳細的解釋了lingering_timeout。
http://shibing.github.io/2016/11/18/nginx的延遲關閉-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設置短一點,但是延時關閉的問題是不可避免的。好在是我們知道了原因,並不是真正的處理慢了,只不過是延時關閉導致日志時間有誤。

------------------------------------end
一起關注高性能WEB后端技術,關注公眾號


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM