第一章 運維利器：萬能的 strace

高效運維 | 2016-05-24 20:10

個人簡介:

王子勇，騰訊高階業務運維工程師，有8年研發與運維工作經驗。崇尚開源，喜歡鑽研系統技術，曾給rsyslog等專案貢獻過程式碼。 微博帳號：jacuro

strace是什麼？

按照strace官網的描述, strace是一個可用於診斷、除錯和教學的Linux使用者空間跟蹤器。我們用它來監控使用者空間程式和核心的互動，比如系統呼叫、訊號傳遞、程式狀態變更等。

strace底層使用核心的ptrace特性來實現其功能。

在運維的日常工作中，故障處理和問題診斷是個主要的內容，也是必備的技能。strace作為一種動態跟蹤工具，能夠幫助運維高效地定位程式和服務故障。它像是一個偵探，通過系統呼叫的蛛絲馬跡，告訴你異常的真相。

strace能做什麼？

運維工程師都是實踐派的人，我們還是先來個例子吧。

我們從別的機器copy了個叫做some_server的軟體包過來，開發說直接啟動就行，啥都不用改。可是嘗試啟動時卻報錯，根本起不來！

啟動命令：

./some_server ../conf/some_server.conf輸出:

FATAL: InitLogFile failed iRet: -1!

Init error: -1655為什麼起不來呢？從日誌看，似乎是初始化日誌檔案失敗，真相到底怎樣呢？我們用strace來看看。

strace -tt -f ./some_server ../conf/some_server.conf輸出:

我們注意到，在輸出InitLogFile failed錯誤的前一行，有個open系統呼叫:

23:14:24.448034 open("/usr/local/apps/some_server/log//server_agent.log", O_RDWR|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = -1 ENOENT (No such file or directory)它嘗試開啟檔案/usr/local/apps/some_server/log//server_agent.log來寫(不存在則建立)，可是卻出錯了，返回碼是-1, 系統錯誤號errorno為ENOENT。 查下open系統呼叫的手冊頁：

man 2 open

搜尋ENOENT這個錯誤號errno的解釋

ENOENT O_CREAT is not set and the named file does not exist. Or, a directory component in pathname does not exist or is a dangling symbolic link.

這裡說得比較清楚，因為我們例子中的open選項指定了O_CREAT選項，這裡errno為ENOENT的原因是日誌路徑中某個部分不存在或者是一個失效的符號連結。我們來一級一級看下路徑中的哪部分不存在：

ls -l /usr/local/apps/some_server/log

ls: cannot access /usr/local/apps/some_server/log: No such file or directory

ls -l /usr/local/apps/some_server

total 8

drwxr-xr-x 2 root users 4096 May 14 23:13 bin

drwxr-xr-x 2 root users 4096 May 14 22:48 conf原來是log子目錄不存在！上層目錄都是存在的。手工建立log子目錄後，服務就能正常啟動了。

回過頭來， strace究竟能做什麼呢？

它能夠開啟應用程式的這個黑盒，通過系統呼叫的線索，告訴你程式大概在幹嘛。

strace怎麼用？

既然strace是用來跟蹤使用者空間程式的系統呼叫和訊號的，在進入strace使用的主題之前，我們的先理解什麼是系統呼叫。

關於系統呼叫：

按維基百科中的解釋，在計算機中，系統呼叫（英語：system call），又稱為系統呼叫，指執行在使用者空間的程式向作業系統核心請求需要更高許可權執行的服務。

系統呼叫提供使用者程式與作業系統之間的介面。作業系統的程式空間分為使用者空間和核心空間：

作業系統核心直接執行在硬體上，提供裝置管理、記憶體管理、任務排程等功能。

使用者空間通過API請求核心空間的服務來完成其功能——核心提供給使用者空間的這些API, 就是系統呼叫。

在Linux系統上，應用程式碼通過glibc庫封裝的函式，間接使用系統呼叫。

Linux核心目前有300多個系統呼叫，詳細的列表可以通過syscalls手冊頁檢視。這些系統呼叫主要分為幾類：

檔案和裝置訪問類 比如open/close/read/write/chmod等

程式管理類 fork/clone/execve/exit/getpid等

訊號類 signal/sigaction/kill 等

記憶體管理 brk/mmap/mlock等

程式間通訊IPC shmget/semget * 訊號量，共享記憶體，訊息佇列等

網路通訊 socket/connect/sendto/sendmsg 等

其他熟悉Linux系統呼叫/系統程式設計，能夠讓我們在使用strace時得心應手。不過，對於運維的問題定位來說，知道strace這個工具，會查系統呼叫手冊，就差不多夠了。

想要深入瞭解的同學，建議閱讀《Linux系統程式設計》, 《Unix環境高階程式設計》等書籍。

我們回到strace的使用上來。strace有兩種執行模式。

一種是通過它啟動要跟蹤的程式。用法很簡單，在原本的命令前加上strace即可。比如我們要跟蹤 "ls -lh /var/log/messages" 這個命令的執行，可以這樣：

strace ls -lh /var/log/messages另外一種執行模式，是跟蹤已經在執行的程式，在不中斷程式執行的情況下，理解它在幹嘛。 這種情況，給strace傳遞個-p pid 選項即可。

比如，有個在執行的some_server服務，第一步，檢視pid:

pidof some_server

17553得到其pid 17553然後就可以用strace跟蹤其執行:

strace -p 17553完成跟蹤時，按ctrl + C 結束strace即可。

strace有一些選項可以調整其行為，我們這裡介紹下其中幾個比較常用的，然後通過示例講解其實際應用效果。

strace常用選項：

從一個示例命令來看：

strace -tt -T -v -f -e trace=file -o /data/log/strace.log -s 1024 -p 23489-tt 在每行輸出的前面，顯示毫秒級別的時間

-T 顯示每次系統呼叫所花費的時間

-v 對於某些相關呼叫，把完整的環境變數，檔案stat結構等打出來。

-f 跟蹤目標程式，以及目標程式建立的所有子程式

-e 控制要跟蹤的事件和跟蹤行為,比如指定要跟蹤的系統呼叫名稱

-o 把strace的輸出單獨寫到指定的檔案

-s 當系統呼叫的某個引數是字串時，最多輸出指定長度的內容，預設是32個位元組

-p 指定要跟蹤的程式pid, 要同時跟蹤多個pid, 重複多次-p選項即可。

例項：跟蹤nginx, 看其啟動時都訪問了哪些檔案

strace -tt -T -f -e trace=file -o /data/log/strace.log -s 1024 ./nginx部分輸出:

輸出中，第一列顯示的是程式的pid, 接著是毫秒級別的時間，這個是-tt 選項的效果。

每一行的最後一列，顯示了該呼叫所花的時間，是-T選項的結果。

這裡的輸出只顯示和檔案訪問有關的內容，這是因為我們通過-e trace=file 選項指定了。

strace問題定位案例

1、定位程式異常退出

問題：機器上有個叫做run.sh的常駐指令碼，執行一分鐘後會死掉。需要查出死因。

定位：程式還在執行時，通過ps命令獲取其pid, 假設我們得到的pid是24298

strace -o strace.log -tt -p 24298檢視strace.log, 我們在最後2行看到如下內容:

22:47:42.803937 wait4(-1,

22:47:43.228422 +++ killed by SIGKILL +++這裡可以看出，程式是被其他程式用KILL訊號殺死的。

實際上，通過分析，我們發現機器上別的服務有個監控指令碼，它監控一個也叫做run.sh的程式，當發現run.sh程式數大於2時，就會把它殺死重啟。結果導致我們這個run.sh指令碼被誤殺。

程式被殺退出時，strace會輸出killed by SIGX(SIGX代表傳送給程式的訊號)等，那麼，程式自己退出時會輸出什麼呢？

這裡有個叫做test_exit的程式，其程式碼如下:

#include

#include

int main(int argc, char **argv) {

exit(1);

}我們strace看下它退出時strace上能看到什麼痕跡。

strace -tt -e trace=process -f ./test_exit說明: -e trace=process 表示只跟蹤和程式管理相關的系統呼叫。

輸出：

23:07:24.672849 execve("./test_exit", ["./test_exit"], [/* 35 vars */]) = 0

23:07:24.674665 arch_prctl(ARCH_SET_FS, 0x7f1c0eca7740) = 0

23:07:24.675108 exit_group(1) = ?

23:07:24.675259 +++ exited with 1 +++可以看出，程式自己退出時（呼叫exit函式，或者從main函式返回）, 最終呼叫的是exit_group系統呼叫， 並且strace會輸出exited with X（X為退出碼）。

可能有人會疑惑，程式碼裡面明明呼叫的是exit, 怎麼顯示為exit_group?

這是因為這裡的exit函式不是系統呼叫，而是glibc庫提供的一個函式，exit函式的呼叫最終會轉化為exit_group系統呼叫，它會退出當前程式的所有執行緒。實際上，有一個叫做_exit()的系統呼叫(注意exit前面的下劃線), 執行緒退出時最終會呼叫它。

2、定位共享記憶體異常

有個服務啟動時報錯：

shmget 267264 30097568: Invalid argument

Can not get shm...exit!錯誤日誌大概告訴我們是獲取共享記憶體出錯，通過strace看下：

strace -tt -f -e trace=ipc ./a_mon_svr ../conf/a_mon_svr.conf輸出：

22:46:36.351798 shmget(0x5feb, 12000, 0666) = 0

22:46:36.351939 shmat(0, 0, 0) = ?

Process 21406 attached

22:46:36.355439 shmget(0x41400, 30097568, 0666) = -1 EINVAL (Invalid argument)

shmget 267264 30097568: Invalid argument

Can not get shm...exit!這裡，我們通過-e trace=ipc 選項，讓strace只跟蹤和程式通訊相關的系統呼叫。

從strace輸出，我們知道是shmget系統呼叫出錯了，errno是EINVAL。同樣， 查詢下shmget手冊頁，搜尋EINVAL的錯誤碼的說明:

EINVAL A new segment was to be created and size < SHMMIN or size > SHMMAX, or no new segment was to be created, a segment with given key existed, but size is greater than the size of that segment

翻譯下，shmget設定EINVAL錯誤碼的原因為下列之一：

要建立的共享記憶體段比 SHMMIN小 (一般是1個位元組)

要建立的共享記憶體段比 SHMMAX 大 (核心引數kernel.shmmax配置)

指定key的共享記憶體段已存在，其大小和呼叫shmget時傳遞的值不同。

從strace輸出看，我們要連的共享記憶體key 0x41400, 指定的大小是30097568位元組，明顯與第1、2種情況不匹配。那隻剩下第三種情況。使用ipcs看下是否真的是大小不匹配：

ipcs -m | grep 41400

key shmid owner perms bytes nattch status

0x00041400 1015822 root 666 30095516 1 可以看到，已經0x41400這個key已經存在，並且其大小為30095516位元組，和我們呼叫引數中的30097568不匹配，於是產生了這個錯誤。

在我們這個案例裡面，導致共享記憶體大小不一致的原因，是一組程式中，其中一個編譯為32位，另外一個編譯為64位,程式碼裡面使用了long這個變長int資料型別。

把兩個程式都編譯為64解決了這個問題。

這裡特別說下strace的-e trace選項。

要跟蹤某個具體的系統呼叫，-e trace=xxx即可。但有時候我們要跟蹤一類系統呼叫，比如所有和檔名有關的呼叫、所有和記憶體分配有關的呼叫。

如果人工輸入每一個具體的系統呼叫名稱，可能容易遺漏。於是strace提供了幾類常用的系統呼叫組合名字。

-e trace=file 跟蹤和檔案訪問相關的呼叫(引數中有檔名)

-e trace=process 和程式管理相關的呼叫，比如fork/exec/exit_group

-e trace=network 和網路通訊相關的呼叫，比如socket/sendto/connect

-e trace=signal 訊號傳送和處理相關，比如kill/sigaction

-e trace=desc 和檔案描述符相關，比如write/read/select/epoll等

-e trace=ipc 程式見同學相關，比如shmget等

絕大多數情況，我們使用上面的組合名字就夠了。實在需要跟蹤具體的系統呼叫時，可能需要注意C庫實現的差異。

比如我們知道建立程式使用的是fork系統呼叫，但在glibc裡面，fork的呼叫實際上對映到了更底層的clone系統呼叫。使用strace時，得指定-e trace=clone, 指定-e trace=fork什麼也匹配不上。

3、 效能分析

假如有個需求，統計Linux 4.5.4 版本核心中的程式碼行數(包含彙編和C程式碼)。這裡提供兩個Shell指令碼實現：

poor_script.sh:

!/bin/bash

total_line=0

while read filename; do

line=$(wc -l $filename | awk ‘{print $1}’)

(( total_line += line ))

done < <( find linux-4.5.4 -type f ( -iname ‘.c’ -o -iname ‘.h’ -o -iname ‘*.S’ ) )

echo “total line: $total_line”

good_script.sh:

!/bin/bash

find linux-4.5.4 -type f ( -iname ‘.c’ -o -iname ‘.h’ -o -iname ‘*.S’ ) -print0 \

| wc -l —files0-from - | tail -n 1

兩段程式碼實現的目的是一樣的。 我們通過strace的-c選項來分別統計兩種版本的系統呼叫情況和其所花的時間(使用-f同時統計子程式的情況)

從兩個輸出可以看出，good_script.sh 只需要2秒就可以得到結果：19613114行。它大部分的呼叫(calls)開銷是檔案操作(read/open/write/close)等，統計程式碼行數本來就是幹這些事情。

而poor_script.sh完成同樣的任務則花了539秒。它大部分的呼叫開銷都在程式和記憶體管理上(wait4/mmap/getpid…)。

實際上，從兩個圖中clone系統呼叫的次數,我們可以看出good_script.sh只需要啟動3個程式，而poor_script.sh完成整個任務居然啟動了126335個程式！

而程式建立和銷燬的代價是相當高的，效能不差才怪。

總結

當發現程式或服務異常時，我們可以通過strace來跟蹤其系統呼叫，“看看它在幹啥”，進而找到異常的原因。熟悉常用系統呼叫，能夠更好地理解和使用strace。

當然，萬能的strace也不是真正的萬能。當目標程式卡死在使用者態時，strace就沒有輸出了。

這個時候我們需要其他的跟蹤手段，比如gdb/perf/SystemTap等。

 

 

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/26736162/viewspace-2109448/，如需轉載，請註明出處，否則將追究法律責任。