More than 5 years have passed since last update.

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

Last updated at 2018-03-30Posted at 2018-03-29

まず SystemTap ってなに？

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

公式のWebページおよび Red Hat にわかりやすく詳細なドキュメントがあります。
SystemTap Documentation (公式英語)
SystemTap Examples.
SystemTap ビギナーズガイド (Red Hat 日本語)
SystemTap タップセットリファレンス (Red Hat 日本語)

Qiita でとても参考になった記事　
SystemTapの使い方（User-Space Probing)
SystemTapの使い方

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

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

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

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

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

トレース用の System Tap スクリプト

/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++ ソースコード

/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 から抜けたか表示したい。
・コアダンプを検知しバックトレースを表示したい。

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

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

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 で ユーザプログラムのトレース その１