簡介：本文將分享Tengine的“時間”和“緩存”的一些問題，說明問題的原因，并從用戶和服務(wù)器的角度分析這些問題。

作者｜俞青

前言

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

在日常排查問題或者同用戶連調(diào)的時候，是否經(jīng)常會遇到，在access_log里看到用戶請求很快，但用戶卻反饋很慢？

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

Tengine打access_log時機

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

Tengine的access_log是在Tengine“認為”這個請求結(jié)束后才打的，對于正常請求，Tengine會在請求最后一個字節(jié)發(fā)出后認為請求結(jié)束；對于異常請求，當Tengine判斷連接超時或者異常斷開，無法再發(fā)送和接收數(shù)據(jù)的時候。通常情況下可以認為Tengine在請求結(jié)束后隨即會打出日志。

如何理解Tengine的“請求最后一個字節(jié)發(fā)出”

Tengine認為請求最后一個字節(jié)發(fā)出后，該請求就結(jié)束了，其實最后一個字節(jié)發(fā)出可以理解為最后一串數(shù)據(jù)發(fā)出，這里是“發(fā)出”而不是用戶收到，指的是將最后一串數(shù)據(jù)填到協(xié)議棧中，只要send 成功返回，Tengine就認為結(jié)束了，至于數(shù)據(jù)是否被客戶端收到那就是協(xié)議棧和網(wǎng)絡(luò)上的事情了，Tengine不會去關(guān)心。

為什么服務(wù)端看到的延時同客戶端不一致

服務(wù)端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.

這個字段表示的是從請求的第一個字節(jié)開始到請求最后一個字節(jié)發(fā)出后所經(jīng)歷的時間。

這里其實包含如下幾點信息：

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

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

3. 最后一個字節(jié)發(fā)出后Tengine認為請求結(jié)束，數(shù)據(jù)僅僅是填在協(xié)議棧中，從協(xié)議棧Buffer中的數(shù)據(jù)發(fā)送給用戶的這段時間是不被算進去的。

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

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

客戶端看到的E2E時間

上節(jié)中分析的request_time_msec從服務(wù)器端看到的請求E2E時間，而用戶看到的時間，假設(shè)用戶用curl去測試：

time curl

那么上節(jié)提到的幾點不會算到服務(wù)器端時間的計算邏輯里的，除了4都會被客戶端計算進去。

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

上傳類請求延時差異

針對于上傳來說，服務(wù)器端和客戶端看到的延時差異不大，相差一個握手/和最后返回的Header發(fā)送回去的時間。

握手到服務(wù)器端收到請求首字節(jié)2rtt，請求完成后返回的HEADER數(shù)據(jù)一般不會很大可以塞在1個cwnd內(nèi)發(fā)完，需要一個0.5個rtt，一共是2.5個rtt。如果是長連接，忽略三次握手的話，那么看到的差異為1個rtt。

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

下載類請求延時差異

關(guān)于下載請求的延時差異會稍微復(fù)雜一些。上傳的情況下，服務(wù)器只會有HTTP狀態(tài)碼和一些HTTP Header，通常一個rtt就可以發(fā)完。而下載，通常服務(wù)器會有較多的數(shù)據(jù)發(fā)送給客戶端，Tengine把最后一串數(shù)據(jù)填在協(xié)議棧的Buffer里，如果在Buffer中的數(shù)據(jù)能在一個rtt內(nèi)發(fā)完，那么同上傳類請求一致，否則就會比上傳類請求的差異大。至于協(xié)議棧Buffer中最后一串數(shù)據(jù)花多長時間能發(fā)送到客戶端，這個就不太好估計了，取決于當時的網(wǎng)絡(luò)狀況及當時的擁塞窗口大小，需要具體情況具體分析。

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

wget your-bucket.o --limit-rate=10k --debug

注：wget這個限速是在應(yīng)用層面做的，測試看到的時間差異除了服務(wù)端Buffer的原因，還有客戶端Buffer的原因，數(shù)據(jù)到達客戶端協(xié)議棧，而應(yīng)用因限速而遲遲不讀。

總結(jié)

服務(wù)器端看到的E2E時間“request_time_msec” 時間是Tengine收到請求的首字節(jié)開始，到最后一個字節(jié)寫到協(xié)議棧的時間。

客戶端看到的E2E時間相比服務(wù)器多了：客戶端建聯(lián)及HTTPS 握手時間、請求首字節(jié)發(fā)送到服務(wù)器的時間、外加Tengine認為請求結(jié)束后協(xié)議棧將Buffer中的數(shù)據(jù)遞送到客戶端的時間。

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

服務(wù)器端慢是真的慢，但是服務(wù)器端看到快，可不一定真的快。

服務(wù)器端看到的請求成功和客戶端看到的請求成功

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

服務(wù)器端看到的成功，是服務(wù)器端正確處理這個請求，并把數(shù)據(jù)發(fā)送到協(xié)議棧后，服務(wù)器就會認為請求已經(jīng)成功。

客戶端看到請求成功，是收到服務(wù)器端返回的狀態(tài)碼及完整的body后才認為請求成功。

access_log看到的“200 OK”

access_log里的狀態(tài)碼，只要請求的header已經(jīng)發(fā)出去，那么狀態(tài)碼就確定了，access_log里面打出來的狀態(tài)碼也是確定的。

如果是上傳類請求，access_log里打印出狀態(tài)碼為200，那么請求一定是成功了（但是客戶端不一定能感知到這個成功）。

如果是下載類請求，access_log里打印出來的狀態(tài)碼是200，那么請求不一定成功，可能body并未發(fā)完請求就異常結(jié)束了。

寫到協(xié)議棧里的數(shù)據(jù)不一定能發(fā)送出去

Tengine把數(shù)據(jù)寫到協(xié)議棧的Buffer中后，從Tengine的角度來說，可以認為數(shù)據(jù)已經(jīng)發(fā)往客戶端了，但從實際角度來看，數(shù)據(jù)寫到協(xié)議棧僅僅是寫到協(xié)議棧，至于寫到協(xié)議棧的數(shù)據(jù)是否能否真正被發(fā)送出去，是不一定的。在協(xié)議棧數(shù)據(jù)還沒發(fā)出去之前可能網(wǎng)絡(luò)中斷了，或者連接被reset 了，都會可能發(fā)生。這是造成客戶端和服務(wù)器端看到有差異的一個主要原因。

有的同學會問，TCP不是可靠的傳輸協(xié)議嘛，怎么會發(fā)不過去？建議看下這篇文章，就明白TCP的可靠性具體指的是什么了。文章地址：

單連接最低下載速度

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

針對系統(tǒng)性能指標，通常我們會描述一個單連接峰值吞吐的數(shù)值，但是實際上一個還有一個最低速度的限制。那么這個最低速度是怎么來的呢？

一個正常C/S架構(gòu)的系統(tǒng)，通常會有很多Buffer，會設(shè)置很多超時時間，針對Tengine會有send_timeout，recv_timeout，keepalive_timeout等各種超時限制。這就會造成系統(tǒng)會有一個最小下載速度的限制。

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

如何獲取系統(tǒng)最低下載速度

正常情況下，我們可以通過分析系統(tǒng)中各個Buffer 的大小及超時時間計算出一個理論的最低下載速度，但是一個復(fù)雜的系統(tǒng)，很難理清楚或者找到各個位置的Buffer 大小及超時時間。因此我們可以利用wget的 --limit-rate 功能進行二分測試，直到找到最低下載速度的零界點，注意下載的時候文件不要選擇太小，選擇太小了會測試不出來，當然也不要太大，太大了會造成測試時間過長，設(shè)置為系統(tǒng)最大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最低下載速度：

• 單連接持續(xù)5k以內(nèi)：速度必然出問題(一般持續(xù)30s+出問題）。
• 單連接持續(xù)5 ~10k以內(nèi)：速度隨機出問題，看系統(tǒng)狀況（比較具有偶然性）。
• 單連接持續(xù)10k+：基本不出問題。

根據(jù)上述6.1節(jié)中的理論和6.2節(jié)中的測試方法，我們甚至可以測試出來服務(wù)器端設(shè)置的sndbuf有多大。

如何解決

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

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

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

為什么復(fù)現(xiàn)不出來

有同學使用wget/curl的limit_rate功能把連接速度限制到很低，但是復(fù)現(xiàn)不出來最低下載速度的問題，這是因為測試的文件太小了，測試的文件大小需要比客戶端的rcvbuf + 服務(wù)端的sndbuf還要大才能測試出來，否則數(shù)據(jù)堆在兩端的協(xié)議棧里，是觸發(fā)不到應(yīng)用的超時時間限制的。

access_log中的400、408及499

產(chǎn)生原因

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

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

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

499，客戶端關(guān)閉請求，在proxy 場景下確切的說是客戶端先于proxy upstream 返回前斷開，Tengine在做proxy 的情況下（fastcgi_pass/proxy_pass 等），同一請求鏈路上，客戶端與Tengine的連接先于Tengine后端返回前斷開，此時在Tengine的access_log中計為499的日志。

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

如何復(fù)現(xiàn)

400請求數(shù)據(jù)發(fā)完之前提前斷開連接，nc建立連接后輸入完成Host頭部后Ctrl + c斷掉，或者發(fā)送PUT請求在body沒有發(fā)送完成之前Ctrl + c掉。

408客戶端發(fā)送超時，nc建立連接后輸入完成Host 頭部后等待連接超時，或者在Body 發(fā)送完成之前等待連接超時。

499客戶端在服務(wù)器返回之前提前關(guān)閉連接 直接Curl，在服務(wù)器返回之前Ctrl + c掉, Tengine在等待upstream返回，此時客戶端連接已經(jīng)斷開?？赡苣愕氖炙贈]服務(wù)端處理的快，可以找一些服務(wù)器處理相對耗時的請求來復(fù)現(xiàn)，比如OSS的大圖片處理。

注：用public-read-write權(quán)限的bucket進行測試。

是否異常

一般正常情況下，400、408、499這三個狀態(tài)碼出現(xiàn)的會比較少，日志中偶爾零星出現(xiàn)一些也不是什么大問題，如果大量出現(xiàn)，那就可能出問題了。

假如日志中大量出現(xiàn)400，如果請求的request_time_msec很小，優(yōu)先排查是否是客戶端問題，如果這個時間很大，請檢查服務(wù)器壓力是否過大，是否有hang住情況。如果服務(wù)器端hang 住，請求在發(fā)送的時候數(shù)據(jù)堆在Tengine里，服務(wù)器端長時間不讀，造成客戶端超時斷開連接，此時Tengine會產(chǎn)生大量因客戶端發(fā)送超時而提前斷連造成的400。

如果日志中大量出現(xiàn)499，如果請求的request_time_msec很?。╩s級別），需要排查是否是客戶端問題，如果這個時間很大，需要從兩個方向排查：

• 檢查用戶請求，是否后端處理確實需要很長時間，而客戶端設(shè)置的超時時間又很短，此時需要客戶端調(diào)整超時時間，否則客戶端的重試可能會導致雪崩（如果沒有限流的話）。
• 檢查服務(wù)器是否壓力過大，是否有hang住的情況，如果后端持續(xù)不返回客戶端提前斷開的話就會造成大量499。

這三個狀態(tài)碼出現(xiàn)，多多少少都是有些異常的，通常情況下，我們需要快速判斷是服務(wù)器端的異常還是客戶端的異常，從而快速定位問題。

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

總結(jié)

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