五種利用strace查故障的簡單方法

我一直驚訝為什麼這麼少的人認識到可以利用strace來乾的事，它一直是我的第一調試工具，因為基本上它存在於我運行過的所有的Linux系統上，它可以用來在很多方面進行故障診斷。

什麼是strace?

strace是一個非常簡單的工具，它可以跟蹤系統調用的執行。最簡單的方式，它可以從頭到尾跟蹤binary的執行，然後以一行文本輸出系統調用的名字，參數和傳回值。

其實它可以做的更多：

• 可以對特定的系統調用或者幾組系統調用進行過濾
• 可以通過統計特定系統調用的調用次數、耗費的時間、成功和失敗的次數來配置(profile)系統調用的使用I
• 跟蹤發送給進程的訊號量
• 可以通過pid附著(attach)到任何啟動並執行進程

如果你使用的是其它Unix系統，它類似於"truss"。其它更複雜的是Sun的Dtrace.

怎麼使用它1) 找出程式在startup的時候讀取的哪個config檔案？

有沒有嘗過解決為什麼某些程式不讀去你認為它應該讀取的config檔案的問題？

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

可以看出這個版本的PHP從/usr/local/lib/php.init讀取config檔案（但是先嘗試/usr/locl/bin)

如果只關心特定的系統調用，有更精緻的方法

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

相同的方法適用於很多其它類似的問題。比如說，安裝了不同版本的library，不確定實際上載入了哪一個版本。

2) 為什麼這個程式沒有開啟我的檔案？

是否曾經碰到過一個程式拒絕讀取它沒有許可權的檔案，但是你發誓原因是它沒有真正找到那個檔案？對程式跟蹤open,access調用，注意失敗的情況

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

3) 某個進程現在在做什麼?

某個進程突然佔用了很多CPU? 或者某個進程看起來像hanging了？

找到對應的pid，然後

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

嗯，這個例子裡面，它在調用futex()的時候掛起了。

"strace -p"非常有用，它減少了很多猜測工作，也不需要重新啟動應用。

4) 是誰偷走了時間？

你可以重新編譯app，開啟profiling，以擷取精確的資訊。但是通常利用strace附著(attach）一個進程以快速地看一下目前時間花費在哪裡非常有用。可以看下是否90%的CPU用在真正的工作，或者用在其它方面了。

root@dev:~# strace -c -p 11084Process 11084 attached - interrupt to quitProcess 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           totalroot@dev:~# 

在執行strace -c -p命令以後，等到你關注的時間到了後，按ctrl-c退出，strace會列出如上的profiling資料。

在這個例子中，程式花了絕大部分時間在等待select()。它在每一個slect()調用這件調用getpid()和time()，這是一種典型的事件迴圈。

你也可以運行"start to finish"，這裡是"ls"

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

正如你的預期，它耗費了大部分時間在兩次調用來讀取目錄條目上（因為運行於一個小的目錄上，所有只有兩次）

5) 為什麼 無法串連到伺服器?

調試進程無法串連到遠端伺服器有時候是件非常頭痛的事。DNS會失敗，connect會掛起，server有可能返回一些意料之外的資料。可以使用tcpdump來分析這些情況，它是一個非常棒的工作。但是有時候你strace可以給你更簡單，耿直借的角度，因為strace只返回你的進程相關的系統調用產生的資料。如果你要從100個串連到統一個資料服務器的運行進程裡面找出一個串連所做的事情，用strace就比tcpdump簡單得多。

下面是跟蹤"nc"串連到www.news.com 80連接埠的例子

$ strace -e poll,select,connect,recvfrom,sendto nc www.news.com 80sendto(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) = 20connect(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) = 0poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1sendto(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) = 30poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1recvfrom(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]) = 153connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, 28) = 0poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1sendto(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) = 30poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1recvfrom(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]) = 106connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39")}, 28) = 0poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1sendto(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) = 30poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1recvfrom(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]) = 106connect(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--the Name Service Cache Daemon--它通常用來基於NIS,YP,LDAP或者類似的目錄協議提供網域名稱查詢。在這裡它失敗了。

然後它串連DNS（DNS是port 53,所以"sin_port=htons(53)")。然後它調用了"sendto（）“,發送包含www.news.com的DNS 包。然後讀迴響應。不知為何，它嘗試了三次，最後一次有細微的卻別，我猜是它www.news.com十一個CNAME（別名），多次請求可能是nc故意的。

最後，它發起一個connect()請求到得到的IP地址，注意到傳回值是EINPROGRESS。這意味這connect是非阻塞的，nc希望繼續處理，然後它調用slect()，串連建立後，select返回成功。

添加"read","write"到過濾系統調用列表中，串連時輸入一個字串，可能會得到如下

Notice the connection attempts to /var/run/nscd/socket? They mean nc first tries to connect to NSCD - the Name Service Cache Daemon - which is usually used in setups that rely on NIS, YP, LDAP or similar directory protocols for name lookups. In this case
the connects fails.

It then moves on to DNS (DNS is port 53, hence the "sin_port=htons(53)" in the following connect. You can see it then does a "sendto()" call, sending a DNS packet that contains www.news.com. It then reads back a packet. For whatever reason it tries three
times, the last with a slightly different request. My best guess why in this case is that www.news.com is a CNAME (an "alias"), and the multiple requests may just be an artifact of how nc deals with that.

Then in the end, it finally issues a connect() to the IP it found. Notice it returns EINPROGRESS. That means the connect was non-blocking - nc wants to go on processing. It then calls select(), which succeeds when the connection was successful.

Try adding "read" and "write" to the list of syscalls given to strace and enter a string when connected, and you'll get something like this:

read(0, "test\\n", 1024)                 = 5write(3, "test\\n", 5)                   = 5poll([{fd=3, events=POLLIN, revents=POLLIN}, {fd=0, events=POLLIN}], 2, -1) = 1read(3, "

這表示從標準輸入讀入"test"+分行符號，並寫到網路連接中，然後調用poll等待響應，讀取響應，寫回標準輸出。

一切看起來都正常工作。

原文地址：http://www.hokstad.com/5-simple-ways-to-troubleshoot-using-strace