摘要：分析的結(jié)果，發(fā)現(xiàn)內(nèi)存，基本沒有什么大的變化，網(wǎng)卡流量明顯降低，上下文切換明顯升高。網(wǎng)卡流量降低可以理解，因?yàn)楫?dāng)前系統(tǒng)已不能正常返回響應(yīng)，但上下文切換升高卻不知道什么原因。

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

據(jù)XX部門兄弟反應(yīng), 其在將PHP從5.3.8 升級到5.5.13 時, 開始運(yùn)行正常, 運(yùn)行一段時間后, 系統(tǒng)負(fù)載變高,達(dá)到200%以上, 從netstat看到大量連接處在CLOSE_WAIT狀態(tài)。 最終導(dǎo)致系統(tǒng)不可用, 將PHP 回滾到5.3. 8 后, 一切正常。

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

根據(jù)TCP關(guān)閉連接的流程圖：

可以看到， 一個處于連通狀態(tài)（ESTABLISHED）的連接， 當(dāng)接收到FIN數(shù)據(jù)包（對方調(diào)用close）后，TCP 連接的狀態(tài)由ESTABLISHED變?yōu)镃LOSE_WAIT，等待應(yīng)用調(diào)用close（即發(fā)送FIN給對方）。

因此我懷疑PHP由于某種原因被堵塞?。ū热鐢?shù)據(jù)庫等資源太慢），導(dǎo)致請求超時， nginx 主動close連接，而PHP 程序由于一直堵塞，導(dǎo)致其無法調(diào)用close，造成大量TCP連接處于CLOSE_WAIT狀態(tài)。

由于當(dāng)時沒有故障現(xiàn)場， 因此我們挑選一臺機(jī)器，將PHP5.5重新上線，等待故障現(xiàn)象重現(xiàn)，我計(jì)劃問題重現(xiàn)時， 用strace 看下進(jìn)程的系統(tǒng)調(diào)用，找出PHP進(jìn)程到底堵塞在哪里。

周一將PHP5.5.13上線后， 周三大約上午9：30左右，系統(tǒng)負(fù)載飆升至200%以上， 立刻用strace 查看，結(jié)果沒有發(fā)現(xiàn)任何堵塞的情況，卻發(fā)現(xiàn)另一個異常現(xiàn)象：write函數(shù)調(diào)用失敗

當(dāng)PHP調(diào)用write返回響應(yīng)時，結(jié)果報錯：Brokenpipe，這說明TCP連接其實(shí)已經(jīng)關(guān)閉。PHP并沒有堵塞住，這跟我猜想的完全不同，一時想不明白為什么PHP會write 一個關(guān)閉了的連接，于是我先用sar 將當(dāng)前的系統(tǒng)狀態(tài)保持起來，包括磁盤，內(nèi)存，網(wǎng)卡，CPU，中斷，上下文切換等，留待以后慢慢分析。

分析sar的結(jié)果， 發(fā)現(xiàn)內(nèi)存，CPU基本沒有什么大的變化， 網(wǎng)卡流量明顯降低，上下文切換（cswch/s）明顯升高。網(wǎng)卡流量降低可以理解，因?yàn)楫?dāng)前系統(tǒng)已不能正常返回響應(yīng)，但上下文切換（cswch/s）升高卻不知道什么原因。

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

從accept 接受一個socket， 到read 讀取數(shù)據(jù)一直正常， 但調(diào)用write當(dāng)返回響應(yīng)時，卻報錯Brokenpipe，從accept到write 一共花費(fèi)大約1ms ，這段時間內(nèi)nginx肯定是不會超時的！那為什么連接會關(guān)閉呢？我們用tcpdump抓包看下網(wǎng)絡(luò)到底發(fā)生了什么。

用tcpdump 抓包，由于數(shù)據(jù)量太大， 我只選擇了一臺Nginx 的IP10.121.96.200，抓包并傳回到本地用wireshark打開（wireshark便于分析），發(fā)現(xiàn)網(wǎng)絡(luò)已經(jīng)一團(tuán)糟：

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

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

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

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

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

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

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

我突然想到， 可以將strace 的結(jié)果和tcpdump的結(jié)果對應(yīng)起來， 從strace 中選取一個（IP，PORT）， 查看其對應(yīng)tcpdump 的結(jié)果。 于是同時運(yùn)行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的結(jié)果過濾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 調(diào)用時的時間戳， 轉(zhuǎn)化為時間就是：WedJun 25 13:30:16 CST 2014，而tcpdump發(fā)起連接的時間卻是13:27:57。accept 調(diào)用比接收到SYN晚了2分鐘多。到這里我立刻明白連接被積壓在隊(duì)列里了，等到2分鐘后， PHP才調(diào)用accept 從隊(duì)列獲取一個連接，而此時這個連接早已經(jīng)因?yàn)槌瑫r被NGINX關(guān)閉了，因此PHP 返回響應(yīng)調(diào)用write時，會報Broken pipe 。

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

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

我們知道， 在server端，監(jiān)聽一個端口， 調(diào)用socket,bind 最后調(diào)用listen：

int listen(intsockfd, int backlog);

listen的第二個參數(shù)叫做backlog， 用來設(shè)置連接隊(duì)列的大小。實(shí)際Linux 維護(hù)兩個隊(duì)列， 一個是在接收到SYN后，此時沒有完成三次握手， 處于半連接狀態(tài)，存放到SYNqueue， 另一個是三次握手完成后， 成功建立連接，存放到acceptqueue，等待應(yīng)用調(diào)用accept 來消費(fèi)隊(duì)列。這里的backlog就是用來設(shè)置accept queue（舊版內(nèi)核用來設(shè)置SYN queue，詳細(xì)請man listen）的大小。

TCP 傳輸跟系統(tǒng)調(diào)用實(shí)際是一個異步的過程， 系統(tǒng)通過隊(duì)列來保存最新的TCP狀態(tài)或數(shù)據(jù)。也就是說，TCP三次握手由內(nèi)核來完成， 跟應(yīng)用層是否調(diào)用accept無關(guān)， 內(nèi)核將完成三次握手的socket 放到acceptqueue中，應(yīng)用調(diào)用accept 時，從accept queue中獲取連接。那么，如果backlog 非常大，而我又不及時調(diào)用accept 來消費(fèi)隊(duì)列，則連接就被積壓到accept queue中了。

同樣， 在三次握手完成后， 客戶端就可以發(fā)送數(shù)據(jù)了， 數(shù)據(jù)由內(nèi)核接收， 并保存在TCP 的buffer中， 而此時應(yīng)用（PHP）可能還沒有調(diào)用accept。

因此， 如果積壓在accept queue中的連接如果已經(jīng)被對方close， 應(yīng)用仍然可以accept到這個連接， 也可以調(diào)用read 讀取buffer中的數(shù)據(jù)， 但是，當(dāng)調(diào)用write 時， 則報錯：Broken pipe。

Backlog 過高的猜想，可以解釋當(dāng)前的故障現(xiàn)象， 但仍然有很多疑問需要解決

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

連接積壓后， PHP獲取到的都是close掉的連接，不需要返回響應(yīng)，應(yīng)該會快速失敗，那么消費(fèi)accept queue的速度應(yīng)該大大提高，最終將close掉的連接都快速消費(fèi)掉，系統(tǒng)應(yīng)該會恢復(fù)正常，但現(xiàn)實(shí)情況下負(fù)載卻持續(xù)很高，并且沒有恢復(fù)， 為什么？

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

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

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

這里從strace 可以找到答案， 我們看下， PHP在write brokenpipe后，到底又做了什么。通過對比正常php進(jìn)程跟異常php進(jìn)程的strace結(jié)果，我發(fā)現(xiàn)異常PHP進(jìn)程在寫log前調(diào)用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進(jìn)程：

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>

幾乎沒有耗費(fèi)時間！ 因此我們可以想到， 當(dāng)大多進(jìn)程都快速失敗時， 他們會同時去寫日志， 由于我們的日志程序在寫日志前都調(diào)用flock加鎖， 導(dǎo)致PHP進(jìn)程由于爭奪鎖而堵塞， 因此喪失了快速消費(fèi)acceptqueue的機(jī)會！

關(guān)于flock， 我查了下PHP 手冊， 其實(shí)一般情況下， 用append方式打開文件寫日志時，是不需要加鎖的， 因?yàn)槠浔旧頌樵硬僮?，具體參考：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 的配置文件， 我發(fā)現(xiàn)目前有兩個vhost， 其中一個是 A.cn， 其中關(guān)于fastcgi的超時fastcgi_read_timeout設(shè)置為100ms，可見這個時間是很容易造成超時的。另外一個vhost 配置了一系列域名，我這里就用B.cn來代替了，其中沒有配置fastcgi 相關(guān)的超時。會采用默認(rèn)值60s。

關(guān)于upstream 的配置是這樣的：

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

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

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

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

從請求分布的統(tǒng)計(jì)結(jié)果來看， 故障前后每分鐘請求數(shù)基本沒有變化， 那么說明不能摘掉后端的vhost B.cn的請求占比例應(yīng)該很大，從而導(dǎo)致可以摘掉后端的vhost A.cn 就算摘除了后端對請求數(shù)影響也不大。為了驗(yàn)證這個推論， 我統(tǒng)計(jì)了accesslog， 發(fā)現(xiàn) B.cn 占了大約85%的流量。因此推論正確。

Nginx 由于客戶端超時，不認(rèn)為是后端失敗， 從而沒有摘掉后端，喪失了故障恢復(fù)的機(jī)會。

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

從以上分析看出， 問題雖然是由于backlog 從128 變?yōu)?5535 引起， 但問題實(shí)際涉及從客戶端，nginx，到php等多個方面，而這多個方面都有問題，綜合導(dǎo)致了這次故障。

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

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

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

寫日志時，去掉flock，因?yàn)閍ppend 方式打開文件， fwrite是原子操作（除非要寫的字符串大于文件系統(tǒng)的block，一般block是4k，應(yīng)該不會超過吧？）。

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

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

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

之所以驗(yàn)證PHP 5.3.28是因?yàn)閾?jù)業(yè)務(wù)反映，以前測試時，這個版本也有問題，但5.3.28 默認(rèn)backlog是128，如果存在問題，則上面的結(jié)論就完全錯了。因此我要求重新驗(yàn)證一下。

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

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

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

統(tǒng)計(jì)數(shù)據(jù)從/proc/net/tcp獲取， 并每秒打印一次， 可以看到00:00:50這一刻， 連接隊(duì)列的積壓達(dá)到0x000004FC， 轉(zhuǎn)化為10進(jìn)制，也就是1276個。

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

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

從以上信息可以，各影響因素有一個發(fā)生改變，可能都不會導(dǎo)致系統(tǒng)負(fù)載居高不下的問題：

Nginx A.cn 調(diào)整100ms，如果時間夠長，則連接隊(duì)列的socket不會被close掉，就不會導(dǎo)致大量PHP進(jìn)程集中寫日志。

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

寫日志去掉flock，這樣避免flock驚群，等iowait恢復(fù)時，系統(tǒng)負(fù)載也就恢復(fù)了。

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

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