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

時間 2020-01-27

標籤使用 strace 工具故障排查簡單方法简体版

原文原文鏈接

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

可是它還能夠作更多的事情：服務器

它能夠基於系統調用或者系統調用組來過濾網絡

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

它能夠追蹤發送給進程的信號(signal)tcp

它能夠經過進程id(pid)號加入到任意正在運行的進程上ide

如何使用函數

這裏只是簡單的描述strace如何使用，並不打算對此作深刻分析工具

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

有的時候，你發發現，不管你如何修改配置文件，應用程序並無按照你的思路去運行，這是什麼緣由？一個淺顯但容易忽視的考慮是，應用程序啓動時讀取了你認爲要讀取的配置文件了嗎？看下面的例子：ui

$ 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 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_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()的調用，發出了一個包含www.news.com信息的DNS包。而後讀取返回的包數據，不知什麼緣由，它作了三次這樣的嘗試。一個可能的緣由是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來等待迴應，而後讀取網絡反饋的信息並寫到標準輸出。