strace命令是一個集診斷、除錯、統計與一體的工具，我們可以使用strace對應用的系統呼叫和訊號傳遞的跟蹤結果來對應用進行分析，以達到解決問題或者是瞭解應用工作過程的目的。當然strace與專業的除錯工具比如說gdb之類的是沒法相比的，因為它不是一個專業的偵錯程式。
strace的最簡單的用法就是執行一個指定的命令，在指定的命令結束之後它也就退出了。在命令執行的過程中，strace會記錄和解析命令程式的所有系統呼叫以及這個程式所接收到的所有的訊號值。
語法
strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ...
[ -ofile ] [-ppid ] ... [ -sstrsize ] [ -uusername ]
[ -Evar=val ] ... [ -Evar ]...
[ command [ arg ... ] ]
strace -c [ -eexpr ] ... [ -Ooverhead ] [ -Ssortby ]
[ command [ arg... ] ]
選項
-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執行被跟蹤的命令
例項
追蹤系統呼叫
現在我們做一個很簡單的程式來演示strace的基本用法。這個程式的C語言程式碼如下：
# filename test.c
#include <stdio.h>
int main()
{
int a;
scanf("%d", &a);
printf("%09d\n", a);
return 0;
}
然後我們用gcc -o test test.c編譯一下，得到一個可執行的檔案test。然後用strace呼叫執行：
strace ./test
執行期間會要求你輸入一個整數，我們輸入99，最後得到如下的結果：
// 直接執行test的結果
oracle@orainst[orcl]:~ $./test
// 執行的結果
99
000000099
// 通過strace執行test的結果
oracle@orainst[orcl]:~ $strace ./test
// strace的trace結果
execve("./test", ["./test"], [/* 41 vars */]) = 0
uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0
brk(0) = 0x8078000
fstat64(3, {st_mode=S_IFREG|0644, st_size=65900, ...}) = 0
old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000
close(3) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200X\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000
old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xa02000
old_mmap(0xb34000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0xb34000
old_mmap(0xb37000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb37000
close(3) = 0
set_thread_area({entry_number:-1 -> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
munmap(0xbf5ef000, 65900) = 0
fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000
read(0, 99
"99\n", 1024) = 3
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5fe000
write(1, "000000099\n", 10000000099
) = 10
munmap(0xbf5fe000, 4096) = 0
exit_group(0) = ?
從trace結構可以看到，系統首先呼叫execve開始一個新的進行，接著進行些環境的初始化操作，最後停頓在”read(0,”上面，這也就是執行到了我們的scanf函式，等待我們輸入數字呢，在輸入完99之後，在呼叫write函式將格式化後的數值”000000099″輸出到螢幕，最後呼叫exit_group退出進行，完成整個程式的執行過程。
跟蹤訊號傳遞
我們還是使用上面的那個test程式，來觀察程式接收訊號的情況。還是先strace ./test，等到等待輸入的畫面的時候不要輸入任何東西，然後開啟另外一個視窗，輸入如下的命令
killall test
這時候就能看到我們的程式推出了，最後的trace結果如下：
oracle@orainst[orcl]:~
$strace ./test
execve("./test", ["./test"], [/* 41 vars */]) = 0
uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0
brk(0) = 0x9ae2000
old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000
close(3) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200X\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000
old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x2e9000
old_mmap(0x41b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0x41b000
old_mmap(0x41e000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x41e000
close(3) = 0
set_thread_area({entry_number:-1 -> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
munmap(0xbf5ef000, 65900) = 0
fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000
read(0, 0xbf5ff000, 1024) = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
+++ killed by SIGTERM +++
trace中很清楚的告訴你test程式”+++ killed by SIGTERM +++”。
系統呼叫統計
strace不光能追蹤系統呼叫，通過使用引數-c，它還能將程式所有的系統呼叫做一個統計分析給你，下面就來看看strace的統計，這次我們執行帶-c引數的strace：
strace -c ./test
最後能得到這樣的trace結果：
oracle@orainst[orcl]:~ $strace -c ./test
execve("./test", ["./test"], [/* 41 vars */]) = 0
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
45.90 0.000140 5 27 25 open
34.43 0.000105 4 24 21 stat64
7.54 0.000023 5 5 old_mmap
2.62 0.000008 8 1 munmap
1.97 0.000006 6 1 uname
1.97 0.000006 2 3 fstat64
1.64 0.000005 3 2 1 read
1.31 0.000004 2 2 close
0.98 0.000003 3 1 brk
0.98 0.000003 3 1 mmap2
0.66 0.000002 2 1 set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00 0.000305 68 47 total
這裡很清楚的告訴你呼叫了那些系統函式，呼叫次數多少，消耗了多少時間等等這些資訊，這個對我們分析一個程式來說是非常有用的。
常用引數說明
除了-c引數之外，strace還提供了其他有用的引數給我們，讓我們能很方便的得到自己想要的資訊，下面就對那些常用的引數一一做個介紹。
重定向輸出
引數-o用在將strace的結果輸出到檔案中，如果不指定-o引數的話，預設的輸出裝置是STDERR，也就是說使用”-o filename”和” 2>filename”的結果是一樣的。
# 這兩個命令都是將strace結果輸出到檔案test.txt中 strace -c -o test.txt ./test strace -c ./test 2>test.txt
對系統呼叫進行計時
strace可以使用引數-T將每個系統呼叫所花費的時間列印出來，每個呼叫的時間花銷現在在呼叫行最右邊的尖括號裡面。
oracle@orainst[orcl]:~
$strace -T ./test
// 這裡只摘錄部分結果
read(0, 1
"1\n", 1024) = 2 <2.673455>
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 <0.000014>
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5fe000 <0.000017>
write(1, "000000001\n", 10000000001
) = 10 <0.000016>
munmap(0xbf5fe000, 4096) = 0 <0.000020>
exit_group(0) = ?
系統呼叫的時間
這是一個很有用的功能，strace會將每次系統呼叫的發生時間記錄下來，只要使用-t/tt/ttt三個引數就可以看到效果了，具體的例子可以自己去嘗試。
| 引數名 | 輸出樣式 | 說明 |
|---|---|---|
| -t | 10:33:04 exit_group(0) | 輸出結果精確到秒 |
| -tt | 10:33:48.159682 exit_group(0) | 輸出結果精確到微妙 |
| -ttt | 1262169244.788478 exit_group(0) | 精確到微妙，而且時間表示為unix時間戳 |
截斷輸出
-s引數用於指定trace結果的每一行輸出的字串的長度，下面看看test程式中-s引數對結果有什麼影響，現指定-s為20，然後在read的是是很我們輸入一個超過20個字元的數字串
strace -s 20 ./test read(0, 2222222222222222222222222 // 我們輸入的2一共有25個 "22222222222222222222"..., 1024) = 26 // 而我們看到的結果中2只有20個
trace一個現有的程式
strace不光能自己初始化一個程式進行trace，還能追蹤現有的程式，引數-p就是取這個作用的，用法也很簡單，具體如下。
strace -p pid
綜合例子
說了那麼多的功能和引數，現在我們來一個實用點的，就是研究下Oracle的lgwr程式，看看這個程式是不是像文件所說的那樣沒3s鍾寫一次log檔案，考慮到lgwr寫日誌的觸發條件比較多，我們需要找一個空閒的Oracle例項做這個實驗。
我們先要得到lgwr程式的pid，執行下面的命令
ps -ef|grep lgwr
oracle 5912 1 0 Nov12 ? 00:14:56 ora_lgwr_orcl
得到lgwr的pid是5912，現在啟動strace，然後將trace的幾個輸出到lgwr.txt檔案中，執行下面的命令
strace -tt -s 10 -o lgwr.txt -p 5912
過一會之後停止strace，然後檢視結果。由於輸出的結果比較多，為了方便我們只看Oracle寫入log檔案時用的pwrite函式的呼叫
grep pwrite\(20 lgwr.txt
等等，為什麼grep的時候用的是”pwrite(2″呢？，因為我知道我這個機器開啟的當前的log檔案的控制程式碼編號都是2開始的。具體查詢方法是先使用下面的語句找出當前活動的日誌檔案都有哪些：
select member, v$log.status from v$log, v$logfile where v$log.group#=v$logfile.group#;
得到
MEMBER STATUS -------------------------------------------------- ---------------- /db/databases/orcl/redo-01-a/redo-t01-g03-m1.log INACTIVE /db/databases/orcl/redo-03-a/redo-t01-g03-m2.log INACTIVE /db/databases/orcl/redo-02-a/redo-t01-g02-m1.log CURRENT /db/databases/orcl/redo-04-a/redo-t01-g02-m2.log CURRENT /db/databases/orcl/redo-01-a/redo-t01-g01-m1.log INACTIVE /db/databases/orcl/redo-03-a/redo-t01-g01-m2.log INACTIVE /db/databases/orcl/redo-02-a/redo-t01-g04-m1.log INACTIVE /db/databases/orcl/redo-04-a/redo-t01-g04-m2.log INACTIVE
然後到/proc中去找開啟檔案的控制程式碼：
ll /proc/.5912/fd/
得到
lrwx------ 1 oracle dba 64 Dec 30 10:55 18 -> /db/databases/orcl/redo-01-a/redo-t01-g01-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 19 -> /db/databases/orcl/redo-03-a/redo-t01-g01-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 20 -> /db/databases/orcl/redo-02-a/redo-t01-g02-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 21 -> /db/databases/orcl/redo-04-a/redo-t01-g02-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 22 -> /db/databases/orcl/redo-01-a/redo-t01-g03-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 23 -> /db/databases/orcl/redo-03-a/redo-t01-g03-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 24 -> /db/databases/orcl/redo-02-a/redo-t01-g04-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 25 -> /db/databases/orcl/redo-04-a/redo-t01-g04-m2.log
現在能看到我機器當前日誌檔案的控制程式碼分別是20和21。
現在我們得到如下結果
11:13:55.603245 pwrite(20, "\1\"\0\0J!"..., 1536, 4363264) = 1536 11:13:55.603569 pwrite(21, "\1\"\0\0J!"..., 1536, 4363264) = 1536 11:13:55.606888 pwrite(20, "\1\"\0\0M!"..., 1536, 4364800) = 1536 11:13:55.607172 pwrite(21, "\1\"\0\0M!"..., 1536, 4364800) = 1536 11:13:55.607934 pwrite(20, "\1\"\0\0P!"..., 1536, 4366336) = 1536 11:13:55.608199 pwrite(21, "\1\"\0\0P!"..., 1536, 4366336) = 1536 11:13:55.610260 pwrite(20, "\1\"\0\0S!"..., 1536, 4367872) = 1536 11:13:55.610530 pwrite(21, "\1\"\0\0S!"..., 1536, 4367872) = 1536 11:14:00.602446 pwrite(20, "\1\"\0\0V!"..., 1536, 4369408) = 1536 11:14:00.602750 pwrite(21, "\1\"\0\0V!"..., 1536, 4369408) = 1536 11:14:00.606386 pwrite(20, "\1\"\0\0Y!"..., 1536, 4370944) = 1536 11:14:00.606676 pwrite(21, "\1\"\0\0Y!"..., 1536, 4370944) = 1536 11:14:00.607900 pwrite(20, "\1\"\0\0\\"..., 1024, 4372480) = 1024 11:14:00.608161 pwrite(21, "\1\"\0\0\\"..., 1024, 4372480) = 1024 11:14:00.608816 pwrite(20, "\1\"\0\0^!"..., 1024, 4373504) = 1024 11:14:00.609071 pwrite(21, "\1\"\0\0^!"..., 1024, 4373504) = 1024 11:14:00.611142 pwrite(20, "\1\"\0\0`!"..., 1536, 4374528) = 1536 11:14:00.611454 pwrite(21, "\1\"\0\0`!"..., 1536, 4374528) = 1536 11:14:05.602804 pwrite(20, "\1\"\0\0c!"..., 1024, 4376064) = 1024 11:14:05.603119 pwrite(21, "\1\"\0\0c!"..., 1024, 4376064) = 1024 11:14:05.607731 pwrite(20, "\1\"\0\0e!"..., 1024, 4377088) = 1024 11:14:05.608020 pwrite(21, "\1\"\0\0e!"..., 1024, 4377088) = 1024 11:14:05.608690 pwrite(20, "\1\"\0\0g!"..., 1024, 4378112) = 1024 11:14:05.608962 pwrite(21, "\1\"\0\0g!"..., 1024, 4378112) = 1024 11:14:05.611022 pwrite(20, "\1\"\0\0i!"..., 1536, 4379136) = 1536 11:14:05.611283 pwrite(21, "\1\"\0\0i!"..., 1536, 4379136) = 1536