引言
“Oops,系統挂死了..."
“Oops,程式崩潰了..."
“Oops,指令執行報錯..."
對于維護人員來說,這樣的悲劇每天都在上演。理想情況下,系統或應用程式的錯誤日志提供了足夠全面的資訊,通過檢視相關日志,維護人員就能很快地定位出問題發生的原因。但現實情況,許多錯誤日志列印模淩兩可,更多地描述了出錯時的現象(比如"could not open file","connect to XXX time out"),而非出錯的原因。
錯誤日志不能滿足定位問題的需求,我們能從更“深層”的方面着手分析嗎?程式或指令的執行,需要通過系統調用(system call)與作業系統産生互動,其實我們可以通過觀察這些系統調用及其參數、傳回值,界定出錯的範圍,甚至找出問題出現的根因。
在Linux中,strace就是這樣一款工具。通過它,我們可以跟蹤程式執行過程中産生的系統調用及接收到的信号,幫助我們分析程式或指令執行中遇到的異常情況。
一個簡單的例子
如何使用strace對程式進行跟蹤,如何檢視相應的輸出?下面我們通過一個例子來說明。
1.被跟蹤程式示例

//main.c
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
int main( )
{
int fd ;
int i = 0 ;
fd = open( “/tmp/foo”, O_RDONLY ) ;
if ( fd < 0 )
i=5;
else
i=2;
return i;
}

以上程式嘗試以隻讀的方式打開/tmp/foo檔案,然後退出,其中隻使用了open這一個系統調用函數。之後我們對該程式進行編譯,生成可執行檔案:
lx@LX:~$ gcc main.c -o main
2.strace跟蹤輸出
使用以下指令,我們将使用strace對以上程式進行跟蹤,并将結果重定向至main.strace檔案:
lx@LX:~$ strace -o main.strace ./main
接下來我們來看main.strace檔案的内容:

lx@LX:~$ cat main.strace
1 execve("./main", ["./main"], [/* 43 vars */]) = 0
2 brk(0) = 0x9ac4000
3 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
4 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7739000
5 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
6 open("/etc/ld.so.cache", O_RDONLY) = 3
7 fstat64(3, {st_mode=S_IFREG|0644, st_size=80682, ...}) = 0
8 mmap2(NULL, 80682, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7725000
9 close(3) = 0
10 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
11 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
12 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220o\1\0004\0\0\0"..., 512) = 512
13 fstat64(3, {st_mode=S_IFREG|0755, st_size=1434180, ...}) = 0
14 mmap2(NULL, 1444360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x56d000
15 mprotect(0x6c7000, 4096, PROT_NONE) = 0
16 mmap2(0x6c8000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15a) = 0x6c8000
17 mmap2(0x6cb000, 10760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x6cb000
18 close(3) = 0
19 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7724000
20 set_thread_area({entry_number:-1 -> 6, base_addr:0xb77248d0, limit:1048575, seg_32bit:1, contents:0, read_exec_ only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
21 mprotect(0x6c8000, 8192, PROT_READ) = 0
22 mprotect(0x8049000, 4096, PROT_READ) = 0
23 mprotect(0x4b0000, 4096, PROT_READ) = 0
24 munmap(0xb7725000, 80682) = 0
25 open("/tmp/foo", O_RDONLY) = -1 ENOENT (No such file or directory)
26 exit_group(5) = ?
//标紅的行号為友善說明而添加,非strace執行輸出

看到這一堆輸出,是否心生畏難情緒?不用擔心,下面我們對輸出逐條進行分析。
strace跟蹤程式與系統互動時産生的系統調用,以上每一行就對應一個系統調用,格式為:
系統調用的名稱( 參數... ) = 傳回值 錯誤标志和描述
Line 1: 對于指令行下執行的程式,execve(或exec系列調用中的某一個)均為strace輸出系統調用中的第一個。strace首先調用fork或clone函數建立一個子程序,然後在子程序中調用exec載入需要執行的程式(這裡為./main)
Line 2: 以0作為參數調用brk,傳回值為記憶體管理的起始位址(若在子程序中調用malloc,則從0x9ac4000位址開始配置設定空間)
Line 3: 調用access函數檢驗/etc/ld.so.nohwcap是否存在
Line 4: 使用mmap2函數進行匿名記憶體映射,以此來擷取8192bytes記憶體空間,該空間起始位址為0xb7739000,關于匿名記憶體映射,可以看
這裡Line 6: 調用open函數嘗試打開/etc/ld.so.cache檔案,傳回檔案描述符為3
Line 7: fstat64函數擷取/etc/ld.so.cache檔案資訊
Line 8: 調用mmap2函數将/etc/ld.so.cache檔案映射至記憶體,關于使用mmap映射檔案至記憶體,可以看
Line 9: close關閉檔案描述符為3指向的/etc/ld.so.cache檔案
Line12: 調用read,從/lib/i386-linux-gnu/libc.so.6該libc庫檔案中讀取512bytes,即讀取
ELF頭資訊
Line15: 使用mprotect函數對0x6c7000起始的4096bytes空間進行保護(PROT_NONE表示不能通路,PROT_READ表示可以讀取)
Line24: 調用munmap函數,将/etc/ld.so.cache檔案從記憶體中去映射,與Line 8的mmap2對應
Line25: 對應源碼中使用到的唯一的系統調用——open函數,使用其打開/tmp/foo檔案
Line26: 子程序結束,退出碼為5(為什麼退出值為5?傳回前面程式示例部分看看源碼吧:)
3.輸出分析
呼呼!看完這麼多系統調用函數,是不是有點摸不着北?讓我們從整體入手,回到主題strace上來。
從上面輸出可以發現,真正能與源碼對應上的隻有open這一個系統調用(Line25),其他系統調用幾乎都用于進行程序初始化工作:裝載被執行程式、載入libc函數庫、設定記憶體映射等。
源碼中的if語句或其他代碼在相應strace輸出中并沒有展現,因為它們并沒有喚起系統調用。strace隻關心程式與系統之間産生的互動,因而strace不适用于程式邏輯代碼的排錯和分析。
對于Linux中幾百個系統調用,上面strace輸出的幾個隻是冰山一角,想要更深入地了解Linux系統調用,那就man一下吧!
man 2 系統調用名稱
man ld.so //Linux動态連結的manpage
strace常用選項
該節介紹經常用到的幾個strace指令選項,以及在何時使用這些選項合适。
1.跟蹤子程序
預設情況下,strace隻跟蹤指定的程序,而不對指定程序中建立的子程序進行跟蹤。使用-f選項,可對程序中建立的子程序進行跟蹤,并在輸出結果中列印相應程序PID:

mprotect(0x5b1000, 4096, PROT_READ) = 0
munmap(0xb77fc000, 80682) = 0
clone(Process 13600 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb77fb938) = 13600
[pid 13599] fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
[pid 13600] fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
[pid 13599] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 13600] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb780f000
……

對多程序程式、指令和腳本使用strace進行跟蹤的時,一般打開-f選項。
2.記錄系統調用時間
strace還可以記錄程式與系統互動時,各個系統調用發生時的時間資訊,有r、t、tt、ttt、T等幾個選項,它們記錄時間的方式為:
-T: 記錄各個系統調用花費的時間,精确到微秒
-r: 以第一個系統調用(通常為execve)計時,精确到微秒
-t: 時:分:秒
-tt: 時:分:秒 . 微秒
-ttt: 計算機紀元以來的秒數 . 微秒
比較常用的為T選項,因為其提供了每個系統調用花費時間。而其他選項的時間記錄既包含系統調用時間,又算上使用者級代碼執行用時,參考意義就小一些。對部分時間選項我們可以組合起來使用,例如:

strace -Tr ./main
0.000000 execve(“./main”, [“main”], [/* 64 vars */]) = 0
0.000931 fcntl64(0, F_GETFD)= 0 <0.000012>
0.000090 fcntl64(1, F_GETFD)= 0 <0.000022>
0.000060 fcntl64(2, F_GETFD)= 0 <0.000012>
0.000054 uname({sys=”Linux”, node=”ion”, ...}) = 0 <0.000014>
0.000307 geteuid32()= 7903 <0.000011>
0.000040 getuid32()= 7903 <0.000012>
0.000039 getegid32()= 200 <0.000011>
0.000039 getgid32()= 200 <0.000011>
……

最左邊一列為-r選項對應的時間輸出,最右邊一列為-T選項對應的輸出。
3.跟蹤正在運作的程序
使用strace對運作中的程式進行跟蹤,使用指令“strace -p PID”即可,指令執行之後,被跟蹤的程序照常執行,strace的其他選項也适用于運作中的程序跟蹤。
使用strace處理程式挂死
最後我們通過一個程式示例,學習使用strace分析程式挂死的方法。
1.挂死程式源碼

//hang.c
#include <stdio.h>
#include <sys/types.h>
#include <unistd.h>
#include <string.h>
int main(int argc, char** argv)
{
getpid(); //該系統調用起到辨別作用
if(argc < 2)
{
printf("hang (user|system)\n");
return 1;
}
if(!strcmp(argv[1], "user"))
while(1);
else if(!strcmp(argv[1], "system"))
sleep(500);
return 0;
}

可向該程式傳送user和system參數,以上代碼使用死循環模拟使用者态挂死,調用sleep模拟核心态程式挂死。
使用者态挂死跟蹤輸出:

lx@LX:~$ gcc hang.c -o hang
lx@LX:~$ strace ./hang user
……
mprotect(0x8049000, 4096, PROT_READ) = 0
mprotect(0xb59000, 4096, PROT_READ) = 0
munmap(0xb77bf000, 80682) = 0
getpid() = 14539

核心态挂死跟蹤輸出:

lx@LX:~$ strace ./hang system
……
mprotect(0x8049000, 4096, PROT_READ) = 0
mprotect(0xddf000, 4096, PROT_READ) = 0
munmap(0xb7855000, 80682) = 0
getpid() = 14543
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({500, 0},

使用者态挂死情況下,strace在getpid()一行輸出之後沒有其他系統調用輸出;程序在核心态挂死,最後一行的系統調用nanosleep不能完整顯示,這裡nanosleep沒有傳回值表示該調用尚未完成。
因而我們可以得出以下結論:使用strace跟蹤挂死程式,如果最後一行系統調用顯示完整,程式在邏輯代碼處挂死;如果最後一行系統調用顯示不完整,程式在該系統調用處挂死。
當程式挂死在系統調用處,我們可以檢視相應系統調用的man手冊,了解在什麼情況下該系統調用會出現挂死情況。另外,系統調用的參數也為我們提供了一些資訊,例如挂死在如下系統調用:
read(16,
那我們可以知道read函數正在對檔案描述符為16的檔案或socket進行讀取,進一步地,我們可以使用lsof工具,擷取對應于檔案描述符為16的檔案名、該檔案被哪些程序占用等資訊。
小結
本文對Linux中常用的問題診斷工具strace進行了介紹,通過程式示例,介紹了strace的使用方法、輸出格式以及使用strace分析程式挂死問題的方法,另外對strace工具的幾個常用選項進行了說明,描述了這幾個選項适用的場景。
下次再遇到程式挂死、指令執行報錯的問題,如果從程式日志和系統日志中看不出問題出現的原因,先别急着google或找高手幫忙,别忘了一個強大的工具它就在那裡,不離不棄,strace一下吧!
Reference:
Self-Service Linux