Help us understand the problem. What is going on with this article?

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

More than 1 year has passed since last update.

まず 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 から抜けたか表示したい。
・コアダンプを検知し バックトレースを表示したい。

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

ここまで読んで頂きありがとうございました。
t-tkd3a
機械学習 について実装できる位の理解を目指します。学ぶ過程の資料・成果を公開していきます。 また Linux での 開発環境・ツール類についても忘備録かねて記載していきます。
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした