我感到驚訝,都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>
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.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,我很樂意聽到你的聲音。哈哈