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

前回 [SystemTap で ユーザプログラムのトレース　その１](https://qiita.com/t-tkd3a/items/3be2c93721fb354394bc) からの続きです。

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

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

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

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

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

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

### トレース用の SystemTap スクリプト
```stp:/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++ ヘッダファイル
``` h:/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++ ソースコード
``` CPP:/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
```

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

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