主機管理+堡壘機系統開發：strace命令用法詳解（六）

時間 2019-11-07

標籤主機管理堡壘系統開發 strace 命令用法詳解简体版

原文原文鏈接

1、簡單介紹

strace是什麼？

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

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

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

strace能作什麼？

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

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

啓動命令：

./some_server ../conf/some_server.conf

輸出:

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

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

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

輸出:mongodb

咱們注意到，在輸出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系統調用的手冊頁：bash

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究竟能作什麼呢？

它可以打開應用進程的這個黑盒，經過系統調用的線索，告訴你進程大概在幹嗎。

2、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 選項指定了。

3、strace範例

一、只跟蹤與文件操做有關的系統調用

15:02:39.777281 open("/usr/lib/python2.7/site-packages/salt/log/handlers/raven.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.777459 close(3)                = 0
15:02:39.777900 umask(027)              = 022
15:02:39.778027 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
15:02:39.778124 fstat(3, {st_mode=S_IFREG|0644, st_size=1398, ...}) = 0
15:02:39.778171 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.778225 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1398
15:02:39.778291 close(3)                = 0
15:02:39.778342 munmap(0x7f5867d93000, 4096) = 0
15:02:39.778435 stat("/var/log", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
15:02:39.778510 mkdir("/var/log/salt", 0777) = -1 EEXIST (File exists)
15:02:39.778610 stat("/var/log/salt/master", {st_mode=S_IFREG|0644, st_size=182, ...}) = 0
15:02:39.778679 stat("/var/log/salt/master", {st_mode=S_IFREG|0644, st_size=182, ...}) = 0
15:02:39.778745 umask(022)              = 027
15:02:39.778859 access("/var/log/salt/master", F_OK) = 0
15:02:39.778932 access("/var/log/salt/master", W_OK) = 0
15:02:39.779048 stat("/usr/lib64/python2.7/multiprocessing/queues", 0x7ffda84186f0) = -1 ENOENT (No such file or directory)
15:02:39.779115 open("/usr/lib64/python2.7/multiprocessing/queues.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.779171 open("/usr/lib64/python2.7/multiprocessing/queuesmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.779224 open("/usr/lib64/python2.7/multiprocessing/queues.py", O_RDONLY) = 3
15:02:39.779271 fstat(3, {st_mode=S_IFREG|0644, st_size=12318, ...}) = 0
15:02:39.779316 open("/usr/lib64/python2.7/multiprocessing/queues.pyc", O_RDONLY) = 4
15:02:39.779369 fstat(4, {st_mode=S_IFREG|0644, st_size=11595, ...}) = 0
15:02:39.779405 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.780894 fstat(5, {st_mode=S_IFREG|0644, st_size=11080, ...}) = 0
15:02:39.780930 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.780968 read(5, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\6\0\0\0@\0\0\0s\234\1\0\0d\0"..., 4096) = 4096
15:02:39.781010 fstat(5, {st_mode=S_IFREG|0644, st_size=11080, ...}) = 0
15:02:39.781051 read(5, "\0\0R)\0\0\0R\35\0\0\0R0\0\0\0(\0\0\0\0(\0\0\0\0(\0\0\0\0"..., 4096) = 4096
15:02:39.781104 read(5, "\203\1\0\fs7\0t\3\0\202\1\0x4\0|\0\0j\7\0j\5\0t\6\0\203\1\0r"..., 4096) = 2888
15:02:39.781141 read(5, "", 4096)       = 0
15:02:39.781272 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5855598000
15:02:39.781346 close(5)                = 0
15:02:39.781390 munmap(0x7f5867d93000, 4096) = 0
15:02:39.781478 stat("/usr/lib64/python2.7/multiprocessing/forking", 0x7ffda8417bf0) = -1 ENOENT (No such file or directory)
15:02:39.781533 open("/usr/lib64/python2.7/multiprocessing/forking.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.781580 open("/usr/lib64/python2.7/multiprocessing/forkingmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.781618 open("/usr/lib64/python2.7/multiprocessing/forking.py", O_RDONLY) = 5
15:02:39.781654 fstat(5, {st_mode=S_IFREG|0644, st_size=16314, ...}) = 0
15:02:39.781689 open("/usr/lib64/python2.7/multiprocessing/forking.pyc", O_RDONLY) = 6
15:02:39.781727 fstat(6, {st_mode=S_IFREG|0644, st_size=14360, ...}) = 0
15:02:39.781758 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.781794 read(6, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\6\0\0\0@\0\0\0s\23\3\0\0d\0"..., 4096) = 4096
15:02:39.781833 fstat(6, {st_mode=S_IFREG|0644, st_size=14360, ...}) = 0
15:02:39.781903 read(6, "i\0\0\0\0g\374\251\361\322Mb@?i\2\0\0\0g\232\231\231\231\231\231\251?(\5\0\0"..., 8192) = 8192
15:02:39.781963 read(6, "|\0\0d\4\0\31r{\0t\10\0j\t\0\203\0\0\1n\0\0d\5\0|\0\0k\6\0"..., 4096) = 2072
15:02:39.781998 read(6, "", 4096)       = 0
15:02:39.782232 close(6)                = 0
15:02:39.783245 close(5)                = 0
15:02:39.783486 close(4)                = 0
15:02:39.783636 close(3)                = 0
15:02:39.783718 stat("/usr/lib64/python2.7/multiprocessing/connection", 0x7ffda8417ef0) = -1 ENOENT (No such file or directory)
15:02:39.783775 open("/usr/lib64/python2.7/multiprocessing/connection.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.783814 open("/usr/lib64/python2.7/multiprocessing/connectionmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.783875 open("/usr/lib64/python2.7/multiprocessing/connection.py", O_RDONLY) = 3
15:02:39.783916 fstat(3, {st_mode=S_IFREG|0644, st_size=14901, ...}) = 0
15:02:39.783955 open("/usr/lib64/python2.7/multiprocessing/connection.pyc", O_RDONLY) = 4
15:02:39.784003 fstat(4, {st_mode=S_IFREG|0644, st_size=14695, ...}) = 0
15:02:39.784037 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.784083 read(4, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\3\0\0\0@\0\0\0s\210\2\0\0d\0"..., 4096) = 4096
15:02:39.784129 fstat(4, {st_mode=S_IFREG|0644, st_size=14695, ...}) = 0
15:02:39.784167 read(4, "d(\0\0\0\0(\0\0\0\0(\0\0\0\0s2\0\0\0/usr/lib64/"..., 8192) = 8192
15:02:39.784205 read(4, "\0\0NRK\0\0\0R\n\0\0\0t\4\0\0\0pollR\235\0\0\0R\231\0\0\0"..., 4096) = 2407
15:02:39.784239 read(4, "", 4096)       = 0

二、經過pid跟蹤進程

[root@saltstack ~]# pgrep salt-maste
14379
14388
14393
14394
14397
14398
14399
14406
14407
14408
14409
14410
14412
strace -tt -f  -e trace=file -p 14407 /usr/bin/salt-master
[pid 19087] 15:07:32.820297 openat(AT_FDCWD, "/var/cache/salt/master/minions/mysql-node1-245", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.820394 stat("/var/cache/salt/master/minions/mysql-node1-245/data.p", {st_mode=S_IFREG|0600, st_size=3084, ...}) = 0
[pid 19087] 15:07:32.820502 stat("/var/cache/salt/master/minions/mysql-node1-245/data.p", {st_mode=S_IFREG|0600, st_size=3084, ...}) = 0
[pid 19087] 15:07:32.820564 lstat("/var/cache/salt/master/minions/mongodb-node2-152", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.820622 openat(AT_FDCWD, "/var/cache/salt/master/minions/mongodb-node2-152", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.820720 stat("/var/cache/salt/master/minions/mongodb-node2-152/data.p", {st_mode=S_IFREG|0600, st_size=2768, ...}) = 0
[pid 19087] 15:07:32.820818 stat("/var/cache/salt/master/minions/mongodb-node2-152/data.p", {st_mode=S_IFREG|0600, st_size=2768, ...}) = 0
[pid 19087] 15:07:32.820896 lstat("/var/cache/salt/master/minions/ccb-credit-notify-114", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.820955 openat(AT_FDCWD, "/var/cache/salt/master/minions/ccb-credit-notify-114", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821053 stat("/var/cache/salt/master/minions/ccb-credit-notify-114/data.p", {st_mode=S_IFREG|0600, st_size=2720, ...}) = 0
[pid 19087] 15:07:32.821153 stat("/var/cache/salt/master/minions/ccb-credit-notify-114/data.p", {st_mode=S_IFREG|0600, st_size=2720, ...}) = 0
[pid 19087] 15:07:32.821217 lstat("/var/cache/salt/master/minions/openstack-compute3-45", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821274 openat(AT_FDCWD, "/var/cache/salt/master/minions/openstack-compute3-45", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821373 stat("/var/cache/salt/master/minions/openstack-compute3-45/data.p", {st_mode=S_IFREG|0600, st_size=4609, ...}) = 0
[pid 19087] 15:07:32.821482 stat("/var/cache/salt/master/minions/openstack-compute3-45/data.p", {st_mode=S_IFREG|0600, st_size=4609, ...}) = 0
[pid 19087] 15:07:32.821547 lstat("/var/cache/salt/master/minions/KVM-node1-9", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821605 openat(AT_FDCWD, "/var/cache/salt/master/minions/KVM-node1-9", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821703 stat("/var/cache/salt/master/minions/KVM-node1-9/data.p", {st_mode=S_IFREG|0600, st_size=4801, ...}) = 0
[pid 19087] 15:07:32.821802 stat("/var/cache/salt/master/minions/KVM-node1-9/data.p", {st_mode=S_IFREG|0600, st_size=4801, ...}) = 0
[pid 19087] 15:07:32.821881 lstat("/var/cache/salt/master/minions/KVM-files-DB-16", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821943 openat(AT_FDCWD, "/var/cache/salt/master/minions/KVM-files-DB-16", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.822043 stat("/var/cache/salt/master/minions/KVM-files-DB-16/data.p", {st_mode=S_IFREG|0600, st_size=3365, ...}) = 0
[pid 19087] 15:07:32.822144 stat("/var/cache/salt/master/minions/KVM-files-DB-16/data.p", {st_mode=S_IFREG|0600, st_size=3365, ...}) = 0
[pid 19087] 15:07:32.822207 lstat("/var/cache/salt/master/minions/kvm-compute8-2", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.822264 openat(AT_FDCWD, "/var/cache/salt/master/minions/kvm-compute8-2", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.822361 stat("/var/cache/salt/master/minions/kvm-compute8-2/data.p", {st_mode=S_IFREG|0600, st_size=3156, ...}) = 0
[pid 19087] 15:07:32.822473 stat("/var/cache/salt/master/minions/kvm-compute8-2/data.p", {st_mode=S_IFREG|0600, st_size=3156, ...}) = 0

說明：每一個調用的時間花銷在調用行最右邊的尖括號裏面

三、跟蹤系統調用統計

[root@saltstack ~]# strace -c /usr/bin/salt-master
[WARNING ] Unable to bind socket 0.0.0.0:4505, error: [Errno 98] Address already in use; Is there another salt-master running?
The salt master is shutdown. The ports are not available to bind
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 42.52    0.003375         482         7           clone
 16.88    0.001340           0      3393      2647 open
  5.96    0.000473           0      1158           read
  5.88    0.000467           0      1572       954 stat
  4.30    0.000341           1       572           mmap
  3.69    0.000293           1       346           munmap
  3.39    0.000269           0       856           close
  3.26    0.000259           0      1219           fstat
  2.36    0.000187           1       171           mprotect
  2.10    0.000167           1       170           getdents
  1.86    0.000148           7        22         1 futex
  1.61    0.000128          18         7           wait4
  1.02    0.000081           1       133        48 openat
  0.84    0.000067           1       116           brk
  0.73    0.000058          19         3           sendmmsg
  0.72    0.000057           1        68           rt_sigaction
  0.44    0.000035           7         5           pipe
  0.42    0.000033           0       220       148 lseek
  0.37    0.000029           3        11         1 ioctl
  0.28    0.000022           2        10           poll
  0.21    0.000017           2         9         6 connect
  0.20    0.000016           3         6           recvfrom
  0.16    0.000013           0        87         6 lstat
  0.16    0.000013           1        23         5 access
  0.13    0.000010           1        10           socket
  0.09    0.000007           0        35           fcntl
  0.08    0.000006           1         6           write
  0.06    0.000005           3         2           mremap
  0.06    0.000005           5         1           execve
  0.04    0.000003           3         1           rt_sigprocmask
  0.04    0.000003           2         2           getrlimit
  0.04    0.000003           3         1           arch_prctl
  0.03    0.000002           0         6           uname
  0.03    0.000002           2         1           set_tid_address
  0.03    0.000002           2         1           set_robust_list
  0.01    0.000001           0         3           getcwd
  0.01    0.000001           0         3           pipe2
  0.00    0.000000           0         2         1 select
  0.00    0.000000           0         1         1 bind
  0.00    0.000000           0         1           setsockopt
  0.00    0.000000           0         1         1 mkdir
  0.00    0.000000           0         3           link
  0.00    0.000000           0         6           unlink
  0.00    0.000000           0         6         2 readlink
  0.00    0.000000           0         2           umask
  0.00    0.000000           0         2           sysinfo
  0.00    0.000000           0        15           getuid
  0.00    0.000000           0         1           getgid
  0.00    0.000000           0         3           geteuid
  0.00    0.000000           0         1           getegid
  0.00    0.000000           0         3         2 statfs
------ ----------- ----------- --------- --------- ----------------
100.00    0.007938                 10303      3823 total

說明：上面的結果將清楚地告訴咱們調用了那些系統函數，調用的次數是多少，消耗了多少時間等信息，這對咱們分析程序來講是很是有用的

四、重定向輸出

strace -c -o tongji.log /usr/bin/salt-master

[root@saltstack ~]# cat tongji.log

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 22.40    0.002689         384         7           clone
 19.96    0.002396           1      3393      2647 open
 12.14    0.001458           1      1572       954 stat
 11.82    0.001419           1      1158           read
  6.43    0.000772           1       856           close
  6.08    0.000730           1      1219           fstat
  3.66    0.000439           1       572           mmap
  3.64    0.000437           1       346           munmap
  2.30    0.000276           2       133        48 openat
  2.16    0.000259           1       220       148 lseek
  2.09    0.000251           1       170           getdents
  1.93    0.000232          33         7           wait4
  1.43    0.000172           1       171           mprotect
  1.10    0.000132           2        87         6 lstat
  0.66    0.000079           1       116           brk
  0.52    0.000062          10         6           write
  0.39    0.000047           2        20         3 futex
  0.37    0.000045           2        23         5 access
  0.27    0.000032           1        35           fcntl
  0.07    0.000009           2         5           pipe
  0.07    0.000008           1        15           getuid
  0.06    0.000007           1        11         1 ioctl
  0.06    0.000007           1         6           uname
  0.04    0.000005           0        68           rt_sigaction
  0.04    0.000005           3         2           mremap
  0.04    0.000005           5         1           execve
  0.04    0.000005           1         6         2 readlink
  0.03    0.000004           1         3           pipe2
  0.02    0.000003           3         1           rt_sigprocmask
  0.02    0.000003           1         3           link
  0.02    0.000003           2         2           getrlimit
  0.02    0.000003           3         1           set_tid_address
  0.02    0.000002           0        10           poll

說明：講結果重定向到文件中

五、對系統調用進行計時

strace -T tongji.log /usr/bin/salt-master

lseek(5, 0, SEEK_CUR)                   = 641 <0.000020>
lseek(5, 0, SEEK_CUR)                   = 641 <0.000024>
read(5, "", 4096)                       = 0 <0.000020>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 6 <0.000027>
fstat(6, {st_mode=S_IFREG|0644, st_size=26480, ...}) = 0 <0.000019>
mmap(NULL, 26480, PROT_READ, MAP_PRIVATE, 6, 0) = 0x7f03c2a9d000 <0.000024>
close(6)                                = 0 <0.000018>
open("/lib64/tls/x86_64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000027>
stat("/lib64/tls/x86_64", 0x7ffc50377020) = -1 ENOENT (No such file or directory) <0.000022>
open("/lib64/tls/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000026>
stat("/lib64/tls", {st_mode=S_IFDIR|0555, st_size=6, ...}) = 0 <0.000022>
open("/lib64/x86_64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
stat("/lib64/x86_64", 0x7ffc50377020)   = -1 ENOENT (No such file or directory) <0.000021>
open("/lib64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
stat("/lib64", {st_mode=S_IFDIR|0555, st_size=24576, ...}) = 0 <0.000021>
open("/usr/lib64/tls/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
open("/usr/lib64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000031>
munmap(0x7f03c2a9d000, 26480)           = 0 <0.000026>
close(5)                                = 0 <0.000042>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000025>
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000030>
fstat(5, {st_mode=S_IFREG|0644, st_size=1398, ...}) = 0 <0.000020>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f03c2b6c000 <0.000022>
read(5, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1398 <0.000025>
close(5)                                = 0 <0.000021>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000023>
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5 <0.000031>
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000033>
close(5)                                = 0 <0.000023>
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5 <0.000022>
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000025>
close(5)                                = 0 <0.000021>
open("/etc/group", O_RDONLY|O_CLOEXEC)  = 5 <0.000037>
fstat(5, {st_mode=S_IFREG|0644, st_size=641, ...}) = 0 <0.000019>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f03c2b6c000 <0.000027>
read(5, "root:x:0:\nbin:x:1:\ndaemon:x:2:\ns"..., 4096) = 641 <0.000026>
close(5)                                = 0 <0.000022>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000023>
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000051>

說明：每一個調用的時間花銷在調用行最右邊的尖括號裏面

4、定位案例

一、定位進程異常退出

問題：機器上有個叫作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個進程！

而進程建立和銷燬的代價是至關高的，性能不差纔怪。

5、總結

當發現進程或服務異常時，咱們能夠經過strace來跟蹤其系統調用，「看看它在幹啥」，進而找到異常的緣由。熟悉經常使用系統調用，可以更好地理解和使用strace。

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

這個時候咱們須要其餘的跟蹤手段，好比gdb/perf/SystemTap等。

備註：

一、perf緣由kernel支持

二、ftrace kernel支持可編程

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

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。