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

# まず SystemTap ってなに？
Linuxのカーネルの動きを調査するためのツールです。
RHEL7 (CentOS7) の カーネル と Systemtap では ユーザプログラムに対しても利用できます。

公式のWebページ および Red Hat に わかりやすく詳細なドキュメントがあります。
[SystemTap Documentation (公式 英語)](https://sourceware.org/systemtap/documentation.html)
[SystemTap Examples.](https://sourceware.org/systemtap/examples/)
[SystemTap ビギナーズガイド (Red Hat 日本語)](https://access.redhat.com/documentation/ja-jp/red_hat_enterprise_linux/7/html-single/systemtap_beginners_guide/) 
[SystemTap タップセットリファレンス (Red Hat 日本語)](https://access.redhat.com/documentation/ja-jp/red_hat_enterprise_linux/7/html-single/systemtap_tapset_reference)

Qiita でとても参考になった記事　
[SystemTapの使い方（User-Space Probing)](https://qiita.com/hana_shin/items/6bca693206bf5f887cb3)
[SystemTapの使い方](https://qiita.com/hana_shin/items/9b265b4f9a51f98d0f4d)

#なるべく手間かけずにプログラムのトレースを行いたい
対象のプログラムがどう動くのか調査する際に、ソースを読みだす前に、
どう関数が呼び出されて行くのか、関数の引数の一覧とその値、戻り値、を表示させ流れを見ておきたいと思うことはありませんか？
私はあります。 C++でクラスの継承が使われてたり、慣れてないパラダイムのソースを読み進める際には、特に思います。

今回は、-gオプション付きでコンパイルされたものか、"-g -O0"オプションでリコンパイルはするがソースコードは変更しない場合でのトレース方法を示します。
（次回では、自前プログラムの開発時に、動きをトレースするためのソースコード編集を行う場合を示します） 

## サンプルコードでの実施例
忘備録を兼ねて、実施手順を記します。
SystemTapのスクリプト、C++ ソースコード、systemtap の 実行方法と実行結果 を示します。 

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

### トレース用の System Tap スクリプト
```stp:/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++ ソースコード
```cpp:/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 から抜けたか表示したい。
・コアダンプを検知し バックトレースを表示したい。

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

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