開發與維運

收藏!Tengine問題排查必備

image.png

假如日誌欺騙了你,不要悲傷,看下這篇文章吧。

一 前言

在日常排查問題或者同用戶連調的時候,是否經常會遇到,在access_log裡看到用戶請求很快,但用戶卻反饋很慢?

在日誌中看到用戶的請求都成功了,用戶卻反饋說有大量請求失敗等一系列自己看到的和用戶描述不一致的問題,有時候會懷疑用戶搞錯了,等用戶貼出截圖的時候又懷疑自己搞錯了,如果有遇到這類問題,這篇文章或許對你有幫助。

二 Tengine打access_log 時機

在接著往下介紹之前,先看下Tengine打access_log的時機,清楚了這個後,再接著往下看會清晰很多。

Tengine的access_log是在Tengine“認為”這個請求結束後才打的,對於正常請求,Tengine會在請求最後一個字節發出後認為請求結束;對於異常請求,當Tengine判斷連接超時或者異常斷開,無法再發送和接收數據的時候。通常情況下可以認為Tengine在請求結束後隨即會打出日誌。

三 如何理解Tengine的"請求最後一個字節發出"

Tengine認為請求最後一個字節發出後,該請求就結束了,其實最後一個字節發出可以理解為最後一串數據發出,這裡是“發出”而不是用戶收到,指的是將最後一串數據填到協議棧中,只要send 成功返回,Tengine就認為結束了,至於數據是否被客戶端收到那就是協議棧和網絡上的事情了,Tengine不會去關心。

四 為什麼服務端看到的延時同客戶端不一致

4.1 服務端request_time_msec的含義

要搞清楚這個問題,首先我們要明確Tengine access_log中的“request_time_msec” 字段到底表達了什麼含義。

我們先看下官方文檔是怎麼說的:

$request_time
request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client.

這個字段表示的是從請求的第一個字節開始到請求最後一個字節發出後所經歷的時間。

這裡其實包含如下幾點信息:

  1. 建連的時間是不會被算進去的。

  2. 如果是HTTPS請求,建連及HTTPS握手的時間都不會被算進去。

  3. 最後一個字節發出後Tengine認為請求結束,數據僅僅是填在協議棧中,從協議棧Buffer中的數據發送給用戶的這段時間是不被算進去的。

  4. 連接揮手的過程是不會被算進去。

注:從長連接的角度去看,上述1、2、4的時間不被算進去還是好理解的。

4.2 客戶端看到的E2E時間

4.1節中分析的request_time_msec從服務器端看到的請求E2E時間,而用戶看到的時間,假設用戶用curl去測試:

time curl https://bucket.oss-cn-hangzhou.aliyuncs.com/object

那麼上面4.1節提到的幾點不會算到服務器端時間的計算邏輯裡的,除了4都會被客戶端計算進去。

針對延時不一致,下面我們從HTTP的上傳下載,具體分析一下這個延時區別,是否差,差多少。

4.3 上傳類請求延時差異

針對於上傳來說,服務器端和客戶端看到的延時差異不大,相差一個握手/和最後返回的Header發送回去的時間。

握手到服務器端收到請求首字節2rtt,請求完成後返回的HEADER數據一般不會很大可以塞在1個cwnd內發完,需要一個0.5個rtt,一共是2.5個rtt。如果是長連接,忽略三次握手的話,那麼看到的差異為1個rtt。

因此針對上傳類請求,客戶端和服務器端看到的延時差距為2.5個RT,如果是長連接(非連接上首個請求)的話差異為1個rtt。

4.4 下載類請求延時差異

關於下載請求的延時差異會稍微複雜一些。上傳的情況下,服務器只會有HTTP狀態碼和一些HTTP Header,通常一個rtt就可以發完。而下載,通常服務器會有較多的數據發送給客戶端,Tengine把最後一串數據填在協議棧的Buffer裡,如果在Buffer中的數據能在一個rtt內發完,那麼同上傳類請求一致,否則就會比上傳類請求的差異大。至於協議棧Buffer中最後一串數據花多長時間能發送到客戶端,這個就不太好估計了,取決於當時的網絡狀況及當時的擁塞窗口大小,需要具體情況具體分析。

在網絡情況不錯並且服務器端Buffer配置較小情況下,通常差距不大,但是如果客戶端網絡差,而服務器端Buffer配置較大的情況下,差距會比較大。比如此時客戶端網絡比較差,只達到100KB/s, 而服務器端協議棧Buffer配置的較大,為1M,Tengine最後一串數據把1M Buffer填滿後Tengine認為請求已經結束了,而實際上客戶端在10s之後才完整的收到請求應答數據,才認為結束。大家可以用wget測試一下,分別觀察下服務器端和客戶端看到的請求時間:

wget your-bucket.oss-cn-hangzhou.aliyuncs.com/tmp/1m-file --limit-rate=10k --debug

注:wget這個限速是在應用層面做的,測試看到的時間差異除了服務端Buffer的原因,還有客戶端Buffer的原因,數據到達客戶端協議棧,而應用因限速而遲遲不讀。

4.5 總結

服務器端看到的E2E時間“request_time_msec” 時間是Tengine收到請求的首字節開始,到最後一個字節寫到協議棧的時間。

客戶端看到的E2E時間相比服務器多了:客戶端建聯及HTTPS 握手時間、請求首字節發送到服務器的時間、外加Tengine認為請求結束後協議棧將Buffer中的數據遞送到客戶端的時間。

因此當客戶抱怨延時高而服務器端看到卻很快的時候,可能客戶說的也對,你看到的也對,這時候就需要根據上述分析,判斷具體是哪裡導致客戶端和服務器端看到延時差距,進而快速定位問題。

服務器端慢是真的慢,但是服務器端看到快,可不一定真的快。

五 服務器端看到的請求成功和客戶端看到的請求成功

接下來分析的都是小概率事件,正常情況下通常不會遇到,主要針對出問題時的分析。

服務器端看到的成功,是服務器端正確處理這個請求,並把數據發送到協議棧後,服務器就會認為請求已經成功。

客戶端看到請求成功,是收到服務器端返回的狀態碼及完整的body後才認為請求成功。

5.1 access_log看到的“200 OK”

access_log裡的狀態碼,只要請求的header已經發出去,那麼狀態碼就確定了,access_log裡面打出來的狀態碼也是確定的。

如果是上傳類請求,access_log裡打印出狀態碼為200,那麼請求一定是成功了(但是客戶端不一定能感知到這個成功)。

如果是下載類請求,access_log裡打印出來的狀態碼是200,那麼請求不一定成功,可能body並未發完請求就異常結束了。

5.2 寫到協議棧裡的數據不一定能發送出去

Tengine把數據寫到協議棧的Buffer中後,從Tengine的角度來說,可以認為數據已經發往客戶端了,但從實際角度來看,數據寫到協議棧僅僅是寫到協議棧,至於寫到協議棧的數據是否能否真正被髮送出去,是不一定的。在協議棧數據還沒發出去之前可能網絡中斷了,或者連接被reset 了,都會可能發生。這是造成客戶端和服務器端看到有差異的一個主要原因。

有的同學會問,TCP不是可靠的傳輸協議嘛,怎麼會發不過去?建議看下這篇文章,就明白TCP的可靠性具體指的是什麼了。文章地址:
https://blog.csdn.net/dog250/article/details/82177299

六 單連接最低下載速度

6.1 為什麼會有最低下載速度限制

針對系統性能指標,通常我們會描述一個單連接峰值吞吐的數值,但是實際上一個還有一個最低速度的限制。那麼這個最低速度是怎麼來的呢?

一個正常C/S架構的系統,通常會有很多Buffer,會設置很多超時時間,針對Tengine會有send_timeout,recv_timeout,keepalive_timeout等各種超時限制。這就會造成系統會有一個最小下載速度的限制。

像上面描述的各類超時時間,其實是會隨著各類網絡事件觸發設置及更新。在Linux環境下,套接字可寫就是其中一個事件,如果套接字長時間不可寫,超過Tengine配置的send_timeout,那麼就會觸發超時,引發Tengine主動斷開連接,甚至reset連接。Linux TCP 套接字在該套接字上的剩餘Buffer空間大於總Buffer 1/3 才會被epoll 等“反應堆”返回可寫,也就是說,如果Buffer被填滿後,在timeout時間內,Buffer中的數據1/3 還沒被發出去的話,就會觸發定時器超時,導致請求異常中斷。假設Buffer配置的是512k,send_timeout配置的是30s。那麼必須在30s內發送出去170k才行,也就是最低要達到5.69KB/s的速度才行。

6.2 如何獲取系統最低下載速度

正常情況下,我們可以通過分析系統中各個Buffer 的大小及超時時間計算出一個理論的最低下載速度,但是一個複雜的系統,很難理清楚或者找到各個位置的Buffer 大小及超時時間。因此我們可以利用wget的 --limit-rate 功能進行二分測試,直到找到最低下載速度的零界點,注意下載的時候文件不要選擇太小,選擇太小了會測試不出來,當然也不要太大,太大了會造成測試時間過長,設置為系統最大Buffer的2倍左右即可。

二分測試過程:

low_rate = 0k, up_rate = 100k
deviation = 5k
while up_rate - low_rate < deviation
   mid_rate = (low_rate + up_rate)/2
    wget url --limit-rate mid_rate
    if succ then 
        up_rate = mid_rate 
    else 
       low_rate = mid_rate

print low_rate, up_rate

如下是測試OSS最低下載速度:

  • 單連接持續5k以內:速度必然出問題(一般持續30s+出問題)。

  • 單連接持續5 ~10k以內:速度隨機出問題,看系統狀況(比較具有偶然性)。

  • 單連接持續10k+:基本不出問題。

根據上述6.1節中的理論和6.2節中的測試方法,我們甚至可以測試出來服務器端設置的sndbuf有多大。

6.3 如何解決

在正常情況下,這個最低下載速度並不會造成什麼問題,因為大家都想方設法讓速度更快,但是有些計算密集型的場景,可能會遇到這個問題。比如說之前遇到一個OSS客戶,從OSS一個文件中讀10k數據,處理30s,然後再讀10k數據,再處理30s,處理一段時間後發現服務器端數據沒發完就莫名其妙關閉連接了。其實就是遇到“最低下載速度問題”了。

針對上述情況,客戶端不要在一個請求上一條連接反反覆覆緩慢讀數據,如果文件不大,可以考慮一次性全讀出來,放內存或者本地再慢慢處理。如果文件太大,可以使用RangeGet,需要多少數據就從服務器端RangeGet讀多少。

注:針對上傳類請求,通常來說沒有速度下限要求。

6.4 為什麼復現不出來

有同學使用wget/curl的limit_rate功能把連接速度限制到很低,但是復現不出來最低下載速度的問題,這是因為測試的文件太小了,測試的文件大小需要比客戶端的rcvbuf + 服務端的sndbuf還要大才能測試出來,否則數據堆在兩端的協議棧裡,是觸發不到應用的超時時間限制的。

七 access_log中的400、408及499

7.1 產生原因

400是很普通的錯誤碼,但是在Tengine裡也有不是普通“400”的時候,在這裡我們只介紹非普通400的情況。

408及499在Tengine中是不會作為錯誤碼返回給用戶的(除非upstream返回了),只是Tengine利用了這兩個狀態碼標識請求的一種完成狀態。這兩種錯誤碼都是和時間相關,但是是不同場景下產生,都是在服務端才能看到的狀態,客戶端是感知不到的。

  • 400,如果用戶請求數據還未發完之前,客戶端主動斷開或者連接異常斷開(如被reset 掉),在Tengine的access_log 中計為400。

  • 499,客戶端關閉請求,在proxy 場景下確切的說是客戶端先於proxy upstream 返回前斷開,Tengine在做proxy 的情況下(fastcgi_pass/proxy_pass 等),同一請求鏈路上,客戶端與Tengine的連接先於Tengine後端返回前斷開,此時在Tengine的access_log中計為499的日誌。

  • 408,客戶端請求超時,確切說客戶端發送數據超時,客戶端向服務器發送請求數據時中間因某種原因中斷了一會,引起服務器端讀數據超時,此時在Tengine的access_log中會記為408。注意,發送header和發送body可能會有不同的超時時間。

7.2 如何復現

400請求數據發完之前提前斷開連接,nc建立連接後輸入完成Host頭部後Ctrl + c斷掉,或者發送PUT請求在body沒有發送完成之前Ctrl + c掉。

408客戶端發送超時,nc建立連接後輸入完成Host 頭部後等待連接超時,或者在Body 發送完成之前等待連接超時。

499客戶端在服務器返回之前提前關閉連接 直接Curl,在服務器返回之前Ctrl + c掉, Tengine在等待upstream返回,此時客戶端連接已經斷開。可能你的手速沒服務端處理的快,可以找一些服務器處理相對耗時的請求來複現,比如OSS的大圖片處理。

注:用public-read-write權限的bucket進行測試。

7.3 是否異常

一般正常情況下,400、408、499這三個狀態碼出現的會比較少,日誌中偶爾零星出現一些也不是什麼大問題,如果大量出現,那就可能出問題了。

假如日誌中大量出現400,如果請求的request_time_msec很小,優先排查是否是客戶端問題,如果這個時間很大,請檢查服務器壓力是否過大,是否有hang住情況。如果服務器端hang 住,請求在發送的時候數據堆在Tengine裡,服務器端長時間不讀,造成客戶端超時斷開連接,此時Tengine會產生大量因客戶端發送超時而提前斷連造成的400。

如果日誌中大量出現499,如果請求的request_time_msec很小(ms級別),需要排查是否是客戶端問題,如果這個時間很大,需要從兩個方向排查:

  • 檢查用戶請求,是否後端處理確實需要很長時間,而客戶端設置的超時時間又很短,此時需要客戶端調整超時時間,否則客戶端的重試可能會導致雪崩(如果沒有限流的話)。

  • 檢查服務器是否壓力過大,是否有hang住的情況,如果後端持續不返回客戶端提前斷開的話就會造成大量499。

這三個狀態碼出現,多多少少都是有些異常的,通常情況下,我們需要快速判斷是服務器端的異常還是客戶端的異常,從而快速定位問題。

當然上述描述的情況也不是絕對的,有時候需要特殊場景特殊分析。

八 總結

學會分析access_log在日常調查問題中會方便很多,理解access_log中一些特殊狀態碼的含義及出現的場景,會讓調查問題事半功倍。同時對C/S系統上Buffer的理解也可以加快調查問題的速度,同時指導設置Buffer的大小,解決系統在大壓力下出現的一些性能及其他一些奇怪問題。

Leave a Reply

Your email address will not be published. Required fields are marked *