跟蹤系統呼叫 strace
linux命令—— strace命令（跟蹤程序中的系統呼叫）
轉：https://www.cnblogs.com/kongzhongqijing/articles/4913192.html strace -e futex -o xxx.log /bin/lsstrace常用來跟蹤程序執行時的系統呼叫和所接收的訊號。 在Linux世界，程序不能直接訪問硬體裝置，當程序需要訪問硬體裝置(比如讀取磁碟檔案，接收網路資料等等)時，必須由使用者態模式切換至核心態模式，通過系統呼叫訪問硬體裝置。strace可以跟蹤到一個程序產生的系統呼叫,包括引數，返回值，執行消耗的時間。
1、引數
每一行都是一條系統呼叫，等號左邊是系統呼叫的函式名及其引數，右邊是該呼叫的返回值。 strace 顯示這些呼叫的引數並返回符號形式的值。strace 從核心接收資訊，而且不需要以任何特殊的方式來構建核心。
$strace cat /dev/null
execve("/bin/cat", ["cat", "/dev/null"], [/* 22 vars */]) = 0
brk(0) = 0xab1000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f29379a7000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
...
引數含義
-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執行被跟蹤的命令
2、使用例項
例項1：跟蹤可執行程式
strace -f -F -o ~/straceout.txt myserver
-f -F選項告訴strace同時跟蹤fork和vfork出來的程序，-o選項把所有strace輸出寫到~/straceout.txt裡 面，myserver是要啟動和除錯的程式。
例項2：跟蹤服務程式
strace -o output.txt -T -tt -e trace=all -p 28979
跟蹤28979程序的所有系統呼叫（-e trace=all），並統計系統呼叫的花費時間，以及開始時間（並以視覺化的時分秒格式顯示），最後將記錄結果存在output.txt檔案裡面。
例項3：轉自手把手教你用Strace診斷問題
早些年，如果你知道有個 strace 命令，就很牛了，而現在大家基本都知道 strace 了，如果你遇到效能問題求助別人，十有八九會建議你用 strace 掛上去看看，不過當你掛上去了，看著滿屏翻滾的字元，卻十有八九看不出個所以然。本文通過一個簡單的案例，向你展示一下在用 strace 診斷問題時的一些套路。
如下真實案例，如有雷同，實屬必然！讓我們看一臺高負載伺服器的 top 結果：
top
技巧：執行 top 時，按「1」開啟 CPU 列表，按「shift+p」以 CPU 排序。
在本例中大家很容易發現 CPU 主要是被若干個 PHP 程序佔用了，同時 PHP 程序佔用的比較多的記憶體，不過系統記憶體尚有結餘，SWAP 也不嚴重，這並不是問題主因。
不過在 CPU 列表中能看到 CPU 主要消耗在核心態「sy」，而不是使用者態「us」，和我們的經驗不符。Linux 作業系統有很多用來跟蹤程式行為的工具，核心態的函式呼叫跟蹤用「strace」，使用者態的函式呼叫跟蹤用「ltrace」，所以這裡我們應該用「strace」：
shell> strace -p <PID>
不過如果直接用 strace 跟蹤某個程序的話，那麼等待你的往往是滿屏翻滾的字元，想從這裡看出問題的癥結並不是一件容易的事情，好在 strace 可以按操作彙總時間：
shell> strace -cp <PID>
通過「c」選項用來彙總各個操作的總耗時，執行後的結果大概如下圖所示：
strace -cp
很明顯，我們能看到 CPU 主要被 clone 操作消耗了，還可以單獨跟蹤一下 clone：
shell> strace -T -e clone -p <PID>
通過「T」選項可以獲取操作實際消耗的時間，通過「e」選項可以跟蹤某個操作：
strace -T -e clone -p
很明顯，一個 clone 操作需要幾百毫秒，至於 clone 的含義，參考 man 文件：
clone() creates a new process, in a manner similar to fork(2). It is actually a library function layered on top of the underlying clone() system call, hereinafterreferred to as sys_clone. A description of sys_clone is given towards the end of this page.
Unlike fork(2), these calls allow the child process to share parts of its execution context with the calling process, such as the memory space, the table of filedescriptors, and the table of signal handlers. (Note that on this manual page, “calling process” normally corresponds to “parent process”. But see the description ofCLONE_PARENT below.)
簡單來說，就是建立一個新程序。那麼在 PHP 裡什麼時候會出現此類系統呼叫呢？查詢業務程式碼看到了exec函式，通過如下命令驗證它確實會導致 clone 系統呼叫：
shell> strace -eclone php -r 'exec("ls");'
最後再考大家一個題：如果我們用 strace 跟蹤一個程序，輸出結果很少，是不是說明程序很空閒？其實試試 ltrace，可能會發現別有洞天。記住有核心態和使用者態之分。
例項4 ：轉自 http://huoding.com/2013/10/06/288
伺服器卻頻現高負載，Nginx出現錯誤日誌：
- connect() failed (110: Connection timed out) while connecting to upstream
- connect() failed (111: Connection refused) while connecting to upstream
看上去是Upstream出了問題，在本例中Upstream就是PHP（版本：5.2.5）。可惜監控不完善，我搞不清楚到底是哪出了問題，無奈之下只好不斷重啟PHP來緩解故障。
如果每次都手動重啟服務無疑是個苦差事，幸運的是可以通過CRON設定每分鐘執行：
#/bin/bash
LOAD=$(awk '{print $1}' /proc/loadavg)
if [ $(echo "$LOAD > 100" | bc) = 1 ]; then
/etc/init.d/php-fpm restart
fi
可惜這只是一個權宜之計，要想徹底解決就必須找出故障的真正原因是什麼。
閒言碎語不要講，輪到Strace出場了，統計一下各個系統呼叫的耗時情況：
shell> strace -c -p $(pgrep -n php-cgi) % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 30.53 0.023554 132 179 brk 14.71 0.011350 140 81 mlock 12.70 0.009798 15 658 16 recvfrom 8.96 0.006910 7 927 read 6.61 0.005097 43 119 accept 5.57 0.004294 4 977 poll 3.13 0.002415 7 359 write 2.82 0.002177 7 311 sendto 2.64 0.002033 2 1201 1 stat 2.27 0.001750 1 2312 gettimeofday 2.11 0.001626 1 1428 rt_sigaction 1.55 0.001199 2 730 fstat 1.29 0.000998 10 100 100 connect 1.03 0.000792 4 178 shutdown 1.00 0.000773 2 492 open 0.93 0.000720 1 711 close 0.49 0.000381 2 238 chdir 0.35 0.000271 3 87 select 0.29 0.000224 1 357 setitimer 0.21 0.000159 2 81 munlock 0.17 0.000133 2 88 getsockopt 0.14 0.000110 1 149 lseek 0.14 0.000106 1 121 mmap 0.11 0.000086 1 121 munmap 0.09 0.000072 0 238 rt_sigprocmask 0.08 0.000063 4 17 lstat 0.07 0.000054 0 313 uname 0.00 0.000000 0 15 1 access 0.00 0.000000 0 100 socket 0.00 0.000000 0 101 setsockopt 0.00 0.000000 0 277 fcntl ------ ----------- ----------- --------- --------- ---------------- 100.00 0.077145 13066 118 total
看上去「brk」非常可疑，它竟然耗費了三成的時間，保險起見，單獨確認一下：
shell> strace -T -e brk -p $(pgrep -n php-cgi) brk(0x1f18000) = 0x1f18000 <0.024025> brk(0x1f58000) = 0x1f58000 <0.015503> brk(0x1f98000) = 0x1f98000 <0.013037> brk(0x1fd8000) = 0x1fd8000 <0.000056> brk(0x2018000) = 0x2018000 <0.012635>
說明：在Strace中和操作花費時間相關的選項有兩個，分別是「-r」和「-T」，它們的差別是「-r」表示相對時間，而「-T」表示絕對時間。簡單統計可以用「-r」，但是需要注意的是在多工背景下，CPU隨時可能會被切換出去做別的事情，所以相對時間不一定準確，此時最好使用「-T」，在行尾可以看到操作時間，可以發現確實很慢。
在繼續定位故障原因前，我們先通過「man brk」來查詢一下它的含義：
brk() sets the end of the data segment to the value specified by end_data_segment, when that value is reasonable, the system does have enough memory and the process does not exceed its max data size (see setrlimit(2)).
簡單點說就是記憶體不夠用時通過它來申請新記憶體（data segment），可是為什麼呢？
shell> strace -T -p $(pgrep -n php-cgi) 2>&1 | grep -B 10 brk
stat("/path/to/script.php", {...}) = 0 <0.000064>
brk(0x1d9a000) = 0x1d9a000 <0.000067>
brk(0x1dda000) = 0x1dda000 <0.001134>
brk(0x1e1a000) = 0x1e1a000 <0.000065>
brk(0x1e5a000) = 0x1e5a000 <0.012396>
brk(0x1e9a000) = 0x1e9a000 <0.000092>
通過「grep」我們很方便就能獲取相關的上下文，反覆執行幾次，發現每當請求某些PHP指令碼時，就會出現若干條耗時的「brk」，而且這些PHP指令碼有一個共同的特點，就是非常大，甚至有幾百K，為何會出現這麼大的PHP指令碼？實際上是程式設計師為了避免資料庫操作，把非常龐大的陣列變數通過「var_export」持久化到PHP檔案中，然後在程式中通過「include」來獲取相應的變數，因為變數太大，所以PHP不得不頻繁執行「brk」，不幸的是在本例的環境中，此操作比較慢，從而導致處理請求的時間過長，加之PHP程序數有限，於是乎在Nginx上造成請求擁堵，最終導致高負載故障。
下面需要驗證一下推斷似乎否正確，首先查詢一下有哪些地方涉及問題指令碼：
shell> find /path -name "*.php" | xargs grep "script.php"
直接把它們都禁用了，看看伺服器是否能緩過來，或許大家覺得這太魯蒙了，但是特殊情況必須做出特殊的決定，不能像個娘們兒似的優柔寡斷，沒過多久，伺服器負載恢復正常，接著再統計一下系統呼叫的耗時：
shell> strace -c -p $(pgrep -n php-cgi) % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 24.50 0.001521 11 138 2 recvfrom 16.11 0.001000 33 30 accept 7.86 0.000488 8 59 sendto 7.35 0.000456 1 360 rt_sigaction 6.73 0.000418 2 198 poll 5.72 0.000355 1 285 stat 4.54 0.000282 0 573 gettimeofday 4.41 0.000274 7 42 shutdown 4.40 0.000273 2 137 open 3.72 0.000231 1 197 fstat 2.93 0.000182 1 187 close 2.56 0.000159 2 90 setitimer 2.13 0.000132 1 244 read 1.71 0.000106 4 30 munmap 1.16 0.000072 1 60 chdir 1.13 0.000070 4 18 setsockopt 1.05 0.000065 1 100 write 1.05 0.000065 1 64 lseek 0.95 0.000059 1 75 uname 0.00 0.000000 0 30 mmap 0.00 0.000000 0 60 rt_sigprocmask 0.00 0.000000 0 3 2 access 0.00 0.000000 0 9 select 0.00 0.000000 0 20 socket 0.00 0.000000 0 20 20 connect 0.00 0.000000 0 18 getsockopt 0.00 0.000000 0 54 fcntl 0.00 0.000000 0 9 mlock 0.00 0.000000 0 9 munlock ------ ----------- ----------- --------- --------- ---------------- 100.00 0.006208 3119 24 total
顯而易見，「brk」已經不見了，取而代之的是「recvfrom」和「accept」，不過這些操作本來就是很耗時的，所以可以定位「brk」就是故障的原因。
有時候，不小心知道了一些事，才發現自己所在乎的事是那麼可笑。