五種利用strace查故障的簡單方法
來源:http://hokstad.com/5-simple-ways-to-troubleshoot-using-strace
我很驚訝很少有人知道他們可以使用的所有東西。它總是我提出的第一個除錯工具之一,因為它通常在我執行的Linux系統上可用,它可以用來解決各種各樣的問題。
什麼是strace?
Strace是一個跟蹤系統呼叫執行的工具。在其最簡單的形式中,它可以從開始到結束跟蹤二進位制的執行,並輸出一行文字,其中包含系統呼叫的名稱,引數以及在程序生命週期內每個系統呼叫的返回值。但它可以做更多:
- 它可以根據特定的系統呼叫或系統呼叫組進行過濾
- 它可以通過統計使用特定系統呼叫的次數,所花費的時間以及成功和錯誤的數量來分析系統呼叫的使用。
- 它跟蹤傳送到程序的訊號。
- 它可以通過pid附加到任何正在執行的程序。
如果您使用過其他Unix系統,則類似於“truss”。另一個(更全面)是Sun的Dtrace。
如何使用它
這只是表面上的問題,並沒有特別重要的順序:
1)找出程式在啟動時讀取的配置檔案
曾經嘗試弄清楚為什麼有些程式沒有讀取你認為它應該的配置檔案?不得不與自定義編譯或發行版特定的二進位制檔案搏鬥,從您認為“錯誤”的位置讀取其配置?天真的方法:
$ strace php 2>&1 | grep php.ini open(“/ usr / local / bin / php.ini”,O_RDONLY)= -1 ENOENT(沒有這樣的檔案或目錄) 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/lib/php.ini讀取php.ini(但它首先嚐試/ usr / local / bin)。如果我只關心特定的系統呼叫,那麼更復雜的方法:
$ strace -e open php 2>&1 | grep php.ini
open(“/ usr / local / bin / php.ini”,O_RDONLY)= -1 ENOENT(沒有這樣的檔案或目錄)
open(“/ usr / local / lib / php.ini”,O_RDONLY)= 4
同樣的方法適用於許多其他事情。在不同的路徑上安裝了多個版本的庫,並確切地想知道實際載入了哪些庫?等等
2)為什麼這個程式沒有開啟我的檔案?
曾經遇到過一個程式,它默默地拒絕閱讀它沒有讀取許可權的檔案,但你只是在發誓多年後才弄明白,因為你認為它實際上並沒有找到檔案?好吧,你已經知道該怎麼做了:
$ strace -e open,access 2>&1 | grep你的檔名
查詢失敗的open()或access()系統呼叫
3)現在正在做什麼的過程是什麼?
曾經有一個過程突然大量的CPU?或者有一個過程似乎掛?然後你找到了pid,然後這樣做:
root @ dev :〜#strace -p 15427
附加過程15427 - 中斷退出
futex(0x402f4900,FUTEX_WAIT,2,NULL
過程15427分離
啊。所以在這種情況下它掛在對futex()的呼叫中。順便提一下,在這種情況下它並沒有告訴我們這麼多 - 掛在futex上可能是由許多事情引起的(futex是Linux核心中的鎖定機制)。以上是來自正常工作但空閒的Apache子程序,它只是等待遞交請求。但是“strace -p”非常有用,因為它消除了大量的猜測,並且通常無需使用更廣泛的日誌記錄重新啟動應用程式(甚至重新編譯它)。
4)什麼是時間?
您始終可以重新編譯打開了效能分析的應用程式,並獲取準確的資訊,尤其是您自己的程式碼的哪些部分需要花費時間,這應該是您應該做的。但是,能夠快速將strace附加到流程以檢視當前花費的時間,特別是診斷問題,這通常非常有用。這是90%的CPU使用,因為它實際上是在做實際工作,或者是失控的東西。這是你做的:
root @ dev :〜#strace -c -p 11084
附加過程11084 - 中斷退出
過程11084分離
%time秒usecs / call calls錯誤系統呼叫
------ ----------- ----------- --------- --------- ---- ------------
94.59 0.001014 48 21選擇
2.89 0.000031 1 21 getppid
2.52 0.000027 1 21次
------ ----------- ----------- --------- --------- ---- ------------
總計100.00 0.001072 63
root @ dev :〜#
在你使用-c -p開始strace之後,只要你願意,就等待,然後用ctrl-c退出。如上所述,Strace將吐出分析資料。在這種情況下,它是一個空閒的Postgres“postmaster”程序,它花費大部分時間靜靜地等待select()。在這種情況下,它在每個select()呼叫之間呼叫getppid()和time(),這是一個相當標準的事件迴圈。您也可以使用“ls”執行此“開始結束”:
root @ dev :〜#strace -c> / dev / null ls
%time秒usecs / call calls錯誤系統呼叫
------ ----------- ----------- --------- --------- ---- ------------
23.62 0.000205 103 2 getdents64
18.78 0.000163 15 11 1開放
15.09 0.000131 19 7閱讀
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訪問
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寫
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總計
幾乎是你所期望的,它花費大部分時間在兩次呼叫中讀取目錄條目(因為它在一個小目錄上執行,所以只有兩次)。
5)為什麼****無法連線到該伺服器?
除錯某些程序未連線到遠端伺服器的原因可能非常令人沮喪。DNS可能會失敗,連線可能會掛起,伺服器可能會發送意外的東西等等。您可以使用tcpdump來分析其中的很多內容,這也是一個非常好的工具,但很多時候strace會減少聊天,只是因為它只會返回與“你的”程序生成的系統呼叫相關的資料。如果你想弄清楚連線到同一個資料庫伺服器的數百個正在執行的程序之一是什麼(例如,選擇與tcpdump的正確連線是一場噩夢),strace會讓生活變得更加容易。這是在埠80上連線到www.news.com的“nc”痕跡的示例,沒有任何問題:
$ 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(沒有這樣的檔案或目錄)
connect(3,{sa_family = AF_FILE,path =“/ var / run / nscd / socket”},110)= -1 ENOENT(沒有這樣的檔案或目錄)
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(正在進行中的操作)
select(4,NULL,[3],NULL,NULL)= 1(out [3])
那麼這裡發生了什麼?注意連線嘗試/ var / run / nscd / socket?他們的意思是nc首先嚐試連線到NSCD - 名稱服務快取守護程序 - 它通常用於依賴於NIS,YP,LDAP或類似目錄協議進行名稱查詢的設定中。在這種情況下,連線失敗。然後它轉到DNS(DNS是埠53,因此在下面的連線中是“sin_port = htons(53)”。你可以看到它然後執行“sendto()”呼叫,傳送包含www.news的DNS資料包然後它會回讀一個數據包。無論出於何種原因它會嘗試三次,最後一次請求稍有不同。我最好猜測為什麼在這種情況下www.news.com是一個CNAME(一個“別名”),並且多個請求可能只是nc如何處理它的工件。然後最後,它最終向它找到的IP發出connect()。注意它返回EINPROGRESS。這意味著連線是非阻塞的 - nc想要繼續處理。然後呼叫select(),在連線成功時成功。嘗試將“read”和“write”新增到給strace的系統呼叫列表中,並在連線時輸入一個字串,你會得到這樣的結果:
讀(0,“test \\ n”,1024)= 5
寫(3,“test \\ n”,5)= 5
poll([{fd = 3,events = POLLIN,revents = POLLIN},{fd = 0,events = POLLIN}],2,-1)= 1
read(3,“\” - // IETF //“......,1024)= 216
寫(1,“\” - // IETF //“......,216)= 216
這表明它從標準輸入讀取“test”+換行,並將其寫回網路連線,然後呼叫poll()等待回覆,從網路連線讀取回復並將其寫入標準輸出。一切似乎都正常。