SystemTap で ユーザプログラムのトレース その１

まず SystemTap ってなに？

Linuxのカーネルの動きを調査するためのツールです。
RHEL7 (CentOS7) の カーネル と Systemtap では ユーザプログラムに対しても利用できます。

公式のWebページ および Red Hat に わかりやすく詳細なドキュメントがあります。
SystemTap Documentation (公式 英語)
SystemTap Examples.
SystemTap ビギナーズガイド (Red Hat 日本語)
SystemTap タップセットリファレンス (Red Hat 日本語)

Qiita でとても参考になった記事　
SystemTapの使い方（User-Space Probing)
SystemTapの使い方

なるべく手間かけずにプログラムのトレースを行いたい

対象のプログラムがどう動くのか調査する際に、ソースを読みだす前に、
どう関数が呼び出されて行くのか、関数の引数の一覧とその値、戻り値、を表示させ流れを見ておきたいと思うことはありませんか？
私はあります。 C++でクラスの継承が使われてたり、慣れてないパラダイムのソースを読み進める際には、特に思います。

今回は、-gオプション付きでコンパイルされたものか、"-g -O0"オプションでリコンパイルはするがソースコードは変更しない場合でのトレース方法を示します。
（次回では、自前プログラムの開発時に、動きをトレースするためのソースコード編集を行う場合を示します）

サンプルコードでの実施例

忘備録を兼ねて、実施手順を記します。
SystemTapのスクリプト、C++ ソースコード、systemtap の 実行方法と実行結果 を示します。

/home/TestProgs/tr1/ ディレクトリの下に、下記に示す "tr1.cpp" と "ttr2.stp" の 2 ファイルがあるとします。

トレース用の System Tap スクリプト

/home/TestProgs/tr1/ttr2.stp

#!/usr/bin/stap
// 実行方法例 > stap -v ttr2.stp 'process("/home/TestProgs/tr1/tr1")' 
// $1 は 起動時引数の1番目を示す。 上記例では process("/home/TestProgs/tr1/tr1") が $1 に入る。 

// プロセス開始時へのプローブ
probe $1.begin
{
    printf("[proc begin] pid=%d,procname=%s\n", 
        pid(),      // プロセス番号
        execname()  //  実行ファイル名
    );
}

// プロセス終了時へのプローブ
probe $1.end
{
    printf("[proc end] pid=%d,procname=%s\n", pid(), execname());
}


// システムコールにプローブ
probe $1.syscall
{
    # open systemcall
    if( $syscall == 2) {
        printf("%s open(%s)\n",thread_indent(0),kernel_string($arg1))
    }
    # close systemcall
    else if ( $syscall == 3) {
        printf("%s close(%d)\n",thread_indent(0), $arg1)
    }
    // system call 番号は "ausyscall --dump" のコマンドで取得できる。  
}

// 関数の開始時へのプローブ
probe $1.function("*").call
{
    printf("%s-->%s(%s) @%s %s\n",
        thread_indent(0),   
        ppfunc(),                   // 関数名(クラス名やネームスペースは表示されない）
        $$parms,                    // 引数一覧
        usymfileline(addr()),       // ファイル名と行番号
        probefunc()                 // 関数名(デマングルされてない)
    );
    thread_indent(1);   //
} 

// 関数の終了時へのプローブ
probe $1.function("*").return
{
    thread_indent(-1);
    printf("%s<--%s,%s\n",
        thread_indent(0),
        ppfunc(),
        $$return                // 戻り値
    );
}

・SystemTap スクリプトは C や awk と似た記述です。

サンプル C++ ソースコード

/home/TestProgs/tr1/tr1.cpp

#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/stat.h>
#include <assert.h>

class classSample1{
    public:
        classSample1(){};
        ~classSample1(){};
        int func_C1()  
        {
            printf("classSample1::func_C1()\n");
            return 0;
        }
        int func_C2();
        int cnt_func_C2 = 0;
};

int classSample1::func_C2(){
    printf("classSample2::func_C2()\n");
    cnt_func_C2++;
    int l= cnt_func_C2 % 2;
    printf("cnt_func_C2 %d, l:%d\n",cnt_func_C2,l);
    assert(cnt_func_C2<5);  // 例として中断。
    return 0;
}


int funcSub1()
{
    printf("funcSub1\n");
    return 1;
}

int func1(int x)
{
    int fd;

    fd = open("/tmp/test1.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
    printf("func1\n");
    close(fd);
    funcSub1();
    return 1;
}

int func2(int x)
{
    int fd;

    fd = open("/tmp/test2.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666);
    printf("func2\n");
    close(fd);
    return 2;
}

int main(int argc, char *argv[])
{
    int ret=0;

    classSample1 c1; 

    for(;;) {
        ret = func1(10);
        sleep(2);

        ret = func2(20);
        sleep(2);

        ret = c1.func_C1();
        sleep(2);

        ret = c1.func_C2();
        sleep(2);
    }
    return ret;
}

C++ ソースコードをコンパイル

> cd /home/TestProgs/tr1/
> gcc -Wall -g3 -O0 -std=c++11 tr1.cpp -o tr1 -lstdc++

Systap スクリプトの実行

> stap -v ttr2.stp 'process("/home/TestProgs/tr1/tr1")'

引数に 実行ファイルへのフルパス を含んだ文字列を与えます。
下記の様な パーサー結果が出力されます。

stdout

Pass 1: parsed user script and 491 library scripts using 243892virt/56392res/3316shr/53784data kb, in 790usr/30sys/826real ms.
WARNING: function _start return probe is blacklisted: keyword at ttr2.stp:45:1
 source: probe $1.function("*").return
         ^
Pass 2: analyzed script: 36 probes, 27 functions, 6 embeds, 2 globals using 246148virt/60044res/4600shr/56040data kb, in 100usr/100sys/195real ms.
Pass 3: translated to C into "/tmp/stapa1Sf5u/stap_174029a96504ce3d524d3ac8b34d4f54_38391_src.c" using 246296virt/60520res/4968shr/56188data kb, in 50usr/100sys/149real ms.
Pass 4: compiled C into "stap_174029a96504ce3d524d3ac8b34d4f54_38391.ko" in 3590usr/540sys/3979real ms.
Pass 5: starting run.

・対象プログラムの実行待ちになります。

もう1つシェルを開き 対象プログラムを実行する

> cd /home/TestProgs/tr1/
> ./tr1

SystemTap スクリプト ttr2.stp の出力結果

stdout

[proc begin] pid=20693,procname=tr1
     0 tr1(20693): open(/etc/ld.so.cache)
     0 tr1(20693): close(3)
     0 tr1(20693): open(/lib64/libstdc++.so.6)
     0 tr1(20693): close(3)
     0 tr1(20693): open(/lib64/libgcc_s.so.1)
     0 tr1(20693): close(3)
     0 tr1(20693): open(/lib64/libc.so.6)
     0 tr1(20693): close(3)
     0 tr1(20693): open(/lib64/libm.so.6)
     0 tr1(20693): close(3)
     0 tr1(20693):-->_start() @0x400770 _start
    19 tr1(20693):-->__libc_csu_init() @0x400a60 __libc_csu_init
    46 tr1(20693): -->_init() @0x400698 _init
    57 tr1(20693): <--_init,
    60 tr1(20693): -->frame_dummy() @0x400830 frame_dummy
    68 tr1(20693):  -->register_tm_clones() @0x4007d0 register_tm_clones
    78 tr1(20693):  <--register_tm_clones,
    80 tr1(20693): <--frame_dummy,
    83 tr1(20693):<--__libc_csu_init,
    96 tr1(20693):-->main(argc=0x1 argv=0x7ffd32486188) @/home/TestProgs/tr1/tr1.cpp:59 main
   113 tr1(20693): -->classSample1(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:9 _ZN12classSample1C2Ev
   123 tr1(20693): <--classSample1,
   131 tr1(20693): -->func1(x=0xa) @/home/TestProgs/tr1/tr1.cpp:40 _Z5func1i
   144 tr1(20693):   open(/tmp/test1.txt)
   215 tr1(20693):   close(3)
   229 tr1(20693):  -->funcSub1() @/home/TestProgs/tr1/tr1.cpp:32 _Z8funcSub1v
   246 tr1(20693):  <--funcSub1,return=0x1
   250 tr1(20693): <--func1,return=0x1
2000657 tr1(20693): -->func2(x=0x14) @/home/TestProgs/tr1/tr1.cpp:51 _Z5func2i
2000684 tr1(20693):   open(/tmp/test2.txt)
2000762 tr1(20693):   close(3)
2000826 tr1(20693): <--func2,return=0x2
4002721 tr1(20693): -->func_C1(this=0x400770) @/home/TestProgs/tr1/tr1.cpp:11 _ZN12classSample17func_C1Ev
4002778 tr1(20693): <--func_C1,return=0x0
6002907 tr1(20693): -->func_C2(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:21 _ZN12classSample17func_C2Ev
6002994 tr1(20693): <--func_C2,return=0x0
8003121 tr1(20693): -->func1(x=0xa) @/home/TestProgs/tr1/tr1.cpp:40 _Z5func1i
8003149 tr1(20693):   open(/tmp/test1.txt)
8003228 tr1(20693):   close(3)
8003279 tr1(20693):  -->funcSub1() @/home/TestProgs/tr1/tr1.cpp:32 _Z8funcSub1v
8003310 tr1(20693):  <--funcSub1,return=0x1
8003317 tr1(20693): <--func1,return=0x1
10004527 tr1(20693): -->func2(x=0x14) @/home/TestProgs/tr1/tr1.cpp:51 _Z5func2i
10004555 tr1(20693):   open(/tmp/test2.txt)
10004633 tr1(20693):   close(3)
10004698 tr1(20693): <--func2,return=0x2
12004785 tr1(20693): -->func_C1(this=0x400770) @/home/TestProgs/tr1/tr1.cpp:11 _ZN12classSample17func_C1Ev
12004839 tr1(20693): <--func_C1,return=0x0
14005308 tr1(20693): -->func_C2(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:21 _ZN12classSample17func_C2Ev
14005365 tr1(20693): <--func_C2,return=0x0
16006063 tr1(20693): -->func1(x=0xa) @/home/TestProgs/tr1/tr1.cpp:40 _Z5func1i
16006091 tr1(20693):   open(/tmp/test1.txt)
16006169 tr1(20693):   close(3)
16006191 tr1(20693):  -->funcSub1() @/home/TestProgs/tr1/tr1.cpp:32 _Z8funcSub1v
16006220 tr1(20693):  <--funcSub1,return=0x1
16006227 tr1(20693): <--func1,return=0x1
18009385 tr1(20693): -->func2(x=0x14) @/home/TestProgs/tr1/tr1.cpp:51 _Z5func2i
18009412 tr1(20693):   open(/tmp/test2.txt)
18009488 tr1(20693):   close(3)
18009503 tr1(20693): <--func2,return=0x2
20010037 tr1(20693): -->func_C1(this=0x400770) @/home/TestProgs/tr1/tr1.cpp:11 _ZN12classSample17func_C1Ev
20010093 tr1(20693): <--func_C1,return=0x0
22011732 tr1(20693): -->func_C2(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:21 _ZN12classSample17func_C2Ev
22011789 tr1(20693): <--func_C2,return=0x0
24012358 tr1(20693): -->func1(x=0xa) @/home/TestProgs/tr1/tr1.cpp:40 _Z5func1i
24012385 tr1(20693):   open(/tmp/test1.txt)
24012460 tr1(20693):   close(3)
24012599 tr1(20693):  -->funcSub1() @/home/TestProgs/tr1/tr1.cpp:32 _Z8funcSub1v
24012750 tr1(20693):  <--funcSub1,return=0x1
24012757 tr1(20693): <--func1,return=0x1
26012971 tr1(20693): -->func2(x=0x14) @/home/TestProgs/tr1/tr1.cpp:51 _Z5func2i
26012999 tr1(20693):   open(/tmp/test2.txt)
26013074 tr1(20693):   close(3)
26013089 tr1(20693): <--func2,return=0x2
28013574 tr1(20693): -->func_C1(this=0x400770) @/home/TestProgs/tr1/tr1.cpp:11 _ZN12classSample17func_C1Ev
28013630 tr1(20693): <--func_C1,return=0x0
30015263 tr1(20693): -->func_C2(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:21 _ZN12classSample17func_C2Ev
30015319 tr1(20693): <--func_C2,return=0x0
32015746 tr1(20693): -->func1(x=0xa) @/home/TestProgs/tr1/tr1.cpp:40 _Z5func1i
32015773 tr1(20693):   open(/tmp/test1.txt)
32015848 tr1(20693):   close(3)
32015871 tr1(20693):  -->funcSub1() @/home/TestProgs/tr1/tr1.cpp:32 _Z8funcSub1v
32015900 tr1(20693):  <--funcSub1,return=0x1
32015907 tr1(20693): <--func1,return=0x1
34017409 tr1(20693): -->func2(x=0x14) @/home/TestProgs/tr1/tr1.cpp:51 _Z5func2i
34017436 tr1(20693):   open(/tmp/test2.txt)
34017515 tr1(20693):   close(3)
34017592 tr1(20693): <--func2,return=0x2
36018061 tr1(20693): -->func_C1(this=0x400770) @/home/TestProgs/tr1/tr1.cpp:11 _ZN12classSample17func_C1Ev
36018218 tr1(20693): <--func_C1,return=0x0
38020672 tr1(20693): -->func_C2(this=0x7ffd32486080) @/home/TestProgs/tr1/tr1.cpp:21 _ZN12classSample17func_C2Ev
[proc end] pid=20693,procname=tr1

以下の特徴をもつトレースが行われてます。
・関数の深さによるインデント
・関数引数の一覧とその値
・関数からの戻り値
・ファイルの open と close の検知

プログラムの動きを見るには 十分な情報はあると思います。

やりたかったけど、可能かどうかわからなかった事

・クラスのメンバ関数名の表示をデマングル済みで表示したい。
・複数のreturn がある関数で、どの return から抜けたか表示したい。
・コアダンプを検知し バックトレースを表示したい。

　ご存知の方いらっしゃれば、ご教示いただければ幸いです。

ここまで読んで頂きありがとうございました。