2017，科學使用strace神器（附代碼，舉栗子）

　　我感到驚訝，都2017年了，幾乎沒有人知道他們可以使用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，通路2>＆1 | grep your-filename
      

查找失敗的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 /調用調用錯誤syscall
------ ----------- ----------- --------- --------- ---- ------------
 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 /調用調用錯誤syscall
------ ----------- ----------- --------- --------- ---- ------------
 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關閉
  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 11 rt_sigprocmask
------ ----------- ----------- --------- --------- ---- ------------
100.00 0.000868 87 10總計
      

幾乎所有的期望，它花費了大部分時間在兩次調用讀取目錄項（隻有兩個，因為它是在一個小的目錄上運作）。

5）為什麼****不能連接配接到該伺服器？

調試為什麼一些程序不連接配接到遠端伺服器可能是非常令人沮喪。DNS可能會失敗，連接配接可能挂起，伺服器可能會發送意外回來等。你可以使用tcpdump分析很多，這也是一個非常好的工具，但很多時間strace會給你較少的顫振，隻是因為它隻會傳回與“你的”程序生成的系統調用相關的資料。如果你想知道連接配接到同一個資料庫伺服器的幾百個運作程序中的哪一個（例如，選擇與tcpdump的正确連接配接是一個噩夢），strace使生活更容易。這是一個“nc”跟蹤的示例，連接配接到www.news.com在端口80上沒有任何問題：

$ 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（）”調用，發送一個DNS資料包，包含www.news .com它讀回一個資料包，無論什麼原因，它嘗試三次，最後一個有一個稍微不同的請求。我最好猜猜為什麼在這種情況下，www.news.com是一個CNAME（一個“别名”），并且多個請求可能隻是一個nc處理的工件，然後最終，它最終發出一個connect（）到它找到的IP。注意它傳回EINPROGRESS。這意味着連接配接是非阻塞的 - nc想要繼續處理。然後調用select（），當連接配接成功時，它成功。嘗試添加“讀”和“寫”到給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，“\” -  // IETF //“...，1024）= 216
write（1，“\” -  // IETF //“...，216）= 216
      

這顯示它從标準讀取“test”+ linefeed，并将其寫回網絡連接配接，然後調用poll（）等待答複，從網絡連接配接讀取答複并将其寫入标準輸出。一切似乎工作正常。

參數：

-c 統計每一系統調用的所執行的時間,次數和出錯的次數等. 
-d 輸出strace關于标準錯誤的調試資訊. 
-f 跟蹤由fork調用所産生的子程序. 
-ff 如果提供-o filename,則所有程序的跟蹤結果輸出到相應的filename.pid中,pid是各程序的程序号. 
-F 嘗試跟蹤vfork調用.在-f時,vfork不被跟蹤. 
-h 輸出簡要的幫助資訊. 
-i 輸出系統調用的入口指針. 
-q 禁止輸出關于脫離的消息. 
-r 列印出相對時間關于,,每一個系統調用. 
-t 在輸出中的每一行前加上時間資訊. 
-tt 在輸出中的每一行前加上時間資訊,微秒級. 
-ttt 微秒級輸出,以秒了表示時間. 
-T 顯示每一調用所耗的時間. 
-v 輸出所有的系統調用.一些調用關于環境變量,狀态,輸入輸出等調用由于使用頻繁,預設不輸出. 
-V 輸出strace的版本資訊. 
-x 以十六進制形式輸出非标準字元串 
-xx 所有字元串以十六進制形式輸出. 
-a column 
設定傳回值的輸出位置.預設 為40. 
-e expr 
指定一個表達式,用來控制如何跟蹤.格式如下: 
[qualifier=][!]value1[,value2]... 
qualifier隻能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用來限定的符号或數字.預設的 qualifier是 trace.感歎号是否定符号.例如: 
-eopen等價于 -e trace=open,表示隻跟蹤open調用.而-etrace!=open表示跟蹤除了open以外的其他調用.有兩個特殊的符号 all 和 none. 
注意有些shell使用!來執行曆史記錄裡的指令,是以要使用\\. 
-e trace=set 
隻跟蹤指定的系統 調用.例如:-e trace=open,close,rean,write表示隻跟蹤這四個系統調用.預設的為set=all. 
-e trace=file 
隻跟蹤有關檔案操作的系統調用. 
-e trace=process 
隻跟蹤有關程序控制的系統調用. 
-e trace=network 
跟蹤與網絡有關的所有系統調用. 
-e strace=signal 
跟蹤所有與系統信号有關的 系統調用 
-e trace=ipc 
跟蹤所有與程序通訊有關的系統調用 
-e abbrev=set 
設定 strace輸出的系統調用的結果集.-v 等與 abbrev=none.預設為abbrev=all. 
-e raw=set 
将指 定的系統調用的參數以十六進制顯示. 
-e signal=set 
指定跟蹤的系統信号.預設為all.如 signal=!SIGIO(或者signal=!io),表示不跟蹤SIGIO信号. 
-e read=set 
輸出從指定檔案中讀出 的資料.例如: 
-e read=3,5 
-e write=set 
輸出寫入到指定檔案中的資料. 
-o filename 
将strace的輸出寫入檔案filename 
-p pid 
跟蹤指定的程序pid. 
-s strsize 
指定輸出的字元串的最大長度.預設為32.檔案名一直全部輸出. 
-u username 
以username 的UID和GID執行被跟蹤的指令      

舉個栗子

　　我的php出現了未知問題，error隻有 ：Fatal error: Allowed memory size of * bytes exhausted (tried to allocate * bytes) in.

　　我想知道發現什麼了，然後打開我的mac, show you my code!

killall -9 php-fpm &&  strace -ff -o strace.log  -f -F     -T /usr/local/sinawap/php-fpm/sbin/php-fpm -c  /usr/local/sinawap/php-fpm/lib/php.gray.ini      

　　指令就不用解釋了吧，然後看看驚喜：

　　

　　沒錯，就看byte數最多的， 

less strace.log.5325

　　發現大量的循環調用，

sendto(10, "set icmsa_page_125221_vt_4_14891"..., 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000022>

recvfrom(10, 0x29f8fc0, 8196, 16384, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>

poll([{fd=10, events=POLLIN}], 1, 1500) = 1 ([{fd=10, revents=POLLIN}]) <0.000109>

recvfrom(10, "STORED\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 8 <0.000013>

sendto(10, "get icmsa_page_125221_vt_4_14891"..., 44, MSG_NOSIGNAL, NULL, 0) = 44 <0.000028>

poll([{fd=10, events=POLLIN}], 1, 1500) = 1 ([{fd=10, revents=POLLIN}]) <0.000013>

recvfrom(10, "VALUE icmsa_page_125221_vt_4_148"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 66 <0.000013>

rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000013>

rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x37a0832920}, 8) = 0 <0.000013>

rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000013>

nanosleep({1, 0}, 0x7fffd5683470)           = 0 <1.000160>

sendto(10, "get icmsa_page_125221_vt_4_14891"..., 44, MSG_NOSIGNAL, NULL, 0) = 44 <0.000080>

recvfrom(10, "END\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 5 <0.000103>

sendto(10, "set icmsa_page_125221_vt_4_14891"..., 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000077>

recvfrom(10, "STORED\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 8 <0.000108>

sendto(10, "delete icmsa_page_125221_vt_4_14"..., 47, MSG_NOSIGNAL, NULL, 0) = 47 <0.000026>

　　　仔細對照下php代碼，發現我的PHP yar 的外部類API_Current存在循環調用，導緻記憶體燒盡！！

　　　通過快速定位後，很快fix了這個bug! 

其他想法？

　　如果你以特别創意的方式使用strace，我很樂意聽到你的聲音。哈哈

　　　　

謀膽并重