Edited at

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

More than 1 year has passed since last update.


まず 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 から抜けたか表示したい。

・コアダンプを検知し バックトレースを表示したい。

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


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