《運(yùn)維利器：萬能的strace》要點(diǎn)：
本文介紹了運(yùn)維利器：萬能的strace，希望對您有用。如果有疑問，可以聯(lián)系我們。

請及時(shí)關(guān)注“高效運(yùn)維(微信ID：greatops)”公眾號(hào),并置頂公眾號(hào),以免錯(cuò)過各種干貨滿滿的原創(chuàng)文章.

個(gè)人簡介:

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

strace是什么?

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

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

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

strace能做什么?

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

我們從別的機(jī)器copy了個(gè)叫做some_server的軟件包過來,開發(fā)說直接啟動(dòng)就行,啥都不用改.可是嘗試啟動(dòng)時(shí)卻報(bào)錯(cuò),根本起不來!

啟動(dòng)命令：

./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錯(cuò)誤的前一行,有個(gè)open系統(tǒng)調(diào)用:

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來寫(不存在則創(chuàng)建),可是卻出錯(cuò)了,返回碼是-1, 系統(tǒng)錯(cuò)誤號(hào)errorno為ENOENT. 查下open系統(tǒng)調(diào)用的手冊頁：

man 2 open

搜索ENOENT這個(gè)錯(cuò)誤號(hào)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的原因是日志路徑中某個(gè)部分不存在或者是一個(gè)失效的符號(hào)鏈接.我們來一級(jí)一級(jí)看下路徑中的哪部分不存在：

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子目錄不存在!上層目錄都是存在的.手工創(chuàng)建log子目錄后,服務(wù)就能正常啟動(dòng)了.

回過頭來, strace究竟能做什么呢?

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

strace怎么用?

既然strace是用來跟蹤用戶空間進(jìn)程的系統(tǒng)調(diào)用和信號(hà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多個(gè)系統(tǒng)調(diào)用,詳細(xì)的列表可以通過syscalls手冊頁查看.這些系統(tǒng)調(diào)用主要分為幾類：

文件和設(shè)備訪問類 比如open/close/read/write/chmod等

進(jìn)程管理類 fork/clone/execve/exit/getpid等

信號(hào)類 signal/sigaction/kill 等

內(nèi)存管理 brk/mmap/mlock等

進(jìn)程間通信IPC shmget/semget * 信號(hào)量,共享內(nèi)存,消息隊(duì)列等

網(wǎng)絡(luò)通信 socket/connect/sendto/sendmsg 等

其他

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

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

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

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

strace ls -lh /var/log/messages

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

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

pidof some_server

17553

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

strace -p 17553

完成跟蹤時(shí),按ctrl + C 結(jié)束strace即可.

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

strace常用選項(xiàng)：

從一個(gè)示例命令來看：

strace -tt -T -v -f -e trace=file -o /data/log/strace.log -s 1024 -p 23489

-tt 在每行輸出的前面,顯示毫秒級(jí)別的時(shí)間
-T 顯示每次系統(tǒng)調(diào)用所花費(fèi)的時(shí)間
-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)用的某個(gè)參數(shù)是字符串時(shí),最多輸出指定長度的內(nèi)容,默認(rèn)是32個(gè)字節(jié)
-p 指定要跟蹤的進(jìn)程pid, 要同時(shí)跟蹤多個(gè)pid, 重復(fù)多次-p選項(xiàng)即可.

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

strace -tt -T -f -e trace=file -o /data/log/strace.log -s 1024 ./nginx

部分輸出:

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

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

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

strace問題定位案例

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

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

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

strace -o strace.log -tt -p 24298

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

22:47:42.803937 wait4(-1, ?<unfinished …>

22:47:43.228422 +++ killed by SIGKILL +++

這里可以看出,進(jìn)程是被其他進(jìn)程用KILL信號(hào)殺死的.

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

進(jìn)程被殺退出時(shí),strace會(huì)輸出killed by SIGX(SIGX代表發(fā)送給進(jìn)程的信號(hào))等,那么,進(jìn)程自己退出時(shí)會(huì)輸出什么呢?

這里有個(gè)叫做test_exit的程序,其代碼如下:

#include <stdio.h>

#include <stdlib.h>

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

exit(1);

}

我們strace看下它退出時(shí)strace上能看到什么痕跡.

strace -tt -e trace=process -f ./test_exit

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

輸出：

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 +++

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

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

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

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

有個(gè)服務(wù)啟動(dòng)時(shí)報(bào)錯(cuò)：

shmget 267264 30097568: Invalid argument
Can not get shm...exit!

錯(cuò)誤日志大概告訴我們是獲取共享內(nèi)存出錯(cuò),通過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 選項(xiàng),讓strace只跟蹤和進(jìn)程通信相關(guān)的系統(tǒng)調(diào)用.

從strace輸出,我們知道是shmget系統(tǒng)調(diào)用出錯(cuò)了,errno是EINVAL.同樣, 查詢下shmget手冊頁,搜索EINVAL的錯(cuò)誤碼的說明:

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錯(cuò)誤碼的原因?yàn)橄铝兄唬?/p>

• 要?jiǎng)?chuàng)建的共享內(nèi)存段比 SHMMIN小 (一般是1個(gè)字節(jié))
• 要?jiǎng)?chuàng)建的共享內(nèi)存段比 SHMMAX 大 (內(nèi)核參數(shù)kernel.shmmax配置)
• 指定key的共享內(nèi)存段已存在,其大小和調(diào)用shmget時(shí)傳遞的值不同.

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

ipcs ?-m | grep 41400

key ? ? ? ?shmid ? ? ?owner ? ? ?perms ? ? ?bytes ? ? ?nattch ? ? status

0x00041400 1015822 ? ?root ? ? ? 666 ? ? ? ?30095516 ? 1

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

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

把兩個(gè)程序都編譯為64解決了這個(gè)問題.

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

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

如果人工輸入每一個(gè)具體的系統(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 ? ?信號(hào)發(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)用時(shí),可能需要注意C庫實(shí)現(xiàn)的差異.

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

3、 性能分析

假如有個(gè)需求,統(tǒng)計(jì)Linux 4.5.4 版本內(nèi)核中的代碼行數(shù)(包含匯編和C代碼).這里提供兩個(gè)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)用情況和其所花的時(shí)間(使用-f同時(shí)統(tǒng)計(jì)子進(jìn)程的情況)

從兩個(gè)輸出可以看出,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í)際上,從兩個(gè)圖中clone系統(tǒng)調(diào)用的次數(shù),我們可以看出good_script.sh只需要啟動(dòng)3個(gè)進(jìn)程,而poor_script.sh完成整個(gè)任務(wù)居然啟動(dòng)了126335個(gè)進(jìn)程!

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

總結(jié)

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

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

這個(gè)時(shí)候我們需要其他的跟蹤手段,比如gdb/perf/SystemTap等.

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

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

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

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

以“重新定義運(yùn)維”為主題的GOPS2016全球運(yùn)維大會(huì)·上海站,已正式啟動(dòng).您可掃描下方二維碼,或點(diǎn)擊文末“閱讀原文”鏈接,以了解詳情：

轉(zhuǎn)載請注明本頁網(wǎng)址：
http://www.snjht.com/jiaocheng/4514.html