Linux 中用 strace 追蹤系統調用和訊號值

文章目錄

• 追蹤系統調用
• 跟蹤訊號傳遞
• 系統調用統計
• 重新導向輸出
• 對系統調用進行計時
• 系統調用的時間
• 截斷輸出
• trace一個現有的進程

原文地址：http://www.dbabeta.com/2009/strace.html

什麼是strace

開啟man strace，我們能看到對strace的最簡潔的介紹就是”strace – trace system calls and signals”。實際上strace是一個集診斷、調試、統計與一體的工具，我們可以使用strace對應用的系統調用和訊號傳遞的跟蹤結果來對應用進行分析，以達到解決問題或者是瞭解應用工作過程的目的。當然strace與專業的調試工具比如說gdb之類的是沒法相比的，因為它不是一個專業的調試器。

strace的最簡單的用法就是執行一個指定的命令，在指定的命令結束之後它也就退出了。在命令執行的過程中，strace會記錄和解析命令進程的所有系統調用以及這個進程所接收到的所有的訊號值。

命令的使用方法如下

1234567

strace [  -dffhiqrtttTvxx  ] [ -acolumn ] [ -eexpr ] ...    [ -ofile ] [-ppid ] ...  [ -sstrsize ] [ -uusername ]    [ -Evar=val ] ...  [ -Evar  ]...    [command[ arg ...  ] ] strace -c  [ -eexpr ] ...  [ -Ooverhead ] [ -Ssortby ]    [command[ arg...  ] ]

 

strace的基本用法追蹤系統調用

現在我們做一個很簡單的程式來示範strace的基本用法。這個程式的C語言代碼如下：

12345678910

# filename test.c#include <stdio.h> int main(){    inta;    scanf("%d", &a);    printf("%09d\n", a);    return0;}

然後我們用gcc -o test test.c編譯一下，得到一個可執行檔檔案test。然後用strace調用執行

1	strace ./test

執行期間會要求你輸入一個整數，我們輸入99，最後得到如下的結果：

12	//直接執行test的結果oracle@orainst[orcl]:~ $./test

123	// 執行的結果99000000099

12	//通過strace執行test的結果oracle@orainst[orcl]:~ $strace ./test

123456789101112131415161718192021222324252627

// strace的trace結果execve("./test", ["./test"], [/* 41 vars */]) = 0uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0brk(0)                                  = 0x8078000fstat64(3, {st_mode=S_IFREG|0644, st_size=65900, ...}) = 0old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000close(3)                                = 0open("/lib/tls/libc.so.6", O_RDONLY)    = 3read(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) = 512fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xa02000old_mmap(0xb34000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0xb34000old_mmap(0xb37000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb37000close(3)                                = 0set_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}) = 0munmap(0xbf5ef000, 65900)               = 0fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000read(0, 99"99\n", 1024)                   = 3fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5fe000write(1," 000000099\n", 10000000099)             = 10munmap(0xbf5fe000, 4096)                = 0exit_group(0)                           = ?

從trace結構可以看到，系統首先調用execve開始一個新的進行，接著進行些環境的初始化操作，最後停頓在”read(0,”上面，這也就是執行到了我們的scanf函數，等待我們輸入數字呢，在輸入完99之後，在調用write函數將格式化後的數值”000000099″輸出到螢幕，最後調用exit_group退出進行，完成整個程式的執行過程。

跟蹤訊號傳遞

我們還是使用上面的那個test程式，來觀察進程接收訊號的情況。還是先strace ./test，等到等待輸入的畫面的時候不要輸入任何東西，然後開啟另外一個視窗，輸入如下的命令

1	killall test

這時候就能看到我們的程式推出了，最後的trace結果如下：

12	oracle@orainst[orcl]:~$strace ./test

1234567891011121314151617181920

execve("./test", ["./test"], [/* 41 vars */]) = 0uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0brk(0)                                  = 0x9ae2000old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000close(3)                                = 0open("/lib/tls/libc.so.6", O_RDONLY)    = 3read(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) = 512fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x2e9000old_mmap(0x41b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0x41b000old_mmap(0x41e000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x41e000close(3)                                = 0set_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}) = 0munmap(0xbf5ef000, 65900)               = 0fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000read(0, 0xbf5ff000, 1024)               = ? ERESTARTSYS (To be restarted)--- SIGTERM (Terminated) @ 0 (0) ---+++ killed by SIGTERM +++

trace中很清楚的告訴你test進程”+++ killed by SIGTERM +++”。

系統調用統計

strace不光能追蹤系統調用，通過使用參數-c，它還能將進程所有的系統調用做一個統計分析給你，下面就來看看strace的統計，這次我們執行帶-c參數的strace：

1	strace  -c  ./test

最後能得到這樣的trace結果：

12	oracle@orainst[orcl]:~$strace  -c  ./test

12345678910111213141516

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”的結果是一樣的。

123	# 這兩個命令都是將strace結果輸出到檔案test.txt中strace -c -o test.txt ./teststrace -c ./test 2>test.txt

對系統調用進行計時

strace可以使用參數-T將每個系統調用所花費的時間列印出來，每個調用的時間花銷現在在調用行最右邊的角括弧裡面。

12	oracle@orainst[orcl]:~$strace -T ./test

123456789

// 這裡只摘錄部分結果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個字元的數字串

1	strace -s 20 ./test

12	read(0, 2222222222222222222222222     // 我們輸入的2一共有25個"22222222222222222222"..., 1024) = 26 // 而我們看到的結果中2隻有20個

trace一個現有的進程

strace不光能自己初始化一個進程進行trace，還能追蹤現有的進程，參數-p就是取這個作用的，用法也很簡單，具體如下。

1	strace -p pid

綜合例子

說了那麼多的功能和參數，現在我們來一個實用點的，就是研究下Oracle的lgwr進程，看看這個進程是不是像文檔所說的那樣沒3s鐘寫一次log檔案，考慮到lgwr寫日誌的觸發條件比較多，我們需要找一個閒置Oracle執行個體做這個實驗。

我們先要得到lgwr進程的pid，運行下面的命令

1	ps -ef|grep lgwr

1	oracle    5912     1  0 Nov12 ?        00:14:56 ora_lgwr_orcl

得到lgwr的pid是5912，現在啟動strace，然後將trace的幾個輸出到lgwr.txt檔案中，執行下面的命令

1	strace -tt -s 10 -o lgwr.txt -p 5912

過一會之後停止strace，然後查看結果。由於輸出的結果比較多，為了方便我們只看Oracle寫入log檔案時用的pwrite函數的調用

1	grep 'pwrite\(20' lgwr.txt

等等，為什麼grep的時候用的是”pwrite(2″呢？，因為我知道我這個機器開啟的當前的log檔案的控制代碼編號都是2開始的。具體尋找方法是先使用下面的語句找出當前活動的記錄檔都有哪些：

12	select member, v$log.status from v$log, v$logfilewhere v$log.group#=v$logfile.group#;

得到

12345678910

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中去找開啟檔案的控制代碼：

1	ll/proc/.5912/fd/

得到

12345678

lrwx------    1 oracle   dba            64 Dec 30 10:55 18 ->/db/databases/orcl/redo-01-a/redo-t01-g01-m1.loglrwx------    1 oracle   dba            64 Dec 30 10:55 19 ->/db/databases/orcl/redo-03-a/redo-t01-g01-m2.loglrwx------    1 oracle   dba            64 Dec 30 10:55 20 ->/db/databases/orcl/redo-02-a/redo-t01-g02-m1.loglrwx------    1 oracle   dba            64 Dec 30 10:55 21 ->/db/databases/orcl/redo-04-a/redo-t01-g02-m2.loglrwx------    1 oracle   dba            64 Dec 30 10:55 22 ->/db/databases/orcl/redo-01-a/redo-t01-g03-m1.loglrwx------    1 oracle   dba            64 Dec 30 10:55 23 ->/db/databases/orcl/redo-03-a/redo-t01-g03-m2.loglrwx------    1 oracle   dba            64 Dec 30 10:55 24 ->/db/databases/orcl/redo-02-a/redo-t01-g04-m1.loglrwx------    1 oracle   dba            64 Dec 30 10:55 25 ->/db/databases/orcl/redo-04-a/redo-t01-g04-m2.log

現在能看到我機器當前記錄檔的控制代碼分別是20和21。

現在我們得到如下結果

1234567891011121314151617181920212223242526

11:13:55.603245 pwrite(20,"\1\"\0\0J!"..., 1536, 4363264) = 153611:13:55.603569 pwrite(21,"\1\"\0\0J!"..., 1536, 4363264) = 153611:13:55.606888 pwrite(20,"\1\"\0\0M!"..., 1536, 4364800) = 153611:13:55.607172 pwrite(21,"\1\"\0\0M!"..., 1536, 4364800) = 153611:13:55.607934 pwrite(20,"\1\"\0\0P!"..., 1536, 4366336) = 153611:13:55.608199 pwrite(21,"\1\"\0\0P!"..., 1536, 4366336) = 153611:13:55.610260 pwrite(20,"\1\"\0\0S!"..., 1536, 4367872) = 153611:13:55.610530 pwrite(21,"\1\"\0\0S!"..., 1536, 4367872) = 153611:14:00.602446 pwrite(20,"\1\"\0\0V!"..., 1536, 4369408) = 153611:14:00.602750 pwrite(21,"\1\"\0\0V!"..., 1536, 4369408) = 153611:14:00.606386 pwrite(20,"\1\"\0\0Y!"..., 1536, 4370944) = 153611:14:00.606676 pwrite(21,"\1\"\0\0Y!"..., 1536, 4370944) = 153611:14:00.607900 pwrite(20,"\1\"\0\0\\"..., 1024, 4372480) = 102411:14:00.608161 pwrite(21,"\1\"\0\0\\"..., 1024, 4372480) = 102411:14:00.608816 pwrite(20,"\1\"\0\0^!"..., 1024, 4373504) = 102411:14:00.609071 pwrite(21,"\1\"\0\0^!"..., 1024, 4373504) = 102411:14:00.611142 pwrite(20,"\1\"\0\0`!"..., 1536, 4374528) = 153611:14:00.611454 pwrite(21,"\1\"\0\0`!"..., 1536, 4374528) = 153611:14:05.602804 pwrite(20,"\1\"\0\0c!"..., 1024, 4376064) = 102411:14:05.603119 pwrite(21,"\1\"\0\0c!"..., 1024, 4376064) = 102411:14:05.607731 pwrite(20,"\1\"\0\0e!"..., 1024, 4377088) = 102411:14:05.608020 pwrite(21,"\1\"\0\0e!"..., 1024, 4377088) = 102411:14:05.608690 pwrite(20,"\1\"\0\0g!"..., 1024, 4378112) = 102411:14:05.608962 pwrite(21,"\1\"\0\0g!"..., 1024, 4378112) = 102411:14:05.611022 pwrite(20,"\1\"\0\0i!"..., 1536, 4379136) = 153611:14:05.611283 pwrite(21,"\1\"\0\0i!"..., 1536, 4379136) = 1536

很遺憾的是我們看到的寫記錄檔的操作是每5s進行一次，可能是因為這個系統閒置原因？這個還需要再研究一下。

延伸閱讀

• strace@sourceforge
• man strace
• strace

• Introducing strace
• Linux隨機數發生器導致Apache進程全部Block的問題追查

• http://jarfield.iteye.com/blog/1739834