使用strace工具故障排查的5種簡單方法

strace 是一個非常簡單的工具，用來跟蹤可執(zhí)行程序的系統(tǒng)調(diào)用(system call)。最簡單的使用是，它追蹤可行程序運行時的整個生命周期，輸出每一個系統(tǒng)調(diào)用的名字，參數(shù)和返回值。

但是它還可以做更多的事情：

它可以基于系統(tǒng)調(diào)用或者系統(tǒng)調(diào)用組來過濾

它可以通過計算制定系統(tǒng)調(diào)用的次數(shù)，花費的時間以及成功和失敗的次數(shù)來描述系統(tǒng)調(diào)用的使用

它可以追蹤發(fā)送給進程的信號(signal)

它可以通過進程id(pid)號加入到任意正在運行的進程上

如何使用

這里只是簡單的描述strace如何使用，并不打算對此做深入分析

找出一個程序啟動時讀取了哪個配置文件

有的時候，你發(fā)發(fā)現(xiàn)，無論你如何修改配置文件，應(yīng)用程序并沒有按照你的思路去運行，這是什么原因？一個淺顯但容易忽視的考慮是，應(yīng)用程序啟動時讀取了你認為要讀取的配置文件了嗎？看下面的例子：

$ strace php 2>&1 | grep php.ini open("/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/local/lib/php.ini", O_RDONLY) = 4 lstat64("/usr/local/lib/php.ini", {st_mode=S_IFLNK|0777, st_size=27, ...}) = 0 readlink("/usr/local/lib/php.ini", "/usr/local/Zend/etc/php.ini", 4096) = 27 lstat64("/usr/local/Zend/etc/php.ini", {st_mode=S_IFREG|0664,st_size=40971, ...}) = 0

上述php程序程序會首先從/usr/local/bin/下讀取php.ini文件，也許不是你想的首先從/usr/local/lib/下讀取。

上述的輸出會很多，我們甚至可以通過參數(shù)來指定只追蹤我們關(guān)心的系統(tǒng)調(diào)用，類似如下：

$ strace -e open php 2>&1 | grep php.ini open("/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/local/lib/php.ini", O_RDONLY) = 4

為什么程序沒有打開我的文件？

每一個可執(zhí)行程序讀取文件時，如果權(quán)限不夠，則會遭拒絕。而如果文件找不到，也并不會報錯，除非你在程序里設(shè)置了錯誤處理，So，如果程序沒有讀取我的文件，我該如何跟蹤呢？

$ strace -e open,access 2>&1 |grep your-filename

檢查open()和access()系統(tǒng)調(diào)用的輸出結(jié)果，看看是什么原因

進程此刻正在做什么？

你的程序突然消耗了大量的CPU，或者程序似乎被掛起了，那么我們通過進程的pid號看看此刻它正在做什么

root@dev:~# strace -p 15427 Process 15427 attached - interrupt to quit futex(0x402f4900, FUTEX_WAIT, 2, NULL Process 15427 detached

通過跟蹤，你知道程序掛起的原因是正在調(diào)用futex()。

程序的時間花在什么地方

你總是希望程序能夠按照你的意愿去工作，也希望它能在正確的時間做正確的事情，甚至希望它是最優(yōu)的，盡可能在程序運行的周期內(nèi)，消耗的90%以上的資源都是在做需要做的事情，而不是簡單的等待。也許，下面的這個指令可以幫上你的忙:

root@dev:~# strace -c -p 11084

Process 11084 attached - interrupt to quit

Process 11084 detached

% time seconds usecs/call calls errors syscall

94.59 0.001014 48 21 select

2.89 0.000031 1 21 getppid

2.52 0.000027 1 21 time

100.00 0.001072 63 total

root@dev:~#

如果你是跟蹤的后臺守護進程，可以通過上面的指令跟蹤一段時間，然后按ctrl+c退出，strace會根據(jù)獲得信息描述出上面的結(jié)果。

上述的例子說明當(dāng)前進程(postmaster)最要的時間花在等待select()函數(shù)上，在每調(diào)用一次select函數(shù)后，它分別調(diào)用getpid函數(shù)和time函數(shù). 如果是非后臺守護進程，那strace可以跟蹤進程的開始至結(jié)束，類似下面這樣：

root@dev:~# strace -c >/dev/null ls

% time seconds usecs/call calls errors syscall

23.62 0.000205 103 2 getdents64

18.78 0.000163 15 11 1 open

15.09 0.000131 19 7 read

12.79 0.000111 7 16 old_mmap

7.03 0.000061 6 11 close

4.84 0.000042 11 4 munmap

4.84 0.000042 11 4 mmap2

4.03 0.000035 6 6 6 access

3.80 0.000033 3 11 fstat64

1.38 0.000012 3 4 brk

0.92 0.000008 3 3 3 ioctl

0.69 0.000006 6 1 uname

0.58 0.000005 5 1 set_thread_area

0.35 0.000003 3 1 write

0.35 0.000003 3 1 rt_sigaction

0.35 0.000003 3 1 fcntl64

0.23 0.000002 2 1 getrlimit

0.23 0.000002 2 1 set_tid_address

0.12 0.000001 1 1 rt_sigprocmask

100.00 0.000868 87 10 total

ls程序大部分時間花在讀取目錄條目上面。

為什么我不能連接到服務(wù)器？

調(diào)試進程不能連接到服務(wù)器是一個痛苦的事情，因為原因很多，比如DNS失效啦，連接被掛起啦，服務(wù)器返回異常數(shù)據(jù)啦，服務(wù)器本身異常啦，等等。一般網(wǎng)絡(luò)調(diào)試方面，很多人會想到另外一個非常不錯的工具-tcpdump。但它的參數(shù)太多了，而且你要從上百個連接進程中找出其中一個進程為什么不能連接恐怕是一件非常費力的工作。strace 其實也能在這種情景下幫上你的忙，它僅僅輸出與系統(tǒng)調(diào)用相關(guān)的數(shù)據(jù)，從而可以讓我們的注意力更集中。類似下面這樣：

$ strace -e poll,select,connect,recvfrom,sendto nc http://www.news.com 80

sendto(3, "\24\0\0\0\26\0\1\3\255\373NH\0\0\0\0\0\0\0\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20

connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "\213\321\1\0\0\1\0\0\0\0\0\0\3www\4news\3com\0\0\34\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "\213\321\201\200\0\1\0\1\0\1\0\0\3www\4news\3com\0\0\34\0\1\300\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, [16]) = 153

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "k\374\1\0\0\1\0\0\0\0\0\0\3www\4news\3com\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "k\374\201\200\0\1\0\2\0\0\0\0\3www\4news\3com\0\0\1\0\1\300\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, [16]) = 106

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "\\2\1\0\0\1\0\0\0\0\0\0\3www\4news\3com\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "\\2\201\200\0\1\0\2\0\0\0\0\3www\4news\3com\0\0\1\0\1\300\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, [16]) = 106

connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("216.239.122.102")}, 16) = -1 EINPROGRESS (Operation now in progress)

select(4, NULL, [3], NULL, NULL) = 1 (out [3])

那么，上述的輸出，說明進程發(fā)生了什么呢？

注意到這個進程嘗試連接/var/run/nscd/socket連接了嗎？這意味著nc程序首先會去連接NSCD- Name Service Cache Daemon - 它通常用于設(shè)置和NIS，YP，LDAP或者類似目錄協(xié)議相關(guān)的域名查詢配置上。在上述例子中，連接失敗了。

接下來進程開始連接到DNS，這點可以從sin_port=htons(53)輸出可以看出。你可以看到，它接著做了一個sendto()的調(diào)用，發(fā)出了一個包含http://www.news.com信息的DNS包。然后讀取返回的包數(shù)據(jù)，不知什么原因，它做了三次這樣的嘗試。一個可能的原因是http://www.news.com是一條CNAME記錄。多次請求可能是nc程序處理的一種方式。

最后，它總算是發(fā)起了connect()操作，注意這個操作的返回結(jié)果是EINPROGRESS，這意味著這個連接是非阻塞式的，nc希望繼續(xù)，于是它調(diào)用了select()。

增加read,write調(diào)用到strace跟蹤的系統(tǒng)調(diào)用列表里，可以讓我們看到下面的一些結(jié)果：

read(0, "test\n", 1024) = 5

write(3, "test\n", 5) = 5

poll([{fd=3, events=POLLIN, revents=POLLIN}, {fd=0, events=POLLIN}], 2, -1) = 1

read(3, "

上述表示它從讀取”test” + 標(biāo)準(zhǔn)輸入的一行信息，然后寫入網(wǎng)絡(luò)連接，接著調(diào)用poll來等待回應(yīng)，然后讀取網(wǎng)絡(luò)反饋的信息并寫到標(biāo)準(zhǔn)輸出。