分析 PHP升級致使系統負載太高問題（轉載）

原文：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進程到底堵塞在哪裏。

分析

1. Strace

週一將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

用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 <mss 1460,nop,nop,sackOK,nop,wscale 7> 

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 爲何突升？

解答

6.1 對於acceptqueue 如何慢慢積壓，暫時我尚未確鑿的證據，不過能夠經過日誌和配置作一些推想。

首先從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也必然會積壓。

6.2 PHP 進程爲何沒有由於快速失敗而快速消費隊列呢？

這裏從strace 能夠找到答案， 咱們看下， PHP在write brokenpipe後，到底又作了什麼。經過對比正常php進程跟異常php進程的strace結果，我發現異常PHP進程在寫log前調用flock，耗時比較多：

1403674085.279482 flock(4, LOCK_EX) = 0 1403674085.668528 write(4, "1\t1\t1403674085\xx\t11"..., 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\t1\t1403680571\xx\t11"..., 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. 

6.3 Nginx 爲何沒有摘掉後端？

經過分析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 因爲客戶端超時，不認爲是後端失敗， 從而沒有摘掉後端，喪失了故障恢復的機會。

6.4 上下文切換cswch/s 爲何突升？

這個問題， 我沒有確切答案， 不過能夠合理推論， 幾百進程同事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，若是存在問題，則上面的結論就徹底錯了。所以我要求從新驗證一下。

驗證結果(2014-07-31)

通過一個月的線上驗證，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，不會積壓鏈接，也就不存在負載太高的問題了。