Edited at

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

More than 1 year has passed since last update.

前回 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

前回の特徴の、

・関数の深さによるインデント

・関数引数の一覧とその値

・関数からの戻り値

・システムコールの検知

に加えて、

・分岐のどこを通ったか行番号を出力

・注目する変数を、変数名とその値を表示

が加わったことで、

自前プログラムのトレース冶具、テスト時のインシデント生成、等に便利に使用していけると感じてます。


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