PHP通過strace定位排解故障位置並解決

這次給大家帶來PHP通過strace定位排解故障位置並解決，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/bashLOAD=$(awk '{print $1}' /proc/loadavg)if [ $(echo "$LOAD > 100" | bc) = 1 ]; then  /etc/init.d/php-fpm restartfi

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

閑言碎語不要講，輪到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 brkstat("/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」就是故障的原因。

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

相信看了本文案例你已經掌握了方法，更多精彩請關注php中文網其它相關文章！

推薦閱讀：

PHP使用file_get_contents發送http請求步驟詳解

PHP+MySQL處理高並發加鎖事務步驟詳解