Strace 調(diào)試 PHP

strace 命令是一個集診斷操漠、調(diào)試、統(tǒng)計與一體的工具,我們可以使用 strace 對應(yīng)用的系統(tǒng)調(diào)用和信號傳遞的跟蹤結(jié)果來對應(yīng)用進(jìn)行分析殃姓,以達(dá)到解決問題或者是了解應(yīng)用工作過程的目的翔冀。

strace 的最簡單的用法就是執(zhí)行一個指定的命令导街,在指定的命令結(jié)束之后它也就退出了。在命令執(zhí)行的過程中纤子,strace 會記錄和解析命令進(jìn)程的所有系統(tǒng)調(diào)用以及這個進(jìn)程所接收到的所有的信號值搬瑰。

通常我們調(diào)試 PHP 可以通過 PHP 函數(shù) echo款票、var_dump、print_r 就能解決大多數(shù)問題泽论。亦或通過 XDebug 單點調(diào)試調(diào)試 PHP艾少。

那么,我們?yōu)楹涡枰褂?strace 來調(diào)試 PHP 呢翼悴?

  • 調(diào)試性能問題缚够。查看系統(tǒng)調(diào)用的頻率,找出耗時的程序段(磁盤 IO鹦赎、網(wǎng)絡(luò) IO)谍椅。
  • 查看程序讀取的配置文件。以此定位配置文件加載是否錯誤古话。
  • 查看某個 PHP 腳本長時間運(yùn)行“假死”的情況雏吭。

1 磁盤 IO

PHP 性能問題通常出現(xiàn)在磁盤 IO、網(wǎng)絡(luò) IO煞额。而磁盤 IO 通常是文件加載過多過大思恐,以及日志寫入磁盤有關(guān)。通過 strace 命令我們就知道這些對系統(tǒng)磁盤 IO 操作的位置耗時膊毁。得知是否出現(xiàn)性能問題需要優(yōu)化胀莹。網(wǎng)絡(luò) IO 通常指連接數(shù)據(jù)庫、調(diào)用第三方接口婚温、其他服務(wù)連接等描焰。如果一個網(wǎng)絡(luò)連接太久就會造成我們的 PHP-FPM 進(jìn)程不能得到有效利用,從而不能快速釋放而加重服務(wù)器負(fù)載栅螟。

現(xiàn)有 fileIo.php 如下類似代碼:

$handle = fopen(__FILE__, 'r');
$content = '';
while ($str = fgets($handle)) {
    $content .= $str;
}
fclose($handle);

我們通過 strace 執(zhí)行它荆秦。

$ strace -T php fileIo.php

會輸出如下信息(部分):

execve("/usr/local/php71/bin/php", ["php", "cli.php", "index/fileIo"], [/* 23 vars */]) = 0 <0.000818>
brk(NULL)                               = 0x2d69000 <0.000041>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f64f76bd000 <0.000046>
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) <0.000092>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000090>
fstat(3, {st_mode=S_IFREG|0644, st_size=43150, ...}) = 0 <0.000041>
mmap(NULL, 43150, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f64f76b2000 <0.000091>
close(3)                                = 0 <0.000040>
open("/lib64/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 3 <0.000240>

根據(jù)對輸出的日志,我們可以大致分為如下幾部分:

1.1命令啟動

execve("/usr/local/php71/bin/php", ["php", "fileIo.php"], [/* 23 vars */]) = 0

1.2 加載系統(tǒng)類庫

日志當(dāng)中類似以下信息都在加載 PHP 啟動時要加載的系統(tǒng)類庫力图。

open("/lib64/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 3 <0.000240>
open("/lib64/libz.so.1", O_RDONLY|O_CLOEXEC) = 3 <0.000063>
open("/usr/local/lib/libmcrypt.so.4", O_RDONLY|O_CLOEXEC) = 3 <0.000060>

1.3 PHP 命令查找

因為步绸,我們在用 PHP 命令執(zhí)行腳本的時候,并沒有用絕對路徑吃媒。所以瓤介,系統(tǒng)在執(zhí)行的時候,會嘗試去尋找 php 命令所在的位置赘那。如下日志所示:

lstat("/usr/local/erlang/bin/php", 0x7fff6ef8e590) = -1 ENOENT (No such file or directory)
lstat("/usr/local/nginx/sbin/php", 0x7fff6ef8e590) = -1 ENOENT (No such file or directory)
lstat("/usr/local/php71/bin/php", {st_mode=S_IFREG|0755, st_size=40414496, ...}) = 0

所以刑桑,我們想優(yōu)化腳本執(zhí)行的速度,那么在運(yùn)行腳本的時候可以使用絕對路徑募舟。這樣系統(tǒng)就不需要去這些目錄中遍列尋找祠斧。

1.4 PHP 配置文件加載

在日志中有如下信息:

open("/usr/local/php71/bin/php-cli.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/php71/etc/php-cli.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/php71/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/php71/etc/php.ini", O_RDONLY) = 3

可以看到,我們的 PHP 會優(yōu)先去 PHP 安裝目錄下的 bin 目錄加載 php-cli.ini 配置拱礁。不存在琢锋,接著去 etc 目錄下加載 php-cli.ini 配置辕漂。不存在,接著又去 bin 下讀取 php.ini 文件吩蔑。不存在钮热,又去 etc 目錄下找 php.ini 配置。

通過這些加載的順序以及文件路徑烛芬,我們可以清晰知道配置的加載順序,以及加載的配置是否有錯飒责。從而驗證我們的 PHP 是否正確配置赘娄。

1.5 加載 PHP 擴(kuò)展

當(dāng)配置文件加載成功之后,PHP 會解析配置文件宏蛉。然后遣臼,加載配置文件當(dāng)中注冊的擴(kuò)展。如下日志所示:

open("/usr/local/php71/lib/php/extensions/no-debug-non-zts-20160303/xdebug.so", O_RDONLY|O_CLOEXEC) = 3
open("/usr/local/php71/lib/php/extensions/no-debug-non-zts-20160303/redis.so", O_RDONLY|O_CLOEXEC) = 3
open("/usr/local/php71/lib/php/extensions/no-debug-non-zts-20160303/yaf.so", O_RDONLY|O_CLOEXEC) = 3

注意這里調(diào)用系統(tǒng)底層的 C 函數(shù) open拾并。-1 代表文件或目錄不存在揍堰,0 代表標(biāo)準(zhǔn)轉(zhuǎn)入,1 代表標(biāo)準(zhǔn)輸出嗅义,2 代表標(biāo)準(zhǔn)出錯屏歹,那么 3 就代表打開文件成功之后返回的句柄 ID。

所以之碗,我們經(jīng)常會建議 PHP 里面加載的擴(kuò)展不要太多蝙眶。夠用就行。這樣在系統(tǒng)加載的時候 IO 壓力就會小褪那。當(dāng)然幽纷,現(xiàn)在采用有了 PHP-FPM 之后,完全不用擔(dān)心這個加載的開銷了博敬。

1.6 TRACE 部分

write(4, "TRACE START [2018-07-20 07:45:47"..., 34) = 34 <0.000046>
write(4, "    0.0026     349704   -> {main"..., 55) = 55 <0.000022>
write(4, "    0.0029     349704     -> fop"..., 77) = 77 <0.000044>
open("/root/fileIo.php", O_RDONLY)      = 5 <0.000070>
fstat(5, {st_mode=S_IFREG|0644, st_size=126, ...}) = 0 <0.000011>
lseek(5, 0, SEEK_CUR)                   = 0 <0.000012>
write(3, "fl=(1) php:internal\nfn=(1) php::"..., 38) = 38 <0.000019>
write(3, "2 473 608\n\n", 11)           = 11 <0.000012>
write(4, "    0.0038     350312     -> fge"..., 84) = 84 <0.000017>
read(5, "<?php\n$handle = fopen(__FILE__, "..., 8192) = 126 <0.000017>
write(3, "fl=(1)\nfn=(2) php::fgets\n", 25) = 25 <0.000020>
write(3, "4 137 8224\n\n", 12)          = 12 <0.000040>
write(4, "    0.0042     358568     -> fge"..., 84) = 84 <0.000018>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000015>
write(3, "4 5 64\n\n", 8)               = 8 <0.000011>
write(4, "    0.0044     358632     -> fge"..., 84) = 84 <0.000013>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000013>
write(3, "4 1 40\n\n", 8)               = 8 <0.000019>
write(4, "    0.0046     358624     -> fge"..., 84) = 84 <0.000016>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000013>
write(3, "4 1 64\n\n", 8)               = 8 <0.000010>
write(4, "    0.0048     358680     -> fge"..., 84) = 84 <0.000016>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000011>
write(3, "4 2 48\n\n", 8)               = 8 <0.000018>
write(4, "    0.0050     358712     -> fge"..., 84) = 84 <0.000063>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000015>
write(3, "4 2 32\n\n", 8)               = 8 <0.000011>
write(4, "    0.0052     358696     -> fge"..., 84) = 84 <0.000014>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000013>
write(3, "4 0 48\n\n", 8)               = 8 <0.000010>
write(4, "    0.0054     358712     -> fge"..., 84) = 84 <0.000011>
read(5, "", 8192)                       = 0 <0.000024>
write(3, "fl=(1)\nfn=(2)\n", 14)        = 14 <0.000066>
write(3, "4 124 0\n\n", 9)              = 9 <0.000015>
write(4, "    0.0058     358664     -> fcl"..., 85) = 85 <0.000012>
close(5)                                = 0 <0.000014>
write(3, "fl=(1)\nfn=(3) php::fclose\n", 26) = 26 <0.000059>
write(3, "7 64 -8664\n\n", 12)          = 12 <0.000014>
write(3, "fl=(2) /root/fileIo.php\nfn=(4) {"..., 58) = 58 <0.000011>
write(3, "1 2352 -168\ncfl=(1)\ncfn=(1)\ncall"..., 375) = 375 <0.000012>
close(2)                                = 0 <0.000023>
close(1)                                = 0 <0.000008>
close(0)                                = 0 <0.000009>
write(4, "    0.0063        184\nTRACE END "..., 57) = 57 <0.000016>

從上面的日志友浸,我們可以發(fā)現(xiàn)如下字眼:

...TRACE START...
...TRACE END...

這確實也是我們 PHP 腳本真正邏輯執(zhí)行的部分。

通過這部分信息偏窝,我們可以看到收恢,我們確實通過系統(tǒng)底層的 open 方法打開了我們的腳本文件,并且調(diào)用了 read 方法讀取腳本中的內(nèi)容囚枪。

注意:

通過 open 函數(shù)打開 fileIo.php 腳本時返回的句柄 ID 的值是 5派诬。所以,對該文件的讀寫操作在下面全部是與 5 相關(guān)链沼。所以默赂, write(3, ...) 與 write(4, ..) 這樣的代碼僅僅與系統(tǒng)底層相關(guān)。

2 網(wǎng)絡(luò) IO

在第 1 小節(jié)括勺,我們通過快速查看了文件 IO 的相關(guān) PHP 執(zhí)行的調(diào)試缆八。本小節(jié)曲掰,我們主要講網(wǎng)絡(luò) IO 的調(diào)試。

2.1 TRACE 部分日志

write(4, "TRACE START [2018-07-20 08:31:43"..., 34) = 34 <0.000034>
write(4, "    0.0055     350160   -> {main"..., 54) = 54 <0.000057>
write(4, "    0.0057     350208     -> Red"..., 68) = 68 <0.000030>
stat("/etc/sysconfig/64bit_strstr_via_64bit_strstr_sse2_unaligned", 0x7ffc8db09af0) = -1 ENOENT (No such file or directory) <0.000029>
write(3, "fl=(1) php:internal\nfn=(1) php::"..., 51) = 51 <0.000032>
write(3, "2 5 0\n\n", 7)                = 7 <0.000032>
write(4, "    0.0064     350208     -> Red"..., 79) = 79 <0.000029>
socket(AF_INET6, SOCK_DGRAM, IPPROTO_IP) = 5 <0.000035>
close(5)                                = 0 <0.000033>
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 5 <0.000030>
fcntl(5, F_GETFL)                       = 0x2 (flags O_RDWR) <0.000024>
fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK)    = 0 <0.000032>
connect(5, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000128>
poll([{fd=5, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=5, revents=POLLOUT}]) <0.000047>
getsockopt(5, SOL_SOCKET, SO_ERROR, [0], [4]) = 0 <0.000043>
fcntl(5, F_SETFL, O_RDWR)               = 0 <0.000043>
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000044>
write(3, "fl=(1)\nfn=(2) php::Redis->connec"..., 34) = 34 <0.000075>
write(3, "3 1884 656\n\n", 12)          = 12 <0.000045>
write(4, "    0.0089     350864     -> Red"..., 67) = 67 <0.000048>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout) <0.000043>
sendto(5, "*2\r\n$6\r\nSELECT\r\n$1\r\n1\r\n", 23, MSG_DONTWAIT, NULL, 0) = 23 <0.000084>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=5, revents=POLLIN}]) <0.000042>
recvfrom(5, "+", 1, MSG_PEEK, NULL, NULL) = 1 <0.000043>
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}]) <0.000058>
recvfrom(5, "+OK\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 5 <0.000054>
write(3, "fl=(1)\nfn=(3) php::Redis->select"..., 33) = 33 <0.000052>
write(3, "4 1643 8192\n\n", 13)         = 13 <0.000042>
write(4, "    0.0111     359056     -> Red"..., 83) = 83 <0.000049>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout) <0.000044>
sendto(5, "*3\r\n$5\r\nLPUSH\r\n$8\r\nlist_key\r\n$12"..., 48, MSG_DONTWAIT, NULL, 0) = 48 <0.000058>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=5, revents=POLLIN}]) <0.000044>
recvfrom(5, ":", 1, MSG_PEEK, NULL, NULL) = 1 <0.000043>
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}]) <0.000043>
recvfrom(5, ":1\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 4 <0.000053>
write(3, "fl=(1)\nfn=(4) php::Redis->lPush\n", 32) = 32 <0.000088>
write(3, "5 1183 0\n\n", 10)            = 10 <0.000044>
write(4, "    0.0129     359056     -> Red"..., 70) = 70 <0.000052>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout) <0.000045>
sendto(5, "*2\r\n$4\r\nLPOP\r\n$8\r\nlist_key\r\n", 28, MSG_DONTWAIT, NULL, 0) = 28 <0.000078>
poll([{fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 1 ([{fd=5, revents=POLLIN}]) <0.000046>
recvfrom(5, "$", 1, MSG_PEEK, NULL, NULL) = 1 <0.000045>
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}]) <0.000049>
recvfrom(5, "$12\r\nhello world~\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 19 <0.000039>
write(3, "fl=(1)\nfn=(5) php::Redis->lPop\n", 31) = 31 <0.000082>
write(3, "6 1334 40\n\n", 11)           = 11 <0.000043>
write(1, "hello world~", 12)            = 12 <0.000046>
write(3, "fl=(2) /root/netIo.php\nfn=(6) {m"..., 58) = 58 <0.000091>
write(3, "1 3368 40\ncfl=(1)\ncfn=(1)\ncalls="..., 199) = 199 <0.000045>
write(4, "    0.0156     357168   -> Redis"..., 58) = 58 <0.000046>
close(5)                                = 0 <0.000059>
close(2)                                = 0 <0.000040>
close(1)                                = 0 <0.000040>
close(0)                                = 0 <0.000047>
write(4, "    0.0165        160\nTRACE END "..., 57) = 57 <0.000062>

我們發(fā)現(xiàn)奈辰,其中有一行日志如下:

connect(5, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000128>

這一行就是我們在連接 Redis 服務(wù)器栏妖。用時 0.000128 秒。

如果我們在運(yùn)行的腳本當(dāng)中懷疑連接 Redis 比較慢奖恰。那么就可以通過這樣的方式確診問題是否真正出在這里吊趾。

2.2 向隊列發(fā)送數(shù)據(jù)

sendto(5, "*2\r\n$4\r\nLPOP\r\n$8\r\nlist_key\r\n", 28, MSG_DONTWAIT, NULL, 0) = 28 <0.000078>

Redis lPush 命令是通過系統(tǒng)底層 sendto 方法封裝實現(xiàn)。

2.3 從接收隊列數(shù)據(jù)

recvfrom(5, "$12\r\nhello world~\r\n", 8192, MSG_DONTWAIT, NULL, NULL) = 19 <0.000039>

2.4 輸出數(shù)據(jù)

write(1, "hello world~", 12)            = 12 <0.000046>

我們向命令行輸出的時候就是調(diào)用了系統(tǒng)底層的 write 方法瑟啃。第一個參數(shù) 1 代表標(biāo)準(zhǔn)輸出的意思论泛。在 C 語言里面,0 代表標(biāo)準(zhǔn)輸入蛹屿,1 代表標(biāo)準(zhǔn)輸出屁奏。所謂標(biāo)準(zhǔn)輸出指的就是命令行輸出。

3 Strace 命令解讀

3.1 普通使用

$ strace php xxx.php

通常使用直接在前面加上 strace 即可错负。就會打印出腳本執(zhí)行中所有的 TRACE 信息坟瓢。

3.2 顯示運(yùn)行時間

$ strace -T php xxx.php

有時我們除了要查看 TRACE 信息∮倘觯可能還想知道每次系統(tǒng)調(diào)用所花費(fèi)的系統(tǒng)時間折联。此時可以加 -T 參數(shù)顯示花費(fèi)的時間。

花費(fèi)的時間單位要秒油航。能精確表示時間到納紗崭庸。1 秒等于 1 百萬納秒。

3.3 TRACE 信息保存到文件

$ strace -T -o strace.log php xxx.php

一個復(fù)雜的腳本往往會輸出大量的 TRACE 日志谊囚。如果直接輸出到屏幕會給排查問題帶來極大的不方便怕享。這里我們可以把這些日志保存到指定的文件當(dāng)中。

- o 后面空格之后緊張文件名即可镰踏。

3.4 統(tǒng)計執(zhí)行的時間

我們可能想快速知曉我們的 PHP 腳本運(yùn)行花費(fèi)的總時間函筋,在哪些位置花費(fèi)時間的比例,以及哪些地方系統(tǒng)底層調(diào)用次數(shù)奠伪。通過這些數(shù)據(jù)可以大致推斷出當(dāng)前腳本可能出現(xiàn)的問題跌帐。

如下命令:

$ strace -c php xxx.php

如輸出如下數(shù)據(jù):

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 29.08    0.001196           7       184         1 mmap
 20.54    0.000845           7       115           mprotect
 14.64    0.000602           7        83        10 open
  6.95    0.000286           4        79           fstat
  6.15    0.000253           4        69           read
  5.98    0.000246           6        43           munmap
  5.42    0.000223           3        80           close
  2.02    0.000083          28         3           sendto
  1.82    0.000075          75         1         1 connect
  1.56    0.000064           3        24           write
  1.43    0.000059           5        11           poll
  0.92    0.000038           1        43           brk
  0.61    0.000025           0        80           rt_sigaction
  0.56    0.000023          23         1           ftruncate
  0.39    0.000016           2         7         3 access
  0.19    0.000008           3         3           recvfrom
  0.17    0.000007           1         9         2 lstat
  0.15    0.000006           2         3           fcntl
  0.12    0.000005           1         6         3 lseek
  0.12    0.000005           2         3           socket
  0.12    0.000005           5         1           execve
  0.12    0.000005           3         2           getdents
  0.10    0.000004           0         9         7 stat
  0.10    0.000004           1         4           getcwd
  0.10    0.000004           1         5           futex
  0.07    0.000003           2         2           madvise
  0.07    0.000003           3         1           setsockopt
  0.07    0.000003           3         1           getsockopt
  0.07    0.000003           2         2           umask
  0.05    0.000002           1         2           rt_sigprocmask
  0.05    0.000002           1         2         2 ioctl
  0.05    0.000002           1         2           uname
  0.05    0.000002           1         3           getrlimit
  0.05    0.000002           1         2           getuid
  0.05    0.000002           1         2         1 openat
  0.02    0.000001           1         1           geteuid
  0.02    0.000001           1         1           arch_prctl
  0.00    0.000000           0         3           flock
  0.00    0.000000           0         1           getgid
  0.00    0.000000           0         1           getegid
  0.00    0.000000           0         2         2 statfs
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           dup3
------ ----------- ----------- --------- --------- ----------------
100.00    0.004113                   899        32 total

通過上述輸出的信息。我們知道了如下信息:

1)腳本運(yùn)行花費(fèi) 0.004113 秒绊率。

2)耗時最高的三個底層系統(tǒng)調(diào)用為:mmap谨敛、mprotect、open滤否。

3)每個系統(tǒng)調(diào)用的次數(shù)/錯誤次數(shù)脸狸。

4)腳本運(yùn)行過程中調(diào)用了哪些系統(tǒng)底層函數(shù)。

腳本優(yōu)化可以根據(jù)這些時間指標(biāo)進(jìn)行對應(yīng)的優(yōu)化。

比如炊甲,表格當(dāng)中 errors 錯誤過多泥彤,有可能說明我們的環(huán)境嘗試了過多的文件加載。導(dǎo)致系統(tǒng)遍列文件時做了過多錯誤的嘗試卿啡。這就是為什么我們在寫程序的時候推薦使用絕對路徑的原因所在吟吝。

其次,如果一個腳本在執(zhí)行過程中調(diào)用了太多次的系統(tǒng) open 方法颈娜,說明我們的腳本有可能存在不合理的磁盤或網(wǎng)絡(luò) IO剑逃。通常是磁盤 IO。當(dāng)出現(xiàn)磁盤 IO 問題的時候官辽,就要引起足夠的重視炕贵。

總之,任何異常的時間開銷野崇,我們都要引起足夠的重視。

3.5 TRACE 已有進(jìn)程

當(dāng)一個進(jìn)程已經(jīng)啟動了亩钟,我們想 TRACE 它乓梨。也是非常簡單的。

$ strace -p 進(jìn)程ID

嗯清酥。就是這么簡單扶镀。剩下的跟我們之前上面講過的差不多。一樣一樣的焰轻。

3.6 更多可選參數(shù)說明

以上 5 小點是我們通常用得最多的參數(shù)臭觉。當(dāng)然,strace 的功能遠(yuǎn)不僅如此辱志。我們可以通過更多的可選參數(shù)發(fā)揮它的功能蝠筑。

-c 統(tǒng)計每一系統(tǒng)調(diào)用的所執(zhí)行的時間,次數(shù)和出錯的次數(shù)等.
-d 輸出 strace 關(guān)于標(biāo)準(zhǔn)錯誤的調(diào)試信息.
-f 跟蹤由 fork 調(diào)用所產(chǎn)生的子進(jìn)程.
-ff 如果提供 -o filename,則所有進(jìn)程的跟蹤結(jié)果輸出到相應(yīng)的filename.pid中,pid是各進(jìn)程的進(jìn)程號.
-F 嘗試跟蹤vfork調(diào)用.在-f時,vfork不被跟蹤.
-h 輸出簡要的幫助信息.
-i 輸出系統(tǒng)調(diào)用的入口指針.
-q 禁止輸出關(guān)于脫離的消息.
-r 打印出相對時間關(guān)于,每一個系統(tǒng)調(diào)用.
-t 在輸出中的每一行前加上時間信息.
-tt 在輸出中的每一行前加上時間信息,微秒級.
-ttt 微秒級輸出,以秒了表示時間.
-T 顯示每一調(diào)用所耗的時間.
-v 輸出所有的系統(tǒng)調(diào)用.一些調(diào)用關(guān)于環(huán)境變量,狀態(tài),輸入輸出等調(diào)用由于使用頻繁,默認(rèn)不輸出.
-V 輸出strace的版本信息.
-x 以十六進(jìn)制形式輸出非標(biāo)準(zhǔn)字符串
-xx 所有字符串以十六進(jìn)制形式輸出.
-a column 設(shè)置返回值的輸出位置.默認(rèn) 為40.
-e expr 指定一個表達(dá)式,用來控制如何跟蹤.格式:[qualifier=][!]value1[,value2]...
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用來限定的符號或數(shù)字.默認(rèn)的 qualifier是 trace.感嘆號是否定符號.例如:-eopen等價于 -e trace=open,表示只跟蹤open調(diào)用.而-etrace!=open 表示跟蹤除了open以外的其他調(diào)用.有兩個特殊的符號 all 和 none. 注意有些shell使用!來執(zhí)行歷史記錄里的命令,所以要使用\\.
-e trace=set 只跟蹤指定的系統(tǒng) 調(diào)用.例如:-e trace=open,close,rean,write表示只跟蹤這四個系統(tǒng)調(diào)用.默認(rèn)的為set=all.
-e trace=file 只跟蹤有關(guān)文件操作的系統(tǒng)調(diào)用.
-e trace=process 只跟蹤有關(guān)進(jìn)程控制的系統(tǒng)調(diào)用.
-e trace=network 跟蹤與網(wǎng)絡(luò)有關(guān)的所有系統(tǒng)調(diào)用.
-e strace=signal 跟蹤所有與系統(tǒng)信號有關(guān)的 系統(tǒng)調(diào)用
-e trace=ipc 跟蹤所有與進(jìn)程通訊有關(guān)的系統(tǒng)調(diào)用
-e abbrev=set 設(shè)定strace輸出的系統(tǒng)調(diào)用的結(jié)果集.-v 等與 abbrev=none.默認(rèn)為abbrev=all.
-e raw=set 將指定的系統(tǒng)調(diào)用的參數(shù)以十六進(jìn)制顯示.
-e signal=set 指定跟蹤的系統(tǒng)信號.默認(rèn)為all.如 signal=!SIGIO(或者signal=!io),表示不跟蹤SIGIO信號.
-e read=set 輸出從指定文件中讀出 的數(shù)據(jù).例如: -e read=3,5
-e write=set 輸出寫入到指定文件中的數(shù)據(jù).
-o filename 將strace的輸出寫入文件filename
-p pid 跟蹤指定的進(jìn)程pid.
-s strsize 指定輸出的字符串的最大長度.默認(rèn)為32.文件名一直全部輸出.
-u username 以username的UID和GID執(zhí)行被跟蹤的命令

4 總結(jié)

總的來說,我們可以使用 strace 命令得知我們的 PHP 腳本運(yùn)行時調(diào)用了底層哪些方法揩懒,以及運(yùn)行的時間等信息什乙。讓我們可以判斷腳本當(dāng)中到底出了什么病況而后進(jìn)行優(yōu)化。

但是已球,strace 有一個不足:調(diào)試 PHP 的時候無法獲知每個系統(tǒng)調(diào)用對應(yīng)了 PHP 哪個腳本的哪個方法或哪一行臣镣。這樣即使我們知道腳本存在時間上的異常耗時,也無法快速獲知是哪里出現(xiàn)了問題智亮。

要熟悉掌握 strace忆某,還需要對底層系統(tǒng)方法有一定的了解。

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末阔蛉,一起剝皮案震驚了整個濱河市弃舒,隨后出現(xiàn)的幾起案子,更是在濱河造成了極大的恐慌馍忽,老刑警劉巖棒坏,帶你破解...
    沈念sama閱讀 216,402評論 6 499
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件燕差,死亡現(xiàn)場離奇詭異,居然都是意外死亡坝冕,警方通過查閱死者的電腦和手機(jī)徒探,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 92,377評論 3 392
  • 文/潘曉璐 我一進(jìn)店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來喂窟,“玉大人测暗,你說我怎么就攤上這事∧ピ瑁” “怎么了碗啄?”我有些...
    開封第一講書人閱讀 162,483評論 0 353
  • 文/不壞的土叔 我叫張陵,是天一觀的道長稳摄。 經(jīng)常有香客問我稚字,道長,這世上最難降的妖魔是什么厦酬? 我笑而不...
    開封第一講書人閱讀 58,165評論 1 292
  • 正文 為了忘掉前任胆描,我火速辦了婚禮,結(jié)果婚禮上仗阅,老公的妹妹穿的比我還像新娘昌讲。我一直安慰自己,他們只是感情好减噪,可當(dāng)我...
    茶點故事閱讀 67,176評論 6 388
  • 文/花漫 我一把揭開白布短绸。 她就那樣靜靜地躺著,像睡著了一般筹裕。 火紅的嫁衣襯著肌膚如雪醋闭。 梳的紋絲不亂的頭發(fā)上,一...
    開封第一講書人閱讀 51,146評論 1 297
  • 那天饶碘,我揣著相機(jī)與錄音目尖,去河邊找鬼。 笑死扎运,一個胖子當(dāng)著我的面吹牛瑟曲,可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播豪治,決...
    沈念sama閱讀 40,032評論 3 417
  • 文/蒼蘭香墨 我猛地睜開眼洞拨,長吁一口氣:“原來是場噩夢啊……” “哼!你這毒婦竟也來了负拟?” 一聲冷哼從身側(cè)響起烦衣,我...
    開封第一講書人閱讀 38,896評論 0 274
  • 序言:老撾萬榮一對情侶失蹤,失蹤者是張志新(化名)和其女友劉穎,沒想到半個月后花吟,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體秸歧,經(jīng)...
    沈念sama閱讀 45,311評論 1 310
  • 正文 獨居荒郊野嶺守林人離奇死亡,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,536評論 2 332
  • 正文 我和宋清朗相戀三年衅澈,在試婚紗的時候發(fā)現(xiàn)自己被綠了键菱。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點故事閱讀 39,696評論 1 348
  • 序言:一個原本活蹦亂跳的男人離奇死亡今布,死狀恐怖经备,靈堂內(nèi)的尸體忽然破棺而出,到底是詐尸還是另有隱情部默,我是刑警寧澤侵蒙,帶...
    沈念sama閱讀 35,413評論 5 343
  • 正文 年R本政府宣布,位于F島的核電站傅蹂,受9級特大地震影響纷闺,放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜份蝴,卻給世界環(huán)境...
    茶點故事閱讀 41,008評論 3 325
  • 文/蒙蒙 一急但、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧搞乏,春花似錦、人聲如沸戒努。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,659評論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽储玫。三九已至侍筛,卻和暖如春,著一層夾襖步出監(jiān)牢的瞬間撒穷,已是汗流浹背匣椰。 一陣腳步聲響...
    開封第一講書人閱讀 32,815評論 1 269
  • 我被黑心中介騙來泰國打工, 沒想到剛下飛機(jī)就差點兒被人妖公主榨干…… 1. 我叫王不留端礼,地道東北人禽笑。 一個月前我還...
    沈念sama閱讀 47,698評論 2 368
  • 正文 我出身青樓,卻偏偏與公主長得像蛤奥,于是被迫代替她去往敵國和親佳镜。 傳聞我的和親對象是個殘疾皇子,可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,592評論 2 353