C
C++
Linux
デバッグ
systemtap

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

前回 SystemTap で ユーザプログラムのトレース その1 からの続きです。

前回は、「既存のソースを変更せずに動きを見よう」との目的でしたが、
今回は、「自前プログラムの開発時に、デバッグ冶具として、注目箇所の変数値を出力させながらトレースを行おう」との目的でのSystemTap を使用する方法を記します。

自前プログラム開発冶具として用いたい

前回 トレーススクリプトにて 以下の特徴を実現しました。
・関数の深さによるインデント
・関数引数の一覧とその値
・関数からの戻り値
・システムコール(open / close 等) の検知

上記に加え、自前プログラムの挙動を追うには、以下の出力が欲しくなりした。
・関数内で分岐がある場合に、何処を通ったかを知りたい。
・注目する変数の値が知りたい。

一応できました。
もっと洗練したやり方に出来そうな所もあるのですが、今の時点での手法として公開します。

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

実施手順を記します。
SystemTap のスクリプト と それと対応するC++用のヘッダファイル、
C++ソースコード、SystemTap の 実行方法と実行結果 を示します。

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

トレース用の SystemTap スクリプト

/home/TestProgs/tr2/ttr3.stp
#!/usr/bin/stap

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                // 戻り値
    );
}


//define TR_FUNC()  STAP_PROBE2(myTrace,lineFunc,__LINE__,__PRETTY_FUNCTION__)
probe $1.provider("myTrace").mark("lineFunc")
{
    printf("%s%s:%d:%s\n",
        thread_indent(0),       
        usymfile(addr()),       // ソースコード ファイル名
        $arg1,                  // __LINE__
        user_string($arg2)  // ユーザ空間の文字列 __PRETTY_FUNCTION__
    ); 
}

//define TR_LINE()  STAP_PROBE1(myTrace,line,__LINE__)
probe $1.provider("myTrace").mark("line")
{
    printf("%s L:%d\n",
        thread_indent(0),       
        $arg1                   // __LINE__
    );      
}

//define TR_LINE_MSG(a1)    STAP_PROBE2(myTrace,lineMsg,__LINE__,a1)             
probe $1.provider("myTrace").mark("lineMsg")
{
    printf("%s L:%d, %s",
        thread_indent(0),       
        $arg1,                  // __LINE__
        user_string($arg2)                  
    );      
}

//define TR_MSG(a1) STAP_PROBE1(myTrace,msg,a1) 
probe $1.provider("myTrace").mark("msg")
{
    printf("%s",
        user_string($arg1)
    );      
}

//define TR_d(a1) STAP_PROBE2(myTrace,p_d,#a1,a1)
probe $1.provider("myTrace").mark("p_d")
{
    printf("%s=%d ",
        user_string($arg1),
        $arg2
    );      
}

//define TR_u(a1) STAP_PROBE2(myTrace,p_u,#a1,a1)
probe $1.provider("myTrace").mark("p_u")
{
    printf("%s=%u ",
        user_string($arg1),
        $arg2
    );      
}

//define TR_x(a1) STAP_PROBE2(myTrace,p_x,#a1,a1)
probe $1.provider("myTrace").mark("p_x")
{
    printf("%s=0x%x ",
        user_string($arg1),
        $arg2
    );      
}


//define TR_s(a1) STAP_PROBE2(myTrace,p_s,#a1,a1)
probe $1.provider("myTrace").mark("p_s")
{
    printf("%s='%s' ",
        user_string($arg1),
        user_string($arg2)
    );      
}


//define TR_LOCAL() STAP_PROBE(myTrace,local);
probe $1.provider("myTrace").mark("local")
{
    printf("[$$locals] %s\n",$$locals); // スコープ内の全てのローカル変数
}

ttr3.stp の 補足

ソースコードへのプローブには provider().mark() を用いました。
・povider() での指定文字列を namespace として、mark() の指定文字列を 識別名として、用いてます。
・C++のソースコード側からは、簡易printf のイメージで、変数名と変数の値を表示させる様にしてます。 

ttr3.stp と対になる C++ ヘッダファイル

/home/TestProgs/tr2/ttr3.h
#ifndef __TTR3_MYTRACE_H_
#define __TTR3_MYTRACE_H_    1

#ifndef NO_MYTRACE

    #include <stdio.h>
    #include <sys/sdt.h>

    // インデント + ソースファイル名 + 行番号 + デマングル済み関数名 + 改行 
    #define TR_FUNC()   STAP_PROBE2(myTrace,lineFunc,__LINE__,__PRETTY_FUNCTION__)

    // インデント + 行番号 + 改行
    #define TR_LINE()   STAP_PROBE1(myTrace,line,__LINE__)

    // インデント + 行番号 + 引数文字列 
    #define TR_LINE_MSG(a1) STAP_PROBE2(myTrace,lineMsg,__LINE__,a1)

    // 引数文字列           
    #define TR_MSG(a1) STAP_PROBE1(myTrace,msg,a1) 

    // 変数名 と その値 (printf の %d 形式)   
    #define TR_d(a1) STAP_PROBE2(myTrace,p_d,#a1,a1)

    // 変数名 と その値 (printf の %u 形式)   
    #define TR_u(a1) STAP_PROBE2(myTrace,p_u,#a1,a1)

    // 変数名 と その値 (printf の %x 形式)   
    #define TR_x(a1) STAP_PROBE2(myTrace,p_x,#a1,a1)

    // 変数名 と その値 (printf の %s 形式)   
    #define TR_s(a1) STAP_PROBE2(myTrace,p_s,#a1,a1)

    // スコープ内 の ローカル変数全て の 変数名とその値 + 改行
    #define TR_LOCAL() STAP_PROBE(myTrace,local);

    // ダミー件 テスト関数
    // "> stap -v ttr3.stp " 時、ttr3.stp で定義している mark()が、CPPコードに1回も出現してなれば、stap 実行がエラーとなる。 
    //  テストコードを兼ねて ttr3.stap で定義している mark() の全てを この関数に記載する。   
    void STAP_TRACE_defines(){
        int dmyI=0;
        const char *dmyS="dummy";
        TR_FUNC();
        TR_LINE();
        TR_LINE_MSG("test mesg\n"); 
        TR_MSG("test mesg\n");
        TR_d(dmyI);
        TR_u(dmyI);
        TR_x(dmyI);
        TR_s(dmyS);
        TR_LOCAL();
        printf("%s %d\n",dmyS,dmyI);
    }

#else

    #define TR_FUNC()           /**/
    #define TR_LINE()           /**/
    #define TR_LINE_MSG(a1) /**/                 
    #define TR_MSG(a1)          /**/
    #define TR_d(a1)            /**/
    #define TR_u(a1)            /**/
    #define TR_x(a1)            /**/
    #define TR_s(a1)            /**/
    #define TR_LOCAL()      /**/

#endif // NO_MYTRACE

#endif // __TTR3_MYTRACE_H_

ttr3.h の 補足

・sys/sdt.h にて定義されている STAP_PROBE 系の関数を用いて、SystemTap の probe 位置を mark させてます。
・TR_d,TR_u_TR_x,TR_s は 引数は一つですが、#define の #演算子を用いて 変数名 と 変数の値 を取得させています。
・printf の %d %u %x %s に対応する形で、TR_d,TR_u_TR_x,TR_s を定義してます。浮動少数とか足りてません...。
・TR_d,TR_u_TR_x,TR_s を テンプレート等を使って 一つにまとめたいな様にも思います...(でも %d と %x は用途によるから自動判別は難しいし...)。

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

/home/TestProgs/tr2/tr2.cpp
#include <stdio.h>
#include <stdint.h>
#include <unistd.h>
#include <assert.h>

#include "ttr3.h"


class classSample1{
    public:
        classSample1(){};
        ~classSample1(){};
        int func_C1(){
            printf("classSample1::func_C1()\n");
            TR_LINE(); // インデント 行番号 改行
            return 0;
        }
        int func_C2(int m);
        int cnt_func_C2 = 0;
};

int classSample1::func_C2(int m){
    printf("classSample2::func_C2()\n");
    TR_FUNC();  // インデント ファイル名 行番号 デマングル済み関数名 改行
    cnt_func_C2++;
    int l= cnt_func_C2 % 2;
    uint32_t u32=0xfffffffd + cnt_func_C2;
    uint64_t u64=0xfffffffffffffffd + cnt_func_C2;
    int32_t  i32=-3 + cnt_func_C2;
    int64_t  i64=-3 + cnt_func_C2;

    printf("cnt_func_C2 %d , l:%d ,u32:%u, u64:%lu\n",cnt_func_C2,l,u32,u64);   

    TR_LINE_MSG("");TR_d(cnt_func_C2);TR_d(l);TR_MSG("\n");                     // インデント 行番号 cnt_func_C2の値 lの値 改行
    TR_LINE_MSG("");TR_d(i32);TR_u(u32);TR_d(i64);TR_u(u64);TR_MSG("\n");   // インデント 行番号 i32の値 u32の値 i64の値 u64の値 改行 
    TR_LINE_MSG("");TR_LOCAL();                                                 // インデント このスコープ内のローカル変数全て()

    assert(cnt_func_C2<m);  // 例として中断。

    if (l == 0) {
        TR_LINE_MSG("even.\n"); // インデント 行番号 文字列 
        return 0;
    }else{
        TR_LINE_MSG("odd.\n");  // インデント 行番号 文字列
        return 1;
    }
}



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

    classSample1 c1; 

    for(;;) {

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

        ret = c1.func_C2(5);
        sleep(2);

    }
    return ret;
}

補足

・printfの様に TR_*** を加えています。

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

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

SystemTap スクリプトの実行

> stap -v ttr3.stp 'process("/home/TestProgs/tr2/tr2")'

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

stdout
Pass 1: parsed user script and 491 library scripts using 243904virt/56396res/3316shr/53796data kb, in 790usr/40sys/837real ms.
WARNING: function _start return probe is blacklisted: keyword at ttr3.stp:45:1
 source: probe $1.function("*").return
         ^
Pass 2: analyzed script: 57 probes, 41 functions, 6 embeds, 2 globals using 246812virt/60696res/4680shr/56704data kb, in 120usr/110sys/228real ms.
Pass 3: translated to C into "/tmp/stap4b9QpY/stap_8a82d56cba8247f5ae53b508cd7dbe33_50483_src.c" using 246956virt/61192res/5028shr/56848data kb, in 50usr/110sys/159real ms.
Pass 4: compiled C into "stap_8a82d56cba8247f5ae53b508cd7dbe33_50483.ko" in 4050usr/640sys/4517real ms.
Pass 5: starting run.

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

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

> cd /home/TestProgs/tr2/
> ./tr2

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

stdout
[proc begin] pid=16890,procname=tr2
     0 tr2(16890): open(/etc/ld.so.cache)
     0 tr2(16890): close(3)
     0 tr2(16890): open(/lib64/libstdc++.so.6)
     0 tr2(16890): close(3)
     0 tr2(16890): open(/lib64/libgcc_s.so.1)
     0 tr2(16890): close(3)
     0 tr2(16890): open(/lib64/libc.so.6)
     0 tr2(16890): close(3)
     0 tr2(16890): open(/lib64/libm.so.6)
     0 tr2(16890): close(3)
     0 tr2(16890):-->_start() @0x4006e0 _start
    19 tr2(16890):-->__libc_csu_init() @0x400a10 __libc_csu_init
    32 tr2(16890): -->_init() @0x400628 _init
    43 tr2(16890): <--_init,
    47 tr2(16890): -->frame_dummy() @0x4007a0 frame_dummy
    57 tr2(16890):  -->register_tm_clones() @0x400740 register_tm_clones
    68 tr2(16890):  <--register_tm_clones,
    70 tr2(16890): <--frame_dummy,
    73 tr2(16890):<--__libc_csu_init,
    86 tr2(16890):-->main(argc=0x1 argv=0x7ffc0ea27058) @/home/TestProgs/tr2/tr2.cpp:53 main
   100 tr2(16890): -->classSample1(this=0x0) @/home/TestProgs/tr2/tr2.cpp:11 _ZN12classSample1C2Ev
   113 tr2(16890): <--classSample1,
   116 tr2(16890): -->func_C1(this=0x7ffc0ea26f50) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
   222 tr2(16890):   L:15
   227 tr2(16890): <--func_C1,return=0x0
2003172 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
2003220 tr2(16890):  /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
2003281 tr2(16890):   L:34, cnt_func_C2=1 l=1 
2003299 tr2(16890):   L:35, i32=-2 u32=4294967294 i64=-2 u64=18446744073709551614 
2003324 tr2(16890):   L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0xfffffffe u64=0xfffffffffffffffe i32=0xfffffffffffffffe i64=0xfffffffffffffffe
2003337 tr2(16890):   L:44, odd.
2003345 tr2(16890): <--func_C2,return=0x1
4003668 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
4003729 tr2(16890):   L:15
4003738 tr2(16890): <--func_C1,return=0x0
6006538 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
6006587 tr2(16890):  /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
6006612 tr2(16890):   L:34, cnt_func_C2=2 l=0 
6006630 tr2(16890):   L:35, i32=-1 u32=4294967295 i64=-1 u64=18446744073709551615 
6006655 tr2(16890):   L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x0 u32=0xffffffff u64=0xffffffffffffffff i32=0xffffffffffffffff i64=0xffffffffffffffff
6006668 tr2(16890):   L:41, even.
6006676 tr2(16890): <--func_C2,return=0x0
8008347 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
8008409 tr2(16890):   L:15
8008418 tr2(16890): <--func_C1,return=0x0
10009956 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
10010004 tr2(16890):  /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
10010028 tr2(16890):   L:34, cnt_func_C2=3 l=1 
10010046 tr2(16890):   L:35, i32=0 u32=0 i64=0 u64=0 
10010070 tr2(16890):   L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0x0 u64=0x0 i32=0x0 i64=0x0
10010081 tr2(16890):   L:44, odd.
10010089 tr2(16890): <--func_C2,return=0x1
12014178 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
12014238 tr2(16890):   L:15
12014246 tr2(16890): <--func_C1,return=0x0
14014842 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
14014888 tr2(16890):  /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
14014912 tr2(16890):   L:34, cnt_func_C2=4 l=0 
14014930 tr2(16890):   L:35, i32=1 u32=1 i64=1 u64=1 
14014953 tr2(16890):   L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x0 u32=0x1 u64=0x1 i32=0x1 i64=0x1
14014965 tr2(16890):   L:41, even.
14014972 tr2(16890): <--func_C2,return=0x0
16015484 tr2(16890): -->func_C1(this=0x4006e0) @/home/TestProgs/tr2/tr2.cpp:13 _ZN12classSample17func_C1Ev
16015579 tr2(16890):   L:15
16015588 tr2(16890): <--func_C1,return=0x0
18020986 tr2(16890): -->func_C2(this=0x7ffc0ea26f50 m=0x5) @/home/TestProgs/tr2/tr2.cpp:23 _ZN12classSample17func_C2Ei
18021033 tr2(16890):  /home/TestProgs/tr2/tr2.cpp:24:int classSample1::func_C2(int)
18021057 tr2(16890):   L:34, cnt_func_C2=5 l=1 
18021074 tr2(16890):   L:35, i32=2 u32=2 i64=2 u64=2 
18021098 tr2(16890):   L:36, [$$locals] __PRETTY_FUNCTION__=[...] l=0x1 u32=0x2 u64=0x2 i32=0x2 i64=0x2
[proc end] pid=16890,procname=tr2

前回の特徴の、
・関数の深さによるインデント
・関数引数の一覧とその値
・関数からの戻り値
・システムコールの検知
に加えて、
・分岐のどこを通ったか行番号を出力
・注目する変数を、変数名とその値を表示
が加わったことで、
自前プログラムのトレース冶具、テスト時のインシデント生成、等に便利に使用していけると感じてます。

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