【PHP問題定位】php-fpm的idle掉底分析

順風車運營研發團隊 熊浩含

問題現象

線上報警羣裏時而有php-fpm-idle的零星報警，持續時間很短（幾秒甚至一秒），見下圖

問題分析

發生故障時，咱們能夠經過觀察相關指標在故障時間的先後異常變化，找出故障緣由。經常使用的指標以下：

• cpu_idle
• php-fpm-idle
• io
• nginx.status.flow
• opcachereset

指標截圖以下：

io.read

nginx.status

opcachereset

在故障發生時（php-fpm-idle掉底），除了nginx的499明顯增多，io增大外，其他性能指標並沒有明顯變化。值得注意的是，故障時間與opcachereset時間高度重合，opcachereset是上線時的操做，會清除服務器上的phpopcache。故有兩種可能：

• 故障單純是清除opcache致使的，php須要從新解析php文件，耗時增長，php-fpm-idle降低;
• 上線時進行的某些操做，影響了某些url請求的效率，致使超時(nginx出現大量499)，也引發了php-fpm-idle降低;

nginx_499:部分請求長時間佔用了php-fpm進程（死循環或者超時），致使了新請求的排隊，php-fpm-idle降低。

cpu-idle:cpu-idle和php-fpm-idle其實並無直接關係，但會相互影響。當請求增多，php-fpm啓動了更多的進程處理請求，天然也會增長cpu的消耗，cpu_idle下降;而當cpu_idle下降時（cpu更忙），php處理請求比平時要花費更多的時間，致使請求堆積，php-fpm-idle降低。

io:磁盤io會直接影響fpm進程讀寫文件，io太高，致使讀寫文件慢；同時太高的io也會影響cpu-idle，進而間接影響php-fpm。

日誌採集系統對採集的性能指標數據有聚合操做。例如指標A10s採集一次，當天能夠按10s的粒度查看數據。但對於歷史數據，例如7天前，數據粒度再也不是10s,而變成了15分鐘，odin對數據作了聚合。這意味着一些」尖峯數據「隨着時間推移，其尖峯再也不，曲線會變得平滑。

問題定位

查看報警機器的nginx的access.log

取前幾處請求的traceid，在業務日誌中查看，發現大量的apollo（一個內部服務）請求超時，proc_time時間過長

在看nginx日誌的時候發現，499的log中，request_time是以客戶端斷開鏈接的時間計算的。例如api的請求超時時間是0.08s，超時後請求方主動斷開，此時nginx即打印了499的log（比0.08s稍長）。但實際上php-fpm的處理仍在繼續，過了更長的時間後，在trace日誌中打印了真正的執行時間（proc_time）。

查到這裏，個人猜測是：由於上線操做觸發了阿波羅(一個內部服務)的某種異常，致使阿波羅連接在這一瞬間所有超時，引發nginx的大量499，也引發了php-fpm-idle的掉底。

驗證這個猜測須要解決如下兩個問題：

• (一) 上線和阿波羅超時是否有必然的聯繫？須要多找幾個例子驗證
• (二）既然只要上線就會觸發這個問題，爲啥不是每臺機器都報警，而只有零星的報警？

先看問題（一），結果是振奮人心的，找了幾臺機器驗證，上線時間和業務日誌中大量出現」call apollo too long「的時間重合。週三晚加上了對阿波羅超時的監控，週四觀察上線期間阿波羅超時指標的變化，時間也吻合。

8月9日下午15：22又報了一次警

與此同時的阿波羅超時監控:

*.16.gz01

.17.gz01

.17.gz01

這裏同時列出17.gz01機器指標的目的是爲了說明，儘管17.gz01沒有報警，但17機器的指標變化和16是統一的。

再看問題（二）：個人猜測是，因爲故障時間很短（看機器日誌只有100ms左右）,而odin最短10s採集一次指標，大部分機器php-fpm-idle掉底的數據並無被採集到。

結論

上線過程當中清除了php的opcache，致使下一時刻的請求到來時，代碼中的阿波羅會讀取本地配置文件，io增長，而php須要從新解析文件，io進一步增大，耗時增長，致使php-fpm-idle有一瞬間的掉底。