網站響應時快時慢的真相？只有 1% 的人知道
平常工作生活中，不知你有沒有遇到這種情況，有時訪問網站異常的快，有時卻要等待10多秒才會有響應， 這種情況下，我們一般不會太多的停留在網站，因為影響了用戶體驗。今天就分享記錄下，我工作中遇到的一個問題。
問題現象
第一次發現這個問題，應該是在很早之前，我本地用瀏覽器訪問我們公司的業務網站，發現有時很快，有時達到8、9秒以上， 但是也沒有太在意，以為是偶爾一次的。另外我用手機 4G 網絡也測試訪問了下，速度挺快的。
然而當站點可用性監控系統剛上線運營的時候，就經常收到報警的通知，因為設置了探測 超時時間，我設置的是5秒。當時覺得可能就這一個站點誤報，我單獨把這個站點的超時設置了10s，但過了幾天后，報警還是會誤報， 終于忍不住了。
這里要自我檢討下，發現問題時，我投機取巧的去掩蓋問題，而沒有去正視這個問題。這種態度是要不得的。不然問題會像滾雪球一樣可怕！！！
現象總結：公司某個網站監控得到的響應時間，延遲大，非常不穩定, 導致站點可用性監控經常誤報警。
環境介紹分析及測試
環境介紹
這里我介紹下整體的大致環境，這幾臺業務主機上，每臺主機都有一個 nginx，用于處理虛擬主機。然后最上面有一個公網 LB（負載均衡器）。它負責接收外部的流量，終止 ssl，均衡的分發請求到每個主機的 nginx 上。
還有一點需要介紹下，我們線上還有一個公網LB，也是轉發流量到這幾臺主機nginx上。這倆LB的區別只是加載的域名ssl證書不一樣，其它配置一摸一樣(讓我一直在糾結是LB配置的原因)。最后就是監控系統是部署在容器集群里的（很大程度的迷惑了自己，我曾以為是容器網絡出現了延時問題…）。
分析
當時想了以下幾個點:
- 公網 LB 配置錯誤
- 某臺應用主機處理請求時間過長
- 監控系統部署所在集群的網絡問題
- 應用主機系統參數有問題（最后追加上去的，我還真沒想到這塊）
測試
公網 LB 配置錯誤
針對這個問題，檢查了LB的的配置的超時時間，緩存等選項，都沒有啥結果，后來想到了日志，在haproxy的日子里，經常看到這樣的消息。下面是截取的其中一條記錄:
- Jun 15 16:45:29 18.19.1.12 haproxy[30952]: 139.1.2.3:61653 [15/Jun/2018:16:45:08.784] lbl-ckv7ynro~ lbl-ckv7ynro_default/lbb-izjpmxrh 327/15003/-1/-1/20331 503 213 - - sCNN 4/3/0/0/+3 0/0 "HEAD /sessions/auth?return_to=%2F HTTP/1.1"
以前沒咋看過 haproxy 日志，nginx 日志倒是都明白，這一看傻眼了。查查文檔吧。下面是對每段的解釋:
- Jun 15 16:45:29 # 時間
- 18.19.1.12 # haproxy ip
- haproxy[30952]: # 進程ID
- 139.1.2.3:61653 #client_ip+port
- [15/Jun/2018:16:45:08.784] #通過haproxy接收到連接的確切日期時間
- lbl-ckv7ynro~ #前端監聽器name
- lbl-ckv7ynro_default/lbb-izjpmxrh #管理與服務器連接的后端/ 命中的 真實server主機
- 327/15003/-1/-1/20331
- #327 是在接收到第一個字節后等待來自客戶端（不包括正文）的完整HTTP請求花費的總時間（毫秒）
- #15003 是在各種隊列中等待的總時間（毫秒）。如果連接在到達隊列之前中止，則可以為“-1”。
- #-1 是等待連接建立到最終服務器的總時間（以毫秒為單位），包括重試次數。如果請求在建立連接之前被中止，它可以是“-1”。
- #-1 是等待服務器發送完整HTTP響應的總時間（毫秒），不計算數據。如果在接收到完整的響應之前請求被中止，它可以是“-1”。它通常與服務器的請求處理時間相匹配，盡管它可能會被客戶端發送到服務器的數據量所改變。“GET”請求的大部分時間通常表示重載的服務器。
- #20331 是請求在haproxy中保持活動的時間，這是在接收到的請求的第一個字節和發送的最后一個字節之間經過的總時間（以毫秒為單位）。它涵蓋所有可能的處理，除了握手（見Th）和空閑時間（參見Ti）
- 503 #http狀態碼
- 213 #是發送日志時發送到客戶端的總字節數
- - #是一個可選的“name = value”條目，指示客戶端在請求中具有此cookie。未設置 -表示
- - #是一個可選的“name = value”條目，表示服務器已經返回了一個具有響應的cookie。
- sCNN #http格式下，會話狀態，結束時會話的條件：（timeout, error）
- #s 在等待服務器發送或接收數據時，服務器端超時已過期
- #C 代理正在等待CONNECTION在服務器上建立。服務器最多可能已經注意到連接嘗試。
- #N client沒有提供cookie。這通常是新的訪客，第一次訪問的情況,所以計算在日志中這個標志的出現次數,通常表示站點被頻繁訪問的有效趨勢。
- #N 服務器沒有提供cookie，也沒有插入任何cookie。4/3/0/0/+3
- #4 是會話記錄時進程上的并發連接總數
- #3 是會話記錄時前端上的并發連接總數
- #0 是會話記錄時由后端處理的并發連接的總數
- #0 是在會話記錄時服務器上仍然處于活動狀態的并發連接總數
- #+3 是嘗試連接到服務器時此會話遇到的連接重試次數
- 0/0 # 前一個數字0 是在服務器隊列中之前處理的請求的總數，后一個數字0是是在服務器隊列中之前處理的請求的總數
- "HEAD /sessions/auth?return_to=%2F HTTP/1.1" #是完整的HTTP請求行，包括方法，請求和HTTP版本字符串。
上面的日志分析中，有很多有價值的信息，值得關注的有 4/3/0/0/+3, sCNN. 但是當時我只關注了超時這一點，以為是網絡原因導致的客戶端連接后端服務器的超時，然后就繼續排查了。這里其實差不多已經說明了出問題的點：lb 和 后端服務器之間的故障(后話，我忽略了這一點)。
某臺應用主機處理請求時間過長
針對這個的測試，我準備在夜間流量低峰時，暫時禁用掉其它的LB后端，只保留1臺后端主機進行對外服務。很快的我發現這也行不通。問題依舊會出現。逐個的去替換，這一個測試沒效果。
監控系統部署所在集群的網絡問題
做這個測試時，我還請了外援。讓別人在他們公司內部幫忙用ab 訪問下。分別是外部聯通、外部電信、Google云主機、VPC內部。下面是ab針對域名訪問的結果。LB1: lb1.example.com LB2: lb2.example.com
監控系統部署所在集群的網絡問題
做這個測試時，我還請了外援。讓別人在他們公司內部幫忙用ab 訪問下。分別是外部聯通、外部電信、Google云主機、VPC內部。下面是ab針對域名訪問的結果。LB1: lb1.example.com LB2: lb2.example.com
LB1 的 ab 測試結果:
- 聯通測試：Server Software: nginx
- Server Hostname: lb1.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 17.629 seconds
- Complete requests: 100
- Failed requests: 0
- Write errors: 0
- Non-2xx responses: 100
- Total transferred: 276000 bytes
- HTML transferred: 240600 bytes
- Requests per second: 5.67 [#/sec] (mean)
- Time per request: 176.291 [ms] (mean)
- Time per request: 176.291 [ms] (mean, across all concurrent requests)
- Transfer rate: 15.29 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 16 121 157.1 20 653
- Processing: 8 55 104.7 11 633
- Waiting: 8 53 99.1 11 633
- Total: 26 176 188.5 36 668
- Percentage of the requests served within a certain time (ms)
- 50% 36
- 66% 241
- 75% 245
- 80% 248
- 90% 452
- 95% 658
- 98% 663
- 99% 668
- 100% 668 (longest request)
- 電信測試：Server Software: nginx
- Server Hostname: lb1.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 69.515 seconds
- Complete requests: 100
- Failed requests: 0
- Write errors: 0
- Non-2xx responses: 100
- Total transferred: 276000 bytes
- HTML transferred: 240600 bytes
- Requests per second: 1.44 [#/sec] (mean)
- Time per request: 695.151 [ms] (mean)
- Time per request: 695.151 [ms] (mean, across all concurrent requests)
- Transfer rate: 3.88 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 108 120 5.7 121 132
- Processing: 40 575 1527.9 45 5049
- Waiting: 40 575 1527.9 45 5049
- Total: 148 695 1527.5 166 5175
- Percentage of the requests served within a certain time (ms)
- 50% 166
- 66% 171
- 75% 173
- 80% 174
- 90% 5154
- 95% 5167
- 98% 5173
- 99% 5175
- 100% 5175 (longest request)
LB2 的 ab 測試結果：
- 聯通測試：Server Software: nginx
- Server Hostname: lb2.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 17.168 seconds
- Complete requests: 100
- Failed requests: 0
- Write errors: 0
- Non-2xx responses: 100
- Total transferred: 276000 bytes
- HTML transferred: 240600 bytes
- Requests per second: 5.82 [#/sec] (mean)
- Time per request: 171.675 [ms] (mean)
- Time per request: 171.675 [ms] (mean, across all concurrent requests)
- Transfer rate: 15.70 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 16 139 161.6 20 840
- Processing: 8 32 87.1 10 641
- Waiting: 8 32 87.1 10 641
- Total: 25 171 176.9 235 852
- Percentage of the requests served within a certain time (ms)
- 50% 235
- 66% 241
- 75% 245
- 80% 248
- 90% 255
- 95% 655
- 98% 667
- 99% 852
- 100% 852 (longest request)
- 電信測試：Server Software: nginx
- Server Hostname: lb2.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 16.714 seconds
- Complete requests: 100
- Failed requests: 0
- Write errors: 0
- Non-2xx responses: 100
- Total transferred: 276000 bytes
- HTML transferred: 240600 bytes
- Requests per second: 5.98 [#/sec] (mean)
- Time per request: 167.144 [ms] (mean)
- Time per request: 167.144 [ms] (mean, across all concurrent requests)
- Transfer rate: 16.13 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 110 122 4.9 122 136
- Processing: 40 45 5.8 45 100
- Waiting: 40 45 5.8 45 99
- Total: 150 167 8.8 166 225
- Percentage of the requests served within a certain time (ms)
- 50% 166
- 66% 170
- 75% 171
- 80% 172
- 90% 175
- 95% 176
- 98% 183
- 99% 225
- 100% 225 (longest request)
VPC 內部測試（統一出口）:
- LB1 的測試結果:
- Server Software: nginx
- Server Hostname: lb1.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 513.333 seconds
- Complete requests: 100
- Failed requests: 1
- (Connect: 0, Receive: 0, Length: 1, Exceptions: 0)
- Non-2xx responses: 100
- Total transferred: 273453 bytes
- HTML transferred: 238302 bytes
- Requests per second: 0.19 [#/sec] (mean)
- Time per request: 5133.329 [ms] (mean)
- Time per request: 5133.329 [ms] (mean, across all concurrent requests)
- Transfer rate: 0.52 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 4 5 2.3 4 21
- Processing: 4 5128 4147.8 5007 20006
- Waiting: 4 5128 4147.8 5007 20006
- Total: 9 5133 4147.6 5012 20011
- LB2 的測試結果:
- Server Software: nginx
- Server Hostname: lb2.example.com
- Server Port: 443
- SSL/TLS Protocol: TLSv1.2,ECDHE-RSA-AES256-GCM-SHA384,2048,256
- Document Path: /favicon_128.ico/
- Document Length: 2406 bytes
- Concurrency Level: 1
- Time taken for tests: 1.099 seconds
- Complete requests: 100
- Failed requests: 0
- Non-2xx responses: 100
- Total transferred: 276000 bytes
- HTML transferred: 240600 bytes
- Requests per second: 91.00 [#/sec] (mean)
- Time per request: 10.990 [ms] (mean)
- Time per request: 10.990 [ms] (mean, across all concurrent requests)
- Transfer rate: 245.26 [Kbytes/sec] received
- Connection Times (ms)
- min mean[+/-sd] median max
- Connect: 4 5 1.7 4 16
- Processing: 4 6 2.4 5 22
- Waiting: 4 6 2.4 5 22
- Total: 8 11 2.9 10 26
- Percentage of the requests served within a certain time (ms)
- 50% 10
- 66% 11
- 75% 11
- 80% 12
- 90% 14
- 95% 17
- 98% 24
- 99% 26
- 100% 26 (longest request)
google 的測試結果沒有放上來，相比國內訪問是慢了點。這里主要關注了在 VPC 內部測試時，LB1 的結果很不理想。但是 LB2 的結果又很正常。看到之前的環境介紹，再配合這個結果，又把我拉回了原來的思路上，即 LB 和 vpc 內部網絡有問題。
忘記說了一件事，我也在 nginx 主機上和 vpc 內部其它主機上通過修改請求 header，直接訪問內部 IP 請求資源，這里是沒有問題的，響應特別快。這又能證明主機上服務運行良好。網絡也可以排除。這……悲劇了。
應用主機系統參數有問題 后來請教別人，最后告訴我看看內核參數 recycle。然后我又去網上查了下，看看有沒有類似的問題，但是不好查啊，環境都不一樣。
但是最后查到一條關于 nat 環境下， 在應用服務器上設置內核參數時，啟用了net.ipv4.tcp_tw_recycle 和 net.ipv4.tcp_tw_reuse。按照這個思路 導致有些客戶端連接服務器失敗，根據這個我去看了下服務器的配置，果不其然，有這個參數的優化。
驗證結果
在手動的執行下面這條命令后：
- sysctl -w net.ipv4.tcp_tw_recycle
繼續在 vpc 網絡內部測試，發現對該 LB 的 ab測試全部都正常了，真是應了那句話，差不多一切的問題不是網絡問題就是配置問題。下面是修改前后的監控對比圖：
分析根本原因
這里提出了2個問題，便于理解記憶全文。
- 為什么啟用這個 tcp recycle？
- 為什么啟用 tcp recycle 之后，會阻塞部分用戶的連接請求？
為什么啟用這個 tcp recycle？
這個是之前在部署應用主機系統時，修改優化了部分內核參數，當時想的是為了增大主機對 tcp 的連接性能，防止遇到并發用戶的連接，導致 tcp 連接不能快速釋放，從而引發服務器出現性能上的瓶頸（會導致服務器內存和CPU的暴增）。
因為 client 與 server 建立鏈接傳輸完數據后，會斷開鏈接，而服務器這邊還會有 2MSL 的 time_wait 時間，超過這個時間之后，正常情況下，該 socket 才會被釋放， 然后才可以接收其它 client 的請求。因為 server 的端口是有固定范圍的，不是說 65535 個全部都用來建立連接（可參看系統內核配置：net.ipv4.ip_local_port_range）。
另外關于 time_wait 具體的可以參考 tcp 的4次斷開后的狀態。所以為了快速回收和重新使用，才開啟了 tcp 的 reuse 和 recycle。但沒想到這個會引起這么大的問題。并且這個參數之前確實也在前公司用過。但沒有發現這個類似的問題（也可能是當時的監控不到位，沒有發現也不代表該問題不存在）。這里是官方內核文檔對這倆參數的解釋：
net.ipv4.tcp_tw_recycle: Enable fast recycling TIME-WAIT sockets. Default value is 0. It should not be changed without advice/request of technical experts.
net.ipv4.tcp_tw_reuse: Allow to reuse TIME-WAIT sockets for new connections when it is safe from protocol viewpoint. Default value is 0. It should not be changed without advice/request of technical experts.
而TIME-WAIT時間為 2MSL 的作用就是為了以確保屬于未來連接的數據包不會被誤認為是舊連接的延遲數據包。tcp_tw_reuse可以在TIME_WAIT 狀態到期之前使用套接字，內核將嘗試確保沒有關于 TCP 序列號的沖突。如果啟用 tcp_timestamps（默認是開啟的，也就是 PAWS，用于保護包裝序列號），它將確保不會發生這些沖突。
為什么會阻塞客戶端（Nat 環境）請求？
上面說了為什么啟用它，現在在討論下，為什么啟用它后，會導致部分用戶的鏈接，而不是全部？看了一些文檔及別人提到的解釋：
當啟用 tcp_tw_recycle 時，內核變得更具攻擊性，并將對遠程的 client 建立連接請求時使用的時間戳進行假設。它將跟蹤具有 TIME_WAIT 狀態連接的每個遠程的 client 使用的最后時間戳， 并允許在時間戳正確增加時重新使用套接字。
但是，如果主機使用的時間戳發生更改（即 server 上記錄 time_wait 中有 A 客戶端的上一個請求的時間戳是 111112，現在又出現了一個 A 客戶端的數據請求，并且序列號是111111.）， 則 SYN 數據包將以靜默的方式丟棄，并且連接將無法建立（將看到類似于“connect timeout”的錯誤）。
為什么我看不到關于 connect timeout 的錯誤呢？因為在這個環境下，client 相當于是最前面的 LB，即 haproxy，從這里也很好的解釋了，為什么haproxy 的日志有很多連接重試的記錄！
因為在 NAT（網絡地址轉換） 環境下，有很多的 client，流量進出都是通過一個公網 IP出去的。
但當多個 NAT 網絡環境下的用戶同時或者短時間內去訪問 server 端的話， 因為對于 server 來說，此時我只知道有一個IP（client的公網IP）與我建立連接， 并且這里啟用了tcp_tw_recycle，Server主機內核將認為有一部分連接請求的時間戳不是遞增的，那么內核將判斷該請求是無效的，就會丟失該請求。
To keep the same guarantees the TIME-WAIT state was providing, while reducing the expiration timer, when a connection enters the TIME-WAIT state, the latest timestamp is remembered in a dedicated structure containing various metrics for previous known destinations. Then, Linux will drop any segment from the remote host whose timestamp is not strictly bigger than the latest recorded timestamp, unless the TIME-WAIT state would have expired
總結
不要開啟tcp_tw_recycle,重要的話說三遍。一定要有配置管理！可以方便在系統出問題時，檢查對主機所做的歷史記錄。考慮問題不能光從 軟件程序、網絡上，還要加入對主機系統的分析。tcpdump、ss、還有log等。
另外，針對 Web 應用服務系統幾個優化建議:
設置 net.ipv4.ip_local_port_range 合理的范圍（10000~63000）；
給 LB 設置更多的client IP；
配置 LB 有多個外網 IP。
