PHP-通過strace定位故障原因


俗話說:不怕賊偷,就怕賊惦記着。在面對故障的時候,我也有類似的感覺:不怕出故障,就怕你不知道故障的原因,故障卻隔三差五的找上門來。

 

十一長假還沒結束,服務器卻頻現高負載,Nginx出現錯誤日志:

    connect() failed (110: Connection timed out) while connecting to upstream
    connect() failed (111: Connection refused) while connecting to upstream

看上去是Upstream出了問題,在本例中Upstream就是PHP(版本:5.2.5)。可惜監控不完善,我搞不清楚到底是哪出了問題,無奈之下只好不斷重啟PHP來緩解故障。

如果每次都手動重啟服務無疑是個苦差事,幸運的是可以通過CRON設置每分鍾執行:

#/bin/bash

LOAD=$(awk '{print $1}' /proc/loadavg)

if [ $(echo "$LOAD > 100" | bc) = 1 ]; then
    /etc/init.d/php-fpm restart
fi

可惜這只是一個權宜之計,要想徹底解決就必須找出故障的真正原因是什么。

閑言碎語不要講,輪到Strace出場了,統計一下各個系統調用的耗時情況:

shell> strace -c -p $(pgrep -n php-cgi)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.53    0.023554         132       179           brk
 14.71    0.011350         140        81           mlock
 12.70    0.009798          15       658        16 recvfrom
  8.96    0.006910           7       927           read
  6.61    0.005097          43       119           accept
  5.57    0.004294           4       977           poll
  3.13    0.002415           7       359           write
  2.82    0.002177           7       311           sendto
  2.64    0.002033           2      1201         1 stat
  2.27    0.001750           1      2312           gettimeofday
  2.11    0.001626           1      1428           rt_sigaction
  1.55    0.001199           2       730           fstat
  1.29    0.000998          10       100       100 connect
  1.03    0.000792           4       178           shutdown
  1.00    0.000773           2       492           open
  0.93    0.000720           1       711           close
  0.49    0.000381           2       238           chdir
  0.35    0.000271           3        87           select
  0.29    0.000224           1       357           setitimer
  0.21    0.000159           2        81           munlock
  0.17    0.000133           2        88           getsockopt
  0.14    0.000110           1       149           lseek
  0.14    0.000106           1       121           mmap
  0.11    0.000086           1       121           munmap
  0.09    0.000072           0       238           rt_sigprocmask
  0.08    0.000063           4        17           lstat
  0.07    0.000054           0       313           uname
  0.00    0.000000           0        15         1 access
  0.00    0.000000           0       100           socket
  0.00    0.000000           0       101           setsockopt
  0.00    0.000000           0       277           fcntl
------ ----------- ----------- --------- --------- ----------------
100.00    0.077145                 13066       118 total

看上去「brk」非常可疑,它竟然耗費了三成的時間,保險起見,單獨確認一下:

shell> strace -T -e brk -p $(pgrep -n php-cgi)
brk(0x1f18000) = 0x1f18000 <0.024025>
brk(0x1f58000) = 0x1f58000 <0.015503>
brk(0x1f98000) = 0x1f98000 <0.013037>
brk(0x1fd8000) = 0x1fd8000 <0.000056>
brk(0x2018000) = 0x2018000 <0.012635>

說明:在Strace中和操作花費時間相關的選項有兩個,分別是「-r」和「-T」,它們的差別是「-r」表示相對時間,而「-T」表示絕對時間。 簡單統計可以用「-r」,但是需要注意的是在多任務背景下,CPU隨時可能會被切換出去做別的事情,所以相對時間不一定准確,此時最好使用「-T」,在行 尾可以看到操作時間,可以發現確實很慢。

在繼續定位故障原因前,我們先通過「man brk」來查詢一下它的含義:

brk() sets the end of the data segment to the value specified by end_data_segment, when that value is reasonable, the system does have enough memory and the process does not exceed its max data size (see setrlimit(2)).

簡單點說就是內存不夠用時通過它來申請新內存(data segment),可是為什么呢?

shell> strace -T -p $(pgrep -n php-cgi) 2>&1 | grep -B 10 brk
stat("/path/to/script.php", {...}) = 0 <0.000064>
brk(0x1d9a000) = 0x1d9a000 <0.000067>
brk(0x1dda000) = 0x1dda000 <0.001134>
brk(0x1e1a000) = 0x1e1a000 <0.000065>
brk(0x1e5a000) = 0x1e5a000 <0.012396>
brk(0x1e9a000) = 0x1e9a000 <0.000092>

通過「grep」我們很方便就能獲取相關的上下文,反復運行幾次,發現每當請求某些PHP腳本時,就會出現若干條耗時的「brk」,而且這些PHP 腳本有一個共同的特點,就是非常大,甚至有幾百K,為何會出現這么大的PHP腳本?實際上是程序員為了避免數據庫操作,把非常龐大的數組變量通過「var_export」持久化到PHP文件中,然后在程序中通過「include」來獲取相應的變量,因為變量太大,所以PHP不得不頻繁執行「brk」,不幸的是在本例的環境中,此操作比較慢,從而導致處理請求的時間過長,加之PHP進程數有限,於是乎在Nginx上造成請求擁堵,最終導致高負載故障。

下面需要驗證一下推斷似乎否正確,首先查詢一下有哪些地方涉及問題腳本:

shell> find /path -name "*.php" | xargs grep "script.php"

直接把它們都禁用了,看看服務器是否能緩過來,或許大家覺得這太魯蒙了,但是特殊情況必須做出特殊的決定,不能像個娘們兒似的優柔寡斷,沒過多久,服務器負載恢復正常,接着再統計一下系統調用的耗時:

shell> strace -c -p $(pgrep -n php-cgi)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 24.50    0.001521          11       138         2 recvfrom
 16.11    0.001000          33        30           accept
  7.86    0.000488           8        59           sendto
  7.35    0.000456           1       360           rt_sigaction
  6.73    0.000418           2       198           poll
  5.72    0.000355           1       285           stat
  4.54    0.000282           0       573           gettimeofday
  4.41    0.000274           7        42           shutdown
  4.40    0.000273           2       137           open
  3.72    0.000231           1       197           fstat
  2.93    0.000182           1       187           close
  2.56    0.000159           2        90           setitimer
  2.13    0.000132           1       244           read
  1.71    0.000106           4        30           munmap
  1.16    0.000072           1        60           chdir
  1.13    0.000070           4        18           setsockopt
  1.05    0.000065           1       100           write
  1.05    0.000065           1        64           lseek
  0.95    0.000059           1        75           uname
  0.00    0.000000           0        30           mmap
  0.00    0.000000           0        60           rt_sigprocmask
  0.00    0.000000           0         3         2 access
  0.00    0.000000           0         9           select
  0.00    0.000000           0        20           socket
  0.00    0.000000           0        20        20 connect
  0.00    0.000000           0        18           getsockopt
  0.00    0.000000           0        54           fcntl
  0.00    0.000000           0         9           mlock
  0.00    0.000000           0         9           munlock
------ ----------- ----------- --------- --------- ----------------
100.00    0.006208                  3119        24 total

顯而易見,「brk」已經不見了,取而代之的是「recvfrom」和「accept」,不過這些操作本來就是很耗時的,所以可以定位「brk」就是故障的原因。

擁抱故障,每一次故障都是歷練。正所謂:天將降大任於斯人也,必先苦其心志,勞其筋骨,餓其體膚,空乏其身,行拂亂其所為,所以動心忍性,增益其所不能。


注意!

本站转载的文章为个人学习借鉴使用,本站对版权不负任何法律责任。如果侵犯了您的隐私权益,请联系我们删除。



 
粤ICP备14056181号  © 2014-2020 ITdaan.com