[轉帖]強大的strace命令用法詳解

強大的strace命令用法詳解

文章轉自: https://www.linuxidc.com/Linux/2018-01/150654.htmhtml

  strace是什麼?

  按照strace官網的描述, strace是一個可用於診斷、調試和教學的Linux用戶空間跟蹤器。咱們用它來監控用戶空間進程和內核的交互,好比系統調用、信號傳遞、進程狀態變動等。linux

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

  在運維的平常工做中,故障處理和問題診斷是個主要的內容,也是必備的技能。strace做爲一種動態跟蹤工具,可以幫助運維高效地定位進程和服務故障。它像是一個偵探,經過系統調用的蛛絲馬跡,告訴你異常的真相。編程

  strace能作什麼?

  運維工程師都是實踐派的人,咱們仍是先來個例子吧。bash

  咱們從別的機器copy了個叫作some_server的軟件包過來,開發說直接啓動就行,啥都不用改。但是嘗試啓動時卻報錯,根本起不來!網絡

  啓動命令:

  ./some_server ../conf/some_server.conf

  輸出:

  FATAL: InitLogFile failed iRet: -1!
  Init error: -1655

  爲何起不來呢?從日誌看,彷佛是初始化日誌文件失敗,真相到底怎樣呢?咱們用strace來看看。app

  strace -tt -f  ./some_server ../conf/some_server.conf

  輸出:運維

 

  咱們注意到,在輸出InitLogFile failed錯誤的前一行,有個open系統調用:socket

  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問題定位案例

  一、定位進程異常退出

  問題:機器上有個叫作run.sh的常駐腳本,運行一分鐘後會死掉。須要查出死因。

  定位:進程還在運行時,經過ps命令獲取其pid, 假設咱們獲得的pid是24298

  strace -o strace.log -tt -p 24298

  查看strace.log, 咱們在最後2行看到以下內容:

  22:47:42.803937 wait4(-1,  <unfinished ...>
  22:47:43.228422 +++ killed by SIGKILL +++

  這裏能夠看出,進程是被其餘進程用KILL信號殺死的。

  實際上,經過分析,咱們發現機器上別的服務有個監控腳本,它監控一個也叫作run.sh的進程,當發現run.sh進程數大於2時,就會把它殺死重啓。結果致使咱們這個run.sh腳本被誤殺。

  進程被殺退出時,strace會輸出killed by SIGX(SIGX表明發送給進程的信號)等,那麼,進程本身退出時會輸出什麼呢?

  這裏有個叫作test_exit的程序,其代碼以下:

  #include <stdio.h>
  #include <stdlib.h>

  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前面的下劃線), 線程退出時最終會調用它。

  二、定位共享內存異常

  有個服務啓動時報錯:

  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字節,明顯與第一、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什麼也匹配不上。

  三、 性能分析

  假若有個需求,統計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等。

  備註:

  一、perf緣由kernel支持

  二、ftrace  kernel支持可編程

  三、systemtap 功能強大,RedHat系統支持,對用戶態,內核態邏輯都能探查,使用範圍更廣

  本文永久更新連接地址:http://www.linuxidc.com/Linux/2018-01/150654.htm

相關文章
相關標籤/搜索