More than 5 years have passed since last update.

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

Last updated at 2018-04-01Posted at 2018-03-31

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

前回は、「既存のソースを変更せずに動きを見よう」との目的でしたが、
今回は、「自前プログラムの開発時に、デバッグ冶具として、注目箇所の変数値を出力させながらトレースを行おう」との目的での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

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

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

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up

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