個人簡介:

王子勇，騰訊高級業(yè)務(wù)運(yùn)維工程師，有8年研發(fā)與運(yùn)維工作經(jīng)驗(yàn)。崇尚開源，喜歡鉆研系統(tǒng)技術(shù)，曾給rsyslog等項(xiàng)目貢獻(xiàn)過代碼。 微博賬號：jacuro

strace是什么？

按照strace官網(wǎng)的描述, strace是一個可用于診斷、調(diào)試和教學(xué)的Linux用戶空間跟蹤器。我們用它來監(jiān)控用戶空間進(jìn)程和內(nèi)核的交互，比如系統(tǒng)調(diào)用、信號傳遞、進(jìn)程狀態(tài)變更等。

strace底層使用內(nèi)核的ptrace特性來實(shí)現(xiàn)其功能。

在運(yùn)維的日常工作中，故障處理和問題診斷是個主要的內(nèi)容，也是必備的技能。strace作為一種動態(tài)跟蹤工具，能夠幫助運(yùn)維高效地定位進(jìn)程和服務(wù)故障。它像是一個偵探，通過系統(tǒng)調(diào)用的蛛絲馬跡，告訴你異常的真相。

strace能做什么？

運(yùn)維工程師都是實(shí)踐派的人，我們還是先來個例子吧。

我們從別的機(jī)器copy了個叫做some_server的軟件包過來，開發(fā)說直接啟動就行，啥都不用改?？墒菄L試啟動時卻報(bào)錯，根本起不來！

啟動命令：

輸出:

為什么起不來呢？從日志看，似乎是初始化日志文件失敗，真相到底怎樣呢？我們用strace來看看。

輸出:

我們注意到，在輸出InitLogFile failed錯誤的前一行，有個open系統(tǒng)調(diào)用:

它嘗試打開文件/usr/local/apps/some_server/log//server_agent.log來寫(不存在則創(chuàng)建)，可是卻出錯了，返回碼是-1, 系統(tǒng)錯誤號errorno為ENOENT。 查下open系統(tǒng)調(diào)用的手冊頁：

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.

這里說得比較清楚，因?yàn)槲覀兝又械膐pen選項(xiàng)指定了O_CREAT選項(xiàng)，這里errno為ENOENT的原因是日志路徑中某個部分不存在或者是一個失效的符號鏈接。我們來一級一級看下路徑中的哪部分不存在：

原來是log子目錄不存在！上層目錄都是存在的。手工創(chuàng)建log子目錄后，服務(wù)就能正常啟動了。

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

它能夠打開應(yīng)用進(jìn)程的這個黑盒，通過系統(tǒng)調(diào)用的線索，告訴你進(jìn)程大概在干嘛。

strace怎么用？

既然strace是用來跟蹤用戶空間進(jìn)程的系統(tǒng)調(diào)用和信號的，在進(jìn)入strace使用的主題之前，我們的先理解什么是系統(tǒng)調(diào)用。

關(guān)于系統(tǒng)調(diào)用：

按維基百科中的解釋，在計(jì)算機(jī)中，系統(tǒng)調(diào)用（英語：system call），又稱為系統(tǒng)呼叫，指運(yùn)行在用戶空間的程序向操作系統(tǒng)內(nèi)核請求需要更高權(quán)限運(yùn)行的服務(wù)。

系統(tǒng)調(diào)用提供用戶程序與操作系統(tǒng)之間的接口。操作系統(tǒng)的進(jìn)程空間分為用戶空間和內(nèi)核空間：

• 操作系統(tǒng)內(nèi)核直接運(yùn)行在硬件上，提供設(shè)備管理、內(nèi)存管理、任務(wù)調(diào)度等功能。

• 用戶空間通過API請求內(nèi)核空間的服務(wù)來完成其功能——內(nèi)核提供給用戶空間的這些API, 就是系統(tǒng)調(diào)用。

在Linux系統(tǒng)上，應(yīng)用代碼通過glibc庫封裝的函數(shù)，間接使用系統(tǒng)調(diào)用。

Linux內(nèi)核目前有300多個系統(tǒng)調(diào)用，詳細(xì)的列表可以通過syscalls手冊頁查看。這些系統(tǒng)調(diào)用主要分為幾類：

熟悉Linux系統(tǒng)調(diào)用/系統(tǒng)編程，能夠讓我們在使用strace時得心應(yīng)手。不過，對于運(yùn)維的問題定位來說，知道strace這個工具，會查系統(tǒng)調(diào)用手冊，就差不多夠了。

想要深入了解的同學(xué)，建議閱讀《Linux系統(tǒng)編程》, 《Unix環(huán)境高級編程》等書籍。

我們回到strace的使用上來。strace有兩種運(yùn)行模式。

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

另外一種運(yùn)行模式，是跟蹤已經(jīng)在運(yùn)行的進(jìn)程，在不中斷進(jìn)程執(zhí)行的情況下，理解它在干嘛。 這種情況，給strace傳遞個-p pid 選項(xiàng)即可。

比如，有個在運(yùn)行的some_server服務(wù)，第一步，查看pid:

得到其pid 17553然后就可以用strace跟蹤其執(zhí)行:

完成跟蹤時，按ctrl + C 結(jié)束strace即可。

strace有一些選項(xiàng)可以調(diào)整其行為，我們這里介紹下其中幾個比較常用的，然后通過示例講解其實(shí)際應(yīng)用效果。

strace常用選項(xiàng)：

從一個示例命令來看：

-tt 在每行輸出的前面，顯示毫秒級別的時間
-T 顯示每次系統(tǒng)調(diào)用所花費(fèi)的時間
-v 對于某些相關(guān)調(diào)用，把完整的環(huán)境變量，文件stat結(jié)構(gòu)等打出來。
-f 跟蹤目標(biāo)進(jìn)程，以及目標(biāo)進(jìn)程創(chuàng)建的所有子進(jìn)程
-e 控制要跟蹤的事件和跟蹤行為,比如指定要跟蹤的系統(tǒng)調(diào)用名稱
-o 把strace的輸出單獨(dú)寫到指定的文件
-s 當(dāng)系統(tǒng)調(diào)用的某個參數(shù)是字符串時，最多輸出指定長度的內(nèi)容，默認(rèn)是32個字節(jié)
-p 指定要跟蹤的進(jìn)程pid, 要同時跟蹤多個pid, 重復(fù)多次-p選項(xiàng)即可。

實(shí)例：跟蹤nginx, 看其啟動時都訪問了哪些文件

部分輸出:

輸出中，第一列顯示的是進(jìn)程的pid, 接著是毫秒級別的時間，這個是-tt 選項(xiàng)的效果。

每一行的最后一列，顯示了該調(diào)用所花的時間，是-T選項(xiàng)的結(jié)果。

這里的輸出只顯示和文件訪問有關(guān)的內(nèi)容，這是因?yàn)槲覀兺ㄟ^-e trace=file 選項(xiàng)指定了。

strace問題定位案例

1、定位進(jìn)程異常退出

問題：機(jī)器上有個叫做run.sh的常駐腳本，運(yùn)行一分鐘后會死掉。需要查出死因。

定位：進(jìn)程還在運(yùn)行時，通過ps命令獲取其pid, 假設(shè)我們得到的pid是24298

查看strace.log, 我們在最后2行看到如下內(nèi)容:

這里可以看出，進(jìn)程是被其他進(jìn)程用KILL信號殺死的。

實(shí)際上，通過分析，我們發(fā)現(xiàn)機(jī)器上別的服務(wù)有個監(jiān)控腳本，它監(jiān)控一個也叫做run.sh的進(jìn)程，當(dāng)發(fā)現(xiàn)run.sh進(jìn)程數(shù)大于2時，就會把它殺死重啟。結(jié)果導(dǎo)致我們這個run.sh腳本被誤殺。

進(jìn)程被殺退出時，strace會輸出killed by SIGX(SIGX代表發(fā)送給進(jìn)程的信號)等，那么，進(jìn)程自己退出時會輸出什么呢？

這里有個叫做test_exit的程序，其代碼如下:

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

說明: -e trace=process 表示只跟蹤和進(jìn)程管理相關(guān)的系統(tǒng)調(diào)用。

輸出：

可以看出，進(jìn)程自己退出時（調(diào)用exit函數(shù)，或者從main函數(shù)返回）, 最終調(diào)用的是exit_group系統(tǒng)調(diào)用， 并且strace會輸出exited with X（X為退出碼）。

可能有人會疑惑，代碼里面明明調(diào)用的是exit, 怎么顯示為exit_group?

這是因?yàn)檫@里的exit函數(shù)不是系統(tǒng)調(diào)用，而是glibc庫提供的一個函數(shù)，exit函數(shù)的調(diào)用最終會轉(zhuǎn)化為exit_group系統(tǒng)調(diào)用，它會退出當(dāng)前進(jìn)程的所有線程。實(shí)際上，有一個叫做_exit()的系統(tǒng)調(diào)用(注意exit前面的下劃線), 線程退出時最終會調(diào)用它。

2、定位共享內(nèi)存異常

有個服務(wù)啟動時報(bào)錯：

錯誤日志大概告訴我們是獲取共享內(nèi)存出錯，通過strace看下：

輸出：

這里，我們通過-e trace=ipc 選項(xiàng)，讓strace只跟蹤和進(jìn)程通信相關(guān)的系統(tǒng)調(diào)用。

從strace輸出，我們知道是shmget系統(tǒng)調(diào)用出錯了，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設(shè)置EINVAL錯誤碼的原因?yàn)橄铝兄唬?/p>

• 要創(chuàng)建的共享內(nèi)存段比 SHMMIN小 (一般是1個字節(jié))

• 要創(chuàng)建的共享內(nèi)存段比 SHMMAX 大 (內(nèi)核參數(shù)kernel.shmmax配置)

• 指定key的共享內(nèi)存段已存在，其大小和調(diào)用shmget時傳遞的值不同。

從strace輸出看，我們要連的共享內(nèi)存key 0x41400, 指定的大小是30097568字節(jié)，明顯與第1、2種情況不匹配。那只剩下第三種情況。使用ipcs看下是否真的是大小不匹配：

可以看到，已經(jīng)0x41400這個key已經(jīng)存在，并且其大小為30095516字節(jié)，和我們調(diào)用參數(shù)中的30097568不匹配，于是產(chǎn)生了這個錯誤。

在我們這個案例里面，導(dǎo)致共享內(nèi)存大小不一致的原因，是一組程序中，其中一個編譯為32位，另外一個編譯為64位,代碼里面使用了long這個變長int數(shù)據(jù)類型。

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

這里特別說下strace的-e trace選項(xiàng)。

要跟蹤某個具體的系統(tǒng)調(diào)用，-e trace=xxx即可。但有時候我們要跟蹤一類系統(tǒng)調(diào)用，比如所有和文件名有關(guān)的調(diào)用、所有和內(nèi)存分配有關(guān)的調(diào)用。

如果人工輸入每一個具體的系統(tǒng)調(diào)用名稱，可能容易遺漏。于是strace提供了幾類常用的系統(tǒng)調(diào)用組合名字。

-e trace=file     跟蹤和文件訪問相關(guān)的調(diào)用(參數(shù)中有文件名)
-e trace=process  和進(jìn)程管理相關(guān)的調(diào)用，比如fork/exec/exit_group
-e trace=network  和網(wǎng)絡(luò)通信相關(guān)的調(diào)用，比如socket/sendto/connect
-e trace=signal    信號發(fā)送和處理相關(guān)，比如kill/sigaction
-e trace=desc  和文件描述符相關(guān)，比如write/read/select/epoll等
-e trace=ipc 進(jìn)程見同學(xué)相關(guān)，比如shmget等

絕大多數(shù)情況，我們使用上面的組合名字就夠了。實(shí)在需要跟蹤具體的系統(tǒng)調(diào)用時，可能需要注意C庫實(shí)現(xiàn)的差異。

比如我們知道創(chuàng)建進(jìn)程使用的是fork系統(tǒng)調(diào)用，但在glibc里面，fork的調(diào)用實(shí)際上映射到了更底層的clone系統(tǒng)調(diào)用。使用strace時，得指定-e trace=clone, 指定-e trace=fork什么也匹配不上。

3、 性能分析

假如有個需求，統(tǒng)計(jì)Linux 4.5.4 版本內(nèi)核中的代碼行數(shù)(包含匯編和C代碼)。這里提供兩個Shell腳本實(shí)現(xiàn)：

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

兩段代碼實(shí)現(xiàn)的目的是一樣的。 我們通過strace的-c選項(xiàng)來分別統(tǒng)計(jì)兩種版本的系統(tǒng)調(diào)用情況和其所花的時間(使用-f同時統(tǒng)計(jì)子進(jìn)程的情況)

從兩個輸出可以看出，good_script.sh 只需要2秒就可以得到結(jié)果：19613114行。它大部分的調(diào)用(calls)開銷是文件操作(read/open/write/close)等，統(tǒng)計(jì)代碼行數(shù)本來就是干這些事情。

而poor_script.sh完成同樣的任務(wù)則花了539秒。它大部分的調(diào)用開銷都在進(jìn)程和內(nèi)存管理上(wait4/mmap/getpid…)。

實(shí)際上，從兩個圖中clone系統(tǒng)調(diào)用的次數(shù),我們可以看出good_script.sh只需要啟動3個進(jìn)程，而poor_script.sh完成整個任務(wù)居然啟動了126335個進(jìn)程！

而進(jìn)程創(chuàng)建和銷毀的代價是相當(dāng)高的，性能不差才怪。

總結(jié)

當(dāng)發(fā)現(xiàn)進(jìn)程或服務(wù)異常時，我們可以通過strace來跟蹤其系統(tǒng)調(diào)用，“看看它在干啥”，進(jìn)而找到異常的原因。熟悉常用系統(tǒng)調(diào)用，能夠更好地理解和使用strace。

當(dāng)然，萬能的strace也不是真正的萬能。當(dāng)目標(biāo)進(jìn)程卡死在用戶態(tài)時，strace就沒有輸出了。

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

怎么讓運(yùn)維更具逼格？

運(yùn)維發(fā)展至今，早已不是刀耕火種的時代，不應(yīng)該仍然是“背黑鍋俠”，“背服務(wù)器俠”。運(yùn)維可以更高逼格、更高價值，運(yùn)維明天可以更美好！

“重新定義運(yùn)維”讓這些成為可能

匯聚整個行業(yè)的力量，集合海內(nèi)外專家的智慧，我們在路上！