天天看點
傳回

Linux C/C++調試之二：使用strace追蹤程式系統調用

在之前的一篇文章中，我介紹了一種調試手段：利用LD_PRELOAD機制，攔截動态連結器對動态庫的符号解析，達到監控程式IO的目的。事實證明我還是太naive了，我們大可利用現成的工具——strace，來更好地完成這一項工作。

strace不隻能跟蹤程式IO，它能跟蹤程式的所有系統調用，實作的基本手段是ptrace系統調用，不過實作細節還沒研究過，今天隻總結一下它的用法。

首先用strace來跟蹤一下喜聞樂見的hello world：

#include <stdio.h>

int main()
{
    printf("Hello, world!\n");
    return 0;
}
           
$ gcc main.c -o main
$ strace ./main

輸出是這樣的（由于太長，省略了大部分内容）：

execve("./main", ["./main"], 0x7ffcea3db620 /* 33 vars */) = 0

......(太長省略)

write(1, "Hello, world!\n", 14Hello, world!
)         = 14
exit_group(0)                           = ?
+++ exited with 0 +++

所有系統調用被一一記錄了下來，我們可以看出來，printf是通過write系統調用将字元串“Hello, world!\n”寫到檔案描述符為1的檔案（即标準輸出）中，進而輸出到螢幕上的。

這就是strace最基本的用法，它還提供一些非常實用的參數，我們可以來看一下：

-e

這個參數可以用來過濾輸出，它功能很多，具體可以檢視strace的手冊，我們隻用其最基本的功能：跟蹤特定的系統調用。

$ strace -e write ./main

輸出瞬間清爽了：

write(1, "Hello, world!\n", 14Hello, world!
)         = 14
+++ exited with 0 +++

-k

這個參數可以用來輸出堆棧，不過strace的幫助将其标記為了實驗性功能。

$ strace -e write -k ./main

輸出為：

write(1, "Hello, world!\n", 14Hello, world!
)         = 14
 > /lib/x86_64-linux-gnu/libc-2.27.so(__write+0x14) [0x110154]
 > /lib/x86_64-linux-gnu/libc-2.27.so(_IO_file_write+0x2d) [0x8b1bd]
 > /lib/x86_64-linux-gnu/libc-2.27.so(_IO_do_write+0xb1) [0x8cf51]
 > /lib/x86_64-linux-gnu/libc-2.27.so(_IO_file_overflow+0x103) [0x8d403]
 > /lib/x86_64-linux-gnu/libc-2.27.so(_IO_puts+0x1a2) [0x80b62]
 > /home/imred/Documents/Workspace/playground/strace_blog/main(main+0x10) [0x64a]
 > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
 > /home/imred/Documents/Workspace/playground/strace_blog/main(_start+0x2a) [0x55a]
+++ exited with 0 +++

-t/-tt

這組參數可以用來列印時間戳

-y

這個參數可以在列印檔案描述符相關參數時同時把檔案描述符對應的檔案路徑列印出來：

$ strace -e write -y ./main

輸出為：

write(1</dev/pts/0>, "Hello, world!\n", 14Hello, world!
) = 14
+++ exited with 0 +++

可以看出來目前内容被輸出到了序号為0的僞終端。

由于下面的參數與時間統計有關，是以最好調用耗時較長的系統調用來分析其作用，我使用的是usleep函數，它調用了nanosleep系統調用，代碼為：

#include <unistd.h>

int main()
{
    for (int i = 0; i < 10; i++)
    {
        usleep(1000);
    }
    return 0;
}

-T

這個參數可以用來輸出每個系統耗費的時間，這個時間是系統調用開始時間和結束時間之差。

$ strace -e nanosleep -T ./main

輸出為：

nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001089>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001078>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001972>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001108>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001139>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001091>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001093>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001326>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001029>
nanosleep({tv_sec=0, tv_nsec=1000000}, NULL) = 0 <0.001297>
+++ exited with 0 +++

看出來這時間統計的算不上十分準确，最大的誤差甚至接近100%，不過這是strace的問題還是系統調用本身的問題并不确定，也還有可能是我使用了虛拟機的緣故。

-c

這個參數用來彙總系統調用的資料。

$ strace -c ./main

輸出為：

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         1           read
  0.00    0.000000           0         2           close
  0.00    0.000000           0         8         7 stat
  0.00    0.000000           0         2           fstat
  0.00    0.000000           0         5           mmap
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0        10           nanosleep
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0        10         8 openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    49        18 total

能夠分析出每種系統調用總的相對時間、總的絕對時間、平均開銷、調用次數、出錯次數資訊。

你可能會比較奇怪為什麼上面彙總出來的時間消耗都是0，至少nanosleep該消耗了時間。這是因為在預設情況下統計的都是系統時間，即程序在核心空間執行代碼消耗的cpu時間，而不是牆上時間。調用了nanosleep雖然消耗了使用者的時間，但并沒有占用多少cpu時間，是以統計出來就是0了，如果要統計牆上時間，需要下面的這個選項。

-w

這個參數指定-c參數統計牆上時間。

$ strace -wc ./main

輸出為：

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.95    0.015065        1507        10           nanosleep
  0.64    0.000098          98         1           execve
  0.38    0.000058           6        10         8 openat
  0.24    0.000037           5         8         7 stat
  0.20    0.000031           6         5           mmap
  0.18    0.000028           7         4           mprotect
  0.11    0.000017           6         3         3 access
  0.10    0.000016          16         1           munmap
  0.06    0.000009           5         2           fstat
  0.05    0.000008           4         2           close
  0.03    0.000005           5         1           read
  0.03    0.000005           5         1           brk
  0.03    0.000004           4         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.015381                    49        18 total

這回輸出結果大緻符合我們的預期了（雖然誤差很大）。

-f

這個參數指定strace要跟蹤從主線程衍生出來的其他線程和程序。

對于下面的程式：

#include <thread>
#include <unistd.h>

void loopSleep()
{
    for (int i = 0; i < 10; i++)
    {
        usleep(1000);
    }
}

int main()
{
    std::thread t1([](){ loopSleep(); });
    std::thread t2([](){ loopSleep(); });

    t1.join();
    t2.join();

    return 0;
}

nanosleep都沒有在主線程調用，如果我們直接這樣調用strace的話：

$ strace -e nanosleep ./main

其輸出為：

+++ exited with 0 +++

并沒有追蹤到nanosleep的調用。這時就需要指定-f參數了：

$ strace -e nanosleep -f ./main

其輸出為：

strace: Process 4623 attached
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000}, strace: Process 4622 attached
 <unfinished ...>
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] nanosleep({tv_sec=0, tv_nsec=1000000},  <unfinished ...>
[pid  4623] <... nanosleep resumed> NULL) = 0
[pid  4623] +++ exited with 0 +++
[pid  4622] <... nanosleep resumed> NULL) = 0
[pid  4622] +++ exited with 0 +++
+++ exited with 0 +++

追蹤到了我們指定的nanosleep系統調用。

-p

這個參數指定strace連接配接到指定程序上。

以上就是strace這把“錘子”的大緻使用手冊，但是如何把我們目前遇到的問題歸約成“釘子”就沒有手冊可以參考了，需要各位各顯神通了。

c c++ Linux debug strace
上一篇: 通過Strace定位故障原因通過Strace定位故障原因
下一篇: linux下c/c++程式調試拾遺

繼續閱讀