本文实例讲述了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设置每分钟执行：

1. #/bin/bash 
2. LOAD=$(awk '{print $1}' /proc/loadavg) 
3. if [ $(echo "$LOAD > 100" | bc) = 1 ]; then 
4.   /etc/init.d/php-fpm restart 
5. fi 

可惜这只是一个权宜之计，要想彻底解决就必须找出故障的真正原因是什么。

闲言碎语不要讲，轮到Strace出场了，统计一下各个系统调用的耗时情况：

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

看上去「brk」非常可疑，它竟然耗费了三成的时间，保险起见，单独确认一下：

1. shell> strace -T -e brk -p $(pgrep -n php-cgi) 
2. brk(0x1f18000) = 0x1f18000 <0.024025> 
3. brk(0x1f58000) = 0x1f58000 <0.015503> 
4. brk(0x1f98000) = 0x1f98000 <0.013037> 
5. brk(0x1fd8000) = 0x1fd8000 <0.000056> 
6. 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），可是为什么呢？

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

直接把它们都禁用了，看看服务器是否能缓过来，或许大家觉得这太鲁蒙了，但是特殊情况必须做出特殊的决定，不能像个娘们儿似的优柔寡断，没过多久，服务器负载恢复正常，接着再统计一下系统调用的耗时：

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

显而易见，「brk」已经不见了，取而代之的是「recvfrom」和「accept」，不过这些操作本来就是很耗时的，所以可以定位「brk」就是故障的原因。

…

拥抱故障，每一次故障都是历练。正所谓：天将降大任于斯人也，必先苦其心志，劳其筋骨，饿其体肤，空乏其身，行拂乱其所为，所以动心忍性，增益其所不能。

Tags: strace PHP定位故障

分享到：