收藏！Tengine問題排查必備

作者 | 俞青

來源 | 阿裡技術公衆号

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

一 前言

在日常排查問題或者同使用者連調的時候，是否經常會遇到，在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的大小，解決系統在大壓力下出現的一些性能及其他一些奇怪問題。