如何使用strace工具排查故障？

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

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

它可以基于系統調用或者系統調用組來過濾

它可以通過計算制定系統調用的次數，花費的時間以及成功和失敗的次數來描述系統調用的使用

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

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

如何使用

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

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

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

$ 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/下讀取。

上述的輸出會很多，我們甚至可以通過參數來指定只追蹤我們關心的系統調用，類似如下：

$ 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

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

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

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

檢查open()和access()系統調用的輸出結果，看看是什么原因

進程此刻正在做什么？

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

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

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

程序的時間花在什么地方

你總是希望程序能夠按照你的意愿去工作，也希望它能在正確的時間做正確的事情，甚至希望它是最優的，盡可能在程序運行的周期內，消耗的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會根據獲得信息描述出上面的結果。

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

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程序大部分時間花在讀取目錄條目上面。

為什么我不能連接到服務器？

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

$ 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])

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

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

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

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

增加read,write調用到strace跟蹤的系統調用列表里，可以讓我們看到下面的一些結果：

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” + 標準輸入的一行信息，然后寫入網絡連接，接著調用poll來等待回應，然后讀取網絡反饋的信息并寫到標準輸出。