通過Strace定位故障原因
這是一個(gè)Nginx錯(cuò)誤日志：
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）。可惜監(jiān)控不完善，我搞不清楚到底是哪出了問題，無(wú)奈之下只好不斷重啟PHP來(lái)緩解故障。
如果每次都手動(dòng)重啟服務(wù)無(wú)疑是個(gè)苦差事，幸運(yùn)的是可以通過CRON設(shè)置每分鐘執(zhí)行：
#/bin/bash/p>
p>LOAD=$(awk '{print $1}' /proc/loadavg)/p>
p>if [ $(echo "$LOAD > 100" | bc) = 1 ]; then
/etc/init.d/php-fpm restart
fi
可惜這只是一個(gè)權(quán)宜之計(jì)，要想徹底解決就必須找出故障的真正原因是什么。
閑言碎語(yǔ)不要講，輪到Strace出場(chǎng)了，統(tǒng)計(jì)一下各個(gè)系統(tǒng)調(diào)用的耗時(shí)情況：
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」非常可疑，它竟然耗費(fèi)了三成的時(shí)間，保險(xiǎn)起見，單獨(dú)確認(rèn)一下：
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>
說(shuō)明：在Strace中和操作花費(fèi)時(shí)間相關(guān)的選項(xiàng)有兩個(gè)，分別是「-r」和「-T」，它們的差別是「-r」表示相對(duì)時(shí)間，而「-T」表示絕對(duì)時(shí)間。簡(jiǎn)單統(tǒng)計(jì)可以用「-r」，但是需要注意的是在多任務(wù)背景下，CPU隨時(shí)可能會(huì)被切換出去做別的事情，所以相對(duì)時(shí)間不一定準(zhǔn)確，此時(shí)最好使用「-T」，在行尾可以看到操作時(shí)間，可以發(fā)現(xiàn)確實(shí)很慢。
在繼續(xù)定位故障原因前，我們先通過「man brk」來(lái)查詢一下它的含義：
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)).
簡(jiǎn)單點(diǎn)說(shuō)就是內(nèi)存不夠用時(shí)通過它來(lái)申請(qǐng)新內(nèi)存（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」我們很方便就能獲取相關(guān)的上下文，反復(fù)運(yùn)行幾次，發(fā)現(xiàn)每當(dāng)請(qǐng)求某些PHP腳本時(shí)，就會(huì)出現(xiàn)若干條耗時(shí)的「brk」，而且這些PHP腳本有一個(gè)共同的特點(diǎn)，就是非常大，甚至有幾百K，為何會(huì)出現(xiàn)這么大的PHP腳本？實(shí)際上是程序員為了避免數(shù)據(jù)庫(kù)操作，把非常龐大的數(shù)組變量通過「var_export」持久化到PHP文件中，然后在程序中通過「include」來(lái)獲取相應(yīng)的變量，因?yàn)樽兞刻螅訮HP不得不頻繁執(zhí)行「brk」，不幸的是在本例的環(huán)境中，此操作比較慢，從而導(dǎo)致處理請(qǐng)求的時(shí)間過長(zhǎng)，加之PHP進(jìn)程數(shù)有限，于是乎在Nginx上造成請(qǐng)求擁堵，最終導(dǎo)致高負(fù)載故障。
下面需要驗(yàn)證一下推斷似乎否正確，首先查詢一下有哪些地方涉及問題腳本：
shell> find /path -name "*.php" | xargs grep "script.php"
直接把它們都禁用了，看看服務(wù)器是否能緩過來(lái)，或許大家覺得這太魯蒙了，但是特殊情況必須做出特殊的決定，不能像個(gè)娘們兒似的優(yōu)柔寡斷，沒過多久，服務(wù)器負(fù)載恢復(fù)正常，接著再統(tǒng)計(jì)一下系統(tǒng)調(diào)用的耗時(shí)：
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」已經(jīng)不見了，取而代之的是「recvfrom」和「accept」，不過這些操作本來(lái)就是很耗時(shí)的，所以可以定位「brk」就是故障的原因。
用 strace 診斷問題
早些年，如果你知道有個(gè) strace 命令，就很牛了，而現(xiàn)在大家基本都知道 strace 了，如果你遇到性能問題求助別人，十有八九會(huì)建議你用 strace 掛上去看看，不過當(dāng)你掛上去了，看著滿屏翻滾的字符，卻十有八九看不出個(gè)所以然。本文通過一個(gè)簡(jiǎn)單的案例，向你展示一下在用 strace 診斷問題時(shí)的一些套路。
如下真實(shí)案例，如有雷同，實(shí)屬必然！讓我們看一臺(tái)高負(fù)載服務(wù)器的 top 結(jié)果：
技巧：運(yùn)行 top 時(shí)，按「1」打開 CPU 列表，按「shift+p」以 CPU 排序。
在本例中大家很容易發(fā)現(xiàn) CPU 主要是被若干個(gè) PHP 進(jìn)程占用了，同時(shí) PHP 進(jìn)程占用的比較多的內(nèi)存，不過系統(tǒng)內(nèi)存尚有結(jié)余，SWAP 也不嚴(yán)重，這并不是問題主因。
不過在 CPU 列表中能看到 CPU 主要消耗在內(nèi)核態(tài)「sy」，而不是用戶態(tài)「us」，和我們的經(jīng)驗(yàn)不符。Linux 操作系統(tǒng)有很多用來(lái)跟蹤程序行為的工具，內(nèi)核態(tài)的函數(shù)調(diào)用跟蹤用「strace」，用戶態(tài)的函數(shù)調(diào)用跟蹤用「ltrace」，所以這里我們應(yīng)該用「strace」：
shell> strace -p PID>
不過如果直接用 strace 跟蹤某個(gè)進(jìn)程的話，那么等待你的往往是滿屏翻滾的字符，想從這里看出問題的癥結(jié)并不是一件容易的事情，好在 strace 可以按操作匯總時(shí)間：
shell> strace -cp PID>
通過「c」選項(xiàng)用來(lái)匯總各個(gè)操作的總耗時(shí)，運(yùn)行后的結(jié)果大概如下圖所示：
很明顯，我們能看到 CPU 主要被 clone 操作消耗了，還可以單獨(dú)跟蹤一下 clone：
shell> strace -T -e clone -p PID>
通過「T」選項(xiàng)可以獲取操作實(shí)際消耗的時(shí)間，通過「e」選項(xiàng)可以跟蹤某個(gè)操作：
很明顯，一個(gè) clone 操作需要幾百毫秒，至于 clone 的含義，參考 man 文檔：
clone() creates a new process, in a manner similar to fork(2). It is actually a library function layered on top of the underlying clone() system call, hereinafter referred to as sys_clone. A description of sys_clone is given towards the end of this page.
Unlike fork(2), these calls allow the child process to share parts of its execution context with the calling process, such as the memory space, the table of file descriptors, and the table of signal handlers. (Note that on this manual page, “calling process” normally corresponds to “parent process”. But see the description of CLONE_PARENT below.)
簡(jiǎn)單來(lái)說(shuō)，就是創(chuàng)建一個(gè)新進(jìn)程。那么在 PHP 里什么時(shí)候會(huì)出現(xiàn)此類系統(tǒng)調(diào)用呢？查詢業(yè)務(wù)代碼看到了 exec 函數(shù)，通過如下命令驗(yàn)證它確實(shí)會(huì)導(dǎo)致 clone 系統(tǒng)調(diào)用：
shell> strace -eclone php -r 'exec("ls");'
最后再考大家一個(gè)題：如果我們用 strace 跟蹤一個(gè)進(jìn)程，輸出結(jié)果很少，是不是說(shuō)明進(jìn)程很空閑？其實(shí)試試 ltrace，可能會(huì)發(fā)現(xiàn)別有洞天。記住有內(nèi)核態(tài)和用戶態(tài)之分。
