摘要：分析的結果，發現內存，基本沒有什么大的變化，網卡流量明顯降低，上下文切換明顯升高。網卡流量降低可以理解，因為當前系統已不能正常返回響應，但上下文切換升高卻不知道什么原因。

原文：http://chuansongme.com/n/797172

據XX部門兄弟反應, 其在將PHP從5.3.8 升級到5.5.13 時, 開始運行正常, 運行一段時間后, 系統負載變高,達到200%以上, 從netstat看到大量連接處在CLOSE_WAIT狀態。 最終導致系統不可用, 將PHP 回滾到5.3. 8 后, 一切正常。

php-fpm 配置文件除了由版本引起的差異外， 沒做任何改變。

根據TCP關閉連接的流程圖：

可以看到， 一個處于連通狀態（ESTABLISHED）的連接， 當接收到FIN數據包（對方調用close）后，TCP 連接的狀態由ESTABLISHED變為CLOSE_WAIT，等待應用調用close（即發送FIN給對方）。

因此我懷疑PHP由于某種原因被堵塞住（比如數據庫等資源太慢），導致請求超時， nginx 主動close連接，而PHP 程序由于一直堵塞，導致其無法調用close，造成大量TCP連接處于CLOSE_WAIT狀態。

由于當時沒有故障現場， 因此我們挑選一臺機器，將PHP5.5重新上線，等待故障現象重現，我計劃問題重現時， 用strace 看下進程的系統調用，找出PHP進程到底堵塞在哪里。

周一將PHP5.5.13上線后， 周三大約上午9：30左右，系統負載飆升至200%以上， 立刻用strace 查看，結果沒有發現任何堵塞的情況，卻發現另一個異常現象：write函數調用失敗

當PHP調用write返回響應時，結果報錯：Brokenpipe，這說明TCP連接其實已經關閉。PHP并沒有堵塞住，這跟我猜想的完全不同，一時想不明白為什么PHP會write 一個關閉了的連接，于是我先用sar 將當前的系統狀態保持起來，包括磁盤，內存，網卡，CPU，中斷，上下文切換等，留待以后慢慢分析。

分析sar的結果， 發現內存，CPU基本沒有什么大的變化， 網卡流量明顯降低，上下文切換（cswch/s）明顯升高。網卡流量降低可以理解，因為當前系統已不能正常返回響應，但上下文切換（cswch/s）升高卻不知道什么原因。

sar的結果暫時沒有什么思路， 繼續分析strace的結果。Brokenpipe說明連接早已經被對方關閉，難道是nginx超時了？看一下從accept連接到關閉連接的整個流程：

從accept 接受一個socket， 到read 讀取數據一直正常， 但調用write當返回響應時，卻報錯Brokenpipe，從accept到write 一共花費大約1ms ，這段時間內nginx肯定是不會超時的！那為什么連接會關閉呢？我們用tcpdump抓包看下網絡到底發生了什么。

用tcpdump 抓包，由于數據量太大， 我只選擇了一臺Nginx 的IP10.121.96.200，抓包并傳回到本地用wireshark打開（wireshark便于分析），發現網絡已經一團糟：

上圖是tcp.port == 61029 的過濾結果，10.121.96.200是NGINX的IP， 10.121.96.206 是PHP的IP，后面為了方便直接用NGINX，PHP 來代稱這兩臺機器。

異常1： 從圖上可以看到， 開始NGINX向PHP發送SYN， 這是TCP創建連接三次握手的第一次， 然后PHP響應ACK， 這里PHP應該響應SYN+ACK 才是正確的，acknumber 是3646825320 也跟NGINX 發的SYN的序列號對應不起來，因此接下來NGINX 返回RST，直接重置了連接。

異常2： 先不管異常1， 我們繼續往下看， 第4個數據包，過了3s后，nginx 重傳了SYN包，這時PHP響應SYN+ACK， 序列號也能對應上，NGINX 回應ACK，三次握手完成，連接成功建立。然后NGINX向PHP發送HTTP請求，到了第9個包， NGINX發送FIN 關閉連接，而PHP除了返回對應的ACK外，沒有返回任何東西：沒有返回響應數據（len=0），也沒有返回FIN來關閉連接。從AbsTime字段可以看到第8,9包之間相隔2s，因此合理推測NINGX應該是2s后超時，主動關閉了連接， PHP什么也沒做，此時PHP機器上連接一定處于CLOSE_WAIT狀態。

異常3： 繼續看下面的數據包， 第11個數據包，又是一個SYN包， 這應該是一個新的連接，從時間上看， 距離上一個包1分鐘多， 說明NGINX 復用（reuse）了這個端口（61029）。 但是從異常2可以知道， 此時PHP上的連接還處于CLOSE_WAIT狀態， 接收到SYN后，只是返回了ACK，并且acknumber=1013848495，說明這個ACK確實是上一個連接的；同異常1， NGINX返回RST，重置了連接。

從抓包結果可以得出結論：PHP 上大量連接一直處于CLOSE_WAIT狀態， 這時NGINX復用端口新建連接， PHP由于還處于CLOSE_WAIT狀態， 直接返回了ACK， NGINX 期待返回的是SYN+ACK， 由于不符合預期NGINX直接返回RST重置連接， 連接重置后PHP上的CLOSE_WAIT就消失了。3s后NGINX重傳SYN， 成功建立連接，發送請求，超時后close連接， PHP什么也沒做，又變為CLOSE_WAIT狀態， 一段時間后NGINX 復用端口新建連接……如此循環往復。

那么問題是， PHP機器是怎么到達這種循環往復的狀態呢？ 總有成因吧？到目前為止， 我們已經知道PHP 機器當前的狀態， 從抓包來看， PHP處于CLOSE_WAIT 狀態， 并且不響應NGINX的請求， 從strace結果來看， PHP沒有堵塞，也在處理響應， 但是在返回響應的時候， 連接卻早已經被NGINX 關閉。這兩種結果明顯矛盾！

此時， 沒有任何其他思路， 走了很多彎路， 首先懷疑是網卡問題， ifconfig/ethtool看網卡狀態， dropped ， errors 都是正常范圍，又懷疑是TCP bug，但是我用SSH登錄卻沒有任何問題，SSH也很正常，TCP這么容易出BUG也不太可能，因此確定一定不是TCP 及底層的問題，問題仍然出在PHP 上。

我突然想到， 可以將strace 的結果和tcpdump的結果對應起來， 從strace 中選取一個（IP，PORT）， 查看其對應tcpdump 的結果。 于是同時運行strace， tcpdump。選取strace 的一個NGINX IP，PORT：

1403674216.729752 accept(0, {sa_family=AF_INET, sin_port=htons(6470), sin_addr=inet_addr("10.121.96.200")}, [2688649527312]) = 4

從tcpdump的結果過濾host10.121.96.200 and port 6470 :

13:27:57.942284 IP 10.121.96.200.6470 > 10.121.96.206.9000: S3965696332:3965696332(0) win 5840 

1403674216.729752為 accept 調用時的時間戳， 轉化為時間就是：WedJun 25 13:30:16 CST 2014，而tcpdump發起連接的時間卻是13:27:57。accept 調用比接收到SYN晚了2分鐘多。到這里我立刻明白連接被積壓在隊列里了，等到2分鐘后， PHP才調用accept 從隊列獲取一個連接，而此時這個連接早已經因為超時被NGINX關閉了，因此PHP 返回響應調用write時，會報Broken pipe 。

連接隊列的大小由backlog控制（listen 系統調用的第二個參數），PHP5.5 默認為65535，而PHP5.3.8 默認為128，我們都是用的默認值，因此這兩個值是不同的。由于PHP5.5 使用65535，這個值比較大， 造成很多連接積壓在隊列里， 由于隊列處理的比較慢， 導致連接超時， 超時的連接由于還沒有accept， 因此不會處理請求，也不會被close， 造成CLOSE_WAIT狀態，這就是我們從tcpdump中看到的現象。 等到accept獲取到一個連接， 實際是獲取到一個CLOSE_WAIT狀態的連接， 等write調用向連接寫數據時，自然會報錯。 這就同時完美解釋了tcpdump跟strace看似矛盾的結果。

這里有必要解釋下， TCP連接為什么會積壓在隊列里， 要理解這個問題， 需要先理解linux 對TCP 三次握手的一些具體實現。

我們知道， 在server端，監聽一個端口， 調用socket,bind 最后調用listen：

int listen(intsockfd, int backlog);

listen的第二個參數叫做backlog， 用來設置連接隊列的大小。實際Linux 維護兩個隊列， 一個是在接收到SYN后，此時沒有完成三次握手， 處于半連接狀態，存放到SYNqueue， 另一個是三次握手完成后， 成功建立連接，存放到acceptqueue，等待應用調用accept 來消費隊列。這里的backlog就是用來設置accept queue（舊版內核用來設置SYN queue，詳細請man listen）的大小。

TCP 傳輸跟系統調用實際是一個異步的過程， 系統通過隊列來保存最新的TCP狀態或數據。也就是說，TCP三次握手由內核來完成， 跟應用層是否調用accept無關， 內核將完成三次握手的socket 放到acceptqueue中，應用調用accept 時，從accept queue中獲取連接。那么，如果backlog 非常大，而我又不及時調用accept 來消費隊列，則連接就被積壓到accept queue中了。

同樣， 在三次握手完成后， 客戶端就可以發送數據了， 數據由內核接收， 并保存在TCP 的buffer中， 而此時應用（PHP）可能還沒有調用accept。

因此， 如果積壓在accept queue中的連接如果已經被對方close， 應用仍然可以accept到這個連接， 也可以調用read 讀取buffer中的數據， 但是，當調用write 時， 則報錯：Broken pipe。

Backlog 過高的猜想，可以解釋當前的故障現象， 但仍然有很多疑問需要解決

accept queue 是如果慢慢積壓的？流量突增還是后端變慢？

連接積壓后， PHP獲取到的都是close掉的連接，不需要返回響應，應該會快速失敗，那么消費accept queue的速度應該大大提高，最終將close掉的連接都快速消費掉，系統應該會恢復正常，但現實情況下負載卻持續很高，并且沒有恢復， 為什么？

Nginx 做反向代理時， 可以自動摘掉失效的后端， 后端摘掉后，不再有新的請求路由過來，從而accept queue得以消費，慢慢恢復正常，但從nginx日志看， nginx 根本就沒摘掉后端，為什么？

上下文切換cswch/s 為什么突升？

首先從PHP slow log看， PHP進程偶爾會出現fastcgi_finish_request 執行慢的情況， 時間超過2s， 此時accept queue 必然會有增長， 另外， 我們的PHP-FPM 配置了max_request=102400也就是處理102400 個請求后， fpm的worker進程會自動退出， fpm重新派生（respawn）worker進程，如果負載比較均衡的話，所有子進程應該幾乎同時退出(因為pm為static模式)，并且從PHP源碼看，PHP沒有對這個機制做任何優化，在這個過程中 accept queue也必然會積壓。

這里從strace 可以找到答案， 我們看下， PHP在write brokenpipe后，到底又做了什么。通過對比正常php進程跟異常php進程的strace結果，我發現異常PHP進程在寫log前調用flock，耗時比較多：

1403674085.279482 flock(4, LOCK_EX) = 0
1403674085.668528 write(4, "1	1	1403674085xx	11"..., 76) =76
1403674085.668565flock(4, LOCK_UN) = 0

1403674085.668– 1403674085.279大約相差400ms， 而正常的PHP進程：

1403680571.144737flock(4, LOCK_EX) = 0 <0.000014>
1403680571.144784write(4, "1	1	1403680571xx	11"..., 74) = 74 <0.000014>
1403680571.144833flock(4, LOCK_UN) = 0<0.000017>

幾乎沒有耗費時間！ 因此我們可以想到， 當大多進程都快速失敗時， 他們會同時去寫日志， 由于我們的日志程序在寫日志前都調用flock加鎖， 導致PHP進程由于爭奪鎖而堵塞， 因此喪失了快速消費acceptqueue的機會！

關于flock， 我查了下PHP 手冊， 其實一般情況下， 用append方式打開文件寫日志時，是不需要加鎖的， 因為其本身為原子操作，具體參考：http://cn2.php.net/manual/en/function.fwrite.php

Note: 
If handle was fopen()ed in appendmode, fwrite()s are atomic(unless the size of string exceeds the filesystem"s block size, onsome platforms, and as long as the file is on a local filesystem). That is,there is no need to flock() a resourcebefore calling fwrite();all of the data will be written without interruption. 

通過分析nginx 的配置文件， 我發現目前有兩個vhost， 其中一個是 A.cn， 其中關于fastcgi的超時fastcgi_read_timeout設置為100ms，可見這個時間是很容易造成超時的。另外一個vhost 配置了一系列域名，我這里就用B.cn來代替了，其中沒有配置fastcgi 相關的超時。會采用默認值60s。

關于upstream 的配置是這樣的：

server10.121.96.206:9000 max_fails=10 fail_timeout=5m;

表示， 如果有10次連續失敗， 則摘掉后端5分鐘， 5分鐘后再嘗試恢復后端。從這里看到， nginx 是配置了摘除后端的功能的。我統計了故障時段以及故障以前的請求分布，發現故障時段請求數并沒有減少，說明nginx根本沒有摘除后端。

我確認了相應版本nginx的源碼， 沒有發現摘除功能的任何bug， 于是試圖分析nginx access_log， 發現大量請求的返回狀態碼為499。499 代表nginx發現客戶端主動斷開了連接， 這時nginx會斷開到upstream的連接并記錄日志，狀態碼記為499，一般出現在客戶端設置有超時的情況下。問題于是出現了，對于client 主動斷開連接， nginx 認為是客戶端放棄了請求，并不是后端失敗，因此不會計入失敗次數，也就不會摘掉后端了。

Vhost A.cn 中設置fastcgi_read_timeout 為100ms，而客戶端的超時一般不會是毫秒級別的，因此這個vhost 如果超時不可能是客戶端超時，而是fastcgi超時，因此記錄狀態碼應該為504，而不是499，那么499 必定大多是由vhost B.cn 導致的，B.cn 沒有設置fastcgi_read_timeout ，默認為60s，因此很可能導致客戶端超時。

從請求分布的統計結果來看， 故障前后每分鐘請求數基本沒有變化， 那么說明不能摘掉后端的vhost B.cn的請求占比例應該很大，從而導致可以摘掉后端的vhost A.cn 就算摘除了后端對請求數影響也不大。為了驗證這個推論， 我統計了accesslog， 發現 B.cn 占了大約85%的流量。因此推論正確。

Nginx 由于客戶端超時，不認為是后端失敗， 從而沒有摘掉后端，喪失了故障恢復的機會。

這個問題， 我沒有確切答案， 不過可以合理推論， 幾百進程同事flock等待鎖， 當鎖可用時， 幾百進程會同時喚醒，但只有一個進程能夠得到鎖，其他進程在分配到時間片后，由于無法獲取鎖，只能放棄時間片再次wait，從而導致上下文切換飆升，但CPU使用率卻升高的不明顯。當然這只是推論，大家如果有什么想法，歡迎一起討論。(Update: 2014-07-04, 經試驗，頻繁flock確實會是cswch/s上升)

從以上分析看出， 問題雖然是由于backlog 從128 變為65535 引起， 但問題實際涉及從客戶端，nginx，到php等多個方面，而這多個方面都有問題，綜合導致了這次故障。

因此我建議多方面同時調整，徹底解決問題：

nginx 設置超時， 至少小于客戶端的超時時間， 否則摘除機制形同虛設。

backlog 設置為合理值， 可以參考排隊論， 通過qps，以及處理時間實際可以確定隊列大小， 比如qps為1000，限時在100ms內返回， 則隊列大小設置為1000*0.1=100比較合適， 否則我明明知道等我處理到這個連接，其早就超時了， 還要將連接放到隊列，肯定是不合理的。

寫日志時，去掉flock，因為append 方式打開文件， fwrite是原子操作（除非要寫的字符串大于文件系統的block，一般block是4k，應該不會超過吧？）。

上線PHP5.5.13，配置listen.backlog為128，等待1到2周，觀察故障是否會再次出現。預期：不出現

上線PHP5.3.8， 配置listen.backlog 為65535，等待1到2周， 觀察故障能否出現。預期：出現

上線PHP5.3.28，配置listen.backlog為128，等待1到2周，觀察故障能否出現。預期：不出現

之所以驗證PHP 5.3.28是因為據業務反映，以前測試時，這個版本也有問題，但5.3.28 默認backlog是128，如果存在問題，則上面的結論就完全錯了。因此我要求重新驗證一下。

經過一個月的線上驗證，PHP 5.5.13自從listen.backlog 改為128后，表現正常。PHP5.3.28也沒有問題。這兩個都符合預期，但listen.backlog 為65535的PHP5.3.8出乎意料，沒有出現異常。

對于backlog積壓的真正原因，我這邊已經確定，是凌晨0點切割日志導致。切割日志腳本在mv完日志后, 發送
SIGUSR1信號給php-fpmmaster進程，php-fpm會reopen日志文件，并通知所有worker進程退出。這一瞬間會造成一定的連接隊列的積壓，不過這不是主要原因，主要原因是隨后腳本查找并刪除2天前的日志文件，由于文件較多，估計應該幾百G，造成iowait偏高。導致連接隊列的積壓。最高積壓可達到上千。

Tue Jul 29 00:00:50CST 2014 3: CE60790A:2328 00000000:0000 0A 00000000:000004FC00:00000000 00000000 0 0 4205691288 1 ffff8101b2c7e6c0 3000 0 0 2 -1

統計數據從/proc/net/tcp獲取， 并每秒打印一次， 可以看到00:00:50這一刻， 連接隊列的積壓達到0x000004FC， 轉化為10進制，也就是1276個。

另外，我采集了凌晨日志切割時負載的相關數據，listen.backlog 為65535 的PHP5.3.8 負載最高達100以上。連接積壓最多達1000以上。而listen.backlog 為128 的PHP5.5.13, 由于限制了連接隊列，其最大積壓為129（128+1），最高負載在70左右。負載之所以仍然很高，這是由刪除日志導致。

系統負載居高不下，無法恢復，與多個因素有關，首先，刪除日志，導致iowait過高，堵塞了PHP進程，從而無法及時消費連接隊列，由于listen.backlog 設置為65535時，連接幾乎一直積壓在連接隊列，由于nginx設置的100ms超時，導致大量連接超時關閉。大量PHP進程由于無法返回響應，時間都集中在寫日志方面，引起flock驚群。此時，就算iowait恢復正常，由于flock過慢，nginx 無法及時摘除后端，系統也無法恢復正常了。

從以上信息可以，各影響因素有一個發生改變，可能都不會導致系統負載居高不下的問題：

Nginx A.cn 調整100ms，如果時間夠長，則連接隊列的socket不會被close掉，就不會導致大量PHP進程集中寫日志。

減小listen.backlog，如果backlog足夠小，新的連接會直接拒掉，連接隊列就不會積壓太多連接。就算都被close掉，也不會有太多影響。

寫日志去掉flock，這樣避免flock驚群，等iowait恢復時，系統負載也就恢復了。

Nginx B.cn 配置合理的超時時間，這樣在后端超時時，可以自動摘除有問題的后端，使后端有機會恢復負載。

避免iowait過高，這樣就不會拖慢PHP，不會積壓連接，也就不存在負載過高的問題了。