首页 > 代码库 > 用户空间程序的函数跟踪器 (Function Tracer)
用户空间程序的函数跟踪器 (Function Tracer)
翻译说明：这是一个日本人写的用户态下的函数tracer, 我们知道系统调用可以用strace, 库调用可以使用ltrace, 但是linux下竟然没有一个比较有名的用户程序的tracer, 这真是比较奇怪。目前这个工具只支持x86架构，arm之类的嵌入式环境不支持。以后有时候自己写一个tracer。
原文来自： http://binary.nahi.to/hogetrace/
tracef - function call tracer
该网页尚未完成。之前用的名字hogetrace比较过分，自重起见改成tracef。
TOC
- 概要
- 実行例子
- 执行环境 (OS)
- 下载
- 编译环境
- 编译方法
- 可解析的程序
- 快照
- fork程序的解析
- exec程序的解析
- 递归
- 多线程
- 大家喜闻乐见的抛出异常
- main之前调用的函数
- 限制事项
- 命令行选项
- 实现机制
- 类似的工具
概要下面
tracef是、面向Linux的「函数调用追踪器」。 和一般在Linux发行版使用的ltrace相类似、但是其有下面的特征和不同点。
- 不单是调用DSO(DLL)里的库函数、自己的函数的调用也可以追踪
- 函数调用的父子关系用可视化的树状图表示
- 可以表示实现函数的文件名和行号
根据上述的这些特征、
- 想了解未知的大型程序的执行的时候
- 阅读源代码时想得到一些额外的信息的时候
- (特别是C++程序中) 想简单确认main函数前后做了什么样的初始化操作的时候
- ...
等等，都可以灵活利用该工具。但是遗憾的是，函数调用时参数的信息没有ltrace那么详细，用于调试还比较困难。目前我手头上的用C++写的比较大的执行文件(.text的大小约为5MB、text/weak的symbol数量是2万左右、进程/线程数量有几十个)的解析都没有什么问题。
如果解析对象没有被strip，就不需要再编译。只要是能使用gdb来调试的可执行文件、也能用tracef来跟踪。除了作为解析対象的可执行文件所包含的「自身函数」的调用以外、如ltrace表示的内容那样、库函数的调用状况也在某种程度上可以表示（命令行选项可以选项是否表示）。
tracef和、ltrace/strace、或gdb一样、通过使用Linux kernel的ptrace(2)系统调用、从别的进程来观察作为解析対象的程序，并显观察状况。
実行例
例如要追踪下面的程序的话、
#include <stdio.h> void my_func_2() { puts("hello, world!"); } void my_func_1() { my_func_2(); } int main(int argc, char** argv) { my_func_1(); fflush(stdout); return 0; }
結果如下所示。
$ gcc -g -o hello hello.c $ tracef --plt --line-numbers --call-tree hello [pid 30126] +++ process 30126 attached (ppid 30125) +++ [pid 30126] === symbols loaded: ‘./hello‘ === [pid 30126] ==> _start() at 0x08048300 [pid 30126] ==> __libc_start_main@plt() at 0x080482cc [pid 30126] ==> __libc_csu_init() at 0x08048440 [pid 30126] ==> _init() at 0x08048294 [pid 30126] ==> call_gmon_start() at 0x08048324 [pid 30126] <== call_gmon_start() [eax = 0x0] [pid 30126] ==> frame_dummy() at 0x080483b0 [pid 30126] <== frame_dummy() [eax = 0x0] [pid 30126] ==> __do_global_ctors_aux() at 0x080484b0 [pid 30126] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30126] <== _init() [eax = 0xffffffff] [pid 30126] <== __libc_csu_init() [eax = 0x8049514] [pid 30126] ==> main() at 0x080483f5 [/home/sato/tracef/sample/hello.c:14] [pid 30126] ==> my_func_1() at 0x080483e8 [/home/sato/tracef/sample/hello.c:9] [pid 30126] ==> my_func_2() at 0x080483d4 [/home/sato/tracef/sample/hello.c:4] [pid 30126] ==> puts@plt() at 0x080482ec [pid 30126] <== puts@plt() [eax = 0xe] [pid 30126] <== my_func_2() [eax = 0xe] [pid 30126] <== my_func_1() [eax = 0xe] [pid 30126] ==> fflush@plt() at 0x080482dc hello, world! [pid 30126] <== fflush@plt() [eax = 0x0] [pid 30126] <== main() [eax = 0x0] [pid 30126] ==> _fini() at 0x080484d8 [pid 30126] ==> __do_global_dtors_aux() at 0x08048350 [pid 30126] <== __do_global_dtors_aux() [eax = 0x0] [pid 30126] <== _fini() [eax = 0x0] [pid 30126] +++ process 30126 detached (ppid 30125) +++ tracef: done
main()调用my_func_1()、my_func_1()调用my_func_2()的过程被显示。另外、 定义这些函数的源文件名也会显示。
这次因为追加了--synthetic选项、puts@plt() 等、DSO里的函数调用也能追踪到。不使用--synthetic 选项的话、仅仅是单纯的追踪程序自身的函数。根据不同的选项，函数的参数的简单的信息也能表示。
動作環境 (OS)
- Linux
- kernel 2.6以后的版本
- x86, x86_64(一部分的功能被限制)
ダウンロード
- tracef-0.16.tar.gz (支持rpmbuild -t, GPLv3)
- tracef-0.16-1.src.rpm
- tracef-0.16-1.i386.rpm
ビルドに必要なライブラリ
Fedora Core 6 / Fedora 7
- gcc-c++
- libstdc++-devel
- binutils-devel
- elfutils-libelf-devel
- boost-devel
RHEL4 / CentOS4
- gcc-c++
- libstdc++-devel
- binutils
- elfutils-libelf-devel
- boost-devel
Ubuntu 7.04
- g++
- binutils-dev
- elfutils
- libelf-dev
- boost*
libdwarf
需要额外的libdwarf包。
- libdwarf-20070703-3.src.rpm
- libdwarf-20070703-3.i386.rpm (Ubuntu 7.04/x86 可用alien -i导入)
ビルド手順
$ tar xvzf tracef-0.1.tar.gz $ cd tracef-0.1 $ ./configure $ cd src $ make
make结果生成的 src/tracef 就是追踪器。这个二进制文件(tracef)、不安装在/usr/local/bin 下也可以、放在自己想放的地方、单独执行也没有问题。这里准备了一些测试用例 sample/用于测试结果。
$ cd ../sample $ ./sample.sh
执行sample.sh后、会编译并链接若干程序，这些程序被tracef解析的结果会放在sample/logs/下。
解析可能なプログラム
是否需要重新编译
解析对象没有被strip的话就不需要重新编译。gdb能解析的二进制就不需要重新编译。
另外、解析対象是有用 -g 编译的话、输出的信息就会增多。例如行号的信息、参数信息都能输出。解析対象は、最好是用-O0 编译的、但这不是必须的。被优化的场合下、一部分的函数调用可能无法被检测出来。
被strip后的二进制的话，就算被追踪了tracef也不会异常退出，但不会输出任何解析結果。
详细
是否被strip、可以使用file命令来确认输出 "stripped" "not stipped"的哪一个。或是用 readelf -S 命令来判断二进制文件是否存在.symtab 段。 下面的例子的话a.out就没有被strip。
$ file a.out a.out: ELF 32-bit LSB executable, Intel 80386, version 1 (SYSV), dynamically linked (uses shared libs), for GNU/Linux 2.6.9, not stripped $ readelf -S a.out | grep ‘\.symtab‘ [40] .symtab SYMTAB 00000000 5d20b4 00d4d0 10 41 1056 4
另外、因为/lib/lib*.a 或 /usr/lib/lib*.a 文件 包含.symtab、如果链接这些 lib*.a 文件的话，这些文件里包含的函数也变成追踪的対象。不希望追踪这些函数的话，请不要使用.a 文件而是链接到 .so上。
程序用 gcc -g编译时就会包含调试信息、追踪结果里就能够包含定义该函数的源文件名、行编号。另外，一部分函数的参数信息也能表示。。程序是否是用-g (或 -ggdb 或 -g3 等等)编译的 、可以用readelf -S 命令确认。如果 有.debug_* 这些段名的话就是用 -g 编译的。
$ readelf -S a.out | grep ‘\.debug_‘ [29] .debug_aranges PROGBITS 00000000 0cb8a6 002aa8 00 0 0 1 [30] .debug_pubnames PROGBITS 00000000 0ce34e 02d72c 00 0 0 1 [31] .debug_info PROGBITS 00000000 0fba7a 1670e5 00 0 0 1 (略)
其他一些细微之处:
- 多线程程序也可以解析 (跟ltrace-0.5 不一样!)。
- 同样、fork的程序也可以解析。fork后的子进程也可以解析。
- fork后exec执行也OK、exec执行的文件的符号会正确读取。
- SIGSEGV/SIGILL/SIGBUS/SIGFPE等crash的程序也可以解析。crash的原因の命令の位置(EIP)也可以表示。
- C++符号也可以demangle(可读化)后表示。
スクリーンショット?
这里举了五个用tracef解析程序的例子。1. forkするプログラムの解析
#include <stdio.h> #include <sys/types.h> #include <unistd.h> int main() { if (fork() == 0) { printf("hello world\n"); return 1; } return 0; }
用tracef解析以上程序的话会输出如下结果。fork后的进程自动开始解析。 --ff 选项可以把每个进程/线程的结果输出到Log文件。
$ ../src/tracef --synthetic -flATu ./fork [pid 30133] 13:56:14.041015 +++ process 30133 attached (ppid 30132) +++ [pid 30133] 13:56:14.065944 === symbols loaded: ‘./fork‘ === [pid 30133] 13:56:14.086854 ==> _start() at 0x080482e0 [pid 30133] 13:56:14.103301 ==> __libc_start_main@plt() at 0x080482a4 [pid 30133] 13:56:14.120804 ==> __libc_csu_init() at 0x08048410 [pid 30133] 13:56:14.142981 ==> _init() at 0x0804826c [pid 30133] 13:56:14.167027 ==> call_gmon_start() at 0x08048304 [pid 30133] 13:56:14.198099 <== call_gmon_start() [eax = 0x0] [pid 30133] 13:56:14.228514 ==> frame_dummy() at 0x08048390 [pid 30133] 13:56:14.256405 <== frame_dummy() [eax = 0x0] [pid 30133] 13:56:14.287810 ==> __do_global_ctors_aux() at 0x08048480 [pid 30133] 13:56:14.316187 <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30133] 13:56:14.346243 <== _init() [eax = 0xffffffff] [pid 30133] 13:56:14.373957 <== __libc_csu_init() [eax = 0x80494e0] [pid 30133] 13:56:14.400881 ==> main() at 0x080483b4 [/home/sato/tracef/sample/fork.c:6] [pid 30133] 13:56:14.424637 ==> fork@plt() at 0x080482c4 [pid 30134] 13:56:14.440226 +++ process 30134 attached (ppid 30133) +++ [pid 30134] 13:56:14.444849 <== fork@plt() [eax = 0x0] [pid 30134] 13:56:14.455462 ==> puts@plt() at 0x080482b4 hello world [pid 30134] 13:56:14.468085 <== puts@plt() [eax = 0xc] [pid 30134] 13:56:14.495761 <== main() [eax = 0x1] [pid 30134] 13:56:14.519362 ==> _fini() at 0x080484a8 [pid 30134] 13:56:14.539950 ==> __do_global_dtors_aux() at 0x08048330 [pid 30134] 13:56:14.566927 <== __do_global_dtors_aux() [eax = 0x0] [pid 30134] 13:56:14.592884 <== _fini() [eax = 0x0] [pid 30134] 13:56:14.616904 +++ process 30134 detached (ppid 30133) +++ [pid 30133] 13:56:14.625031 <== fork@plt() [eax = 0x75b6] [pid 30133] 13:56:14.652768 --- SIGCHLD received (#17 Child exited) --- [pid 30133] 13:56:14.660887 <== main() [eax = 0x0] [pid 30133] 13:56:14.685255 ==> _fini() at 0x080484a8 [pid 30133] 13:56:14.701960 ==> __do_global_dtors_aux() at 0x08048330 [pid 30133] 13:56:14.726249 <== __do_global_dtors_aux() [eax = 0x0] [pid 30133] 13:56:14.755024 <== _fini() [eax = 0x0] [pid 30133] 13:56:14.781833 +++ process 30133 detached (ppid 30132) +++
2. execするプログラムの解析
自分自身をexecすることで足し算という処理を進めていくプログラムを書いてみました (元ネタは何だっけな...BinaryHacks? 思い出せない)。 $ ./exec 0 5 のように起動すると、見えないところでexecve(2)を繰り返して 5+4+3+2+1 を計算し、結果を出力します。argv[1]が累積変数です。
#include <stdio.h> #include <stdlib.h> #include <unistd.h> int main(int argc, char** argv) { if (argc != 3) return 0; /* usage: ./a.out 0 N */ int accum = atoi(argv[1]); int n = atoi(argv[2]); if (n == 0) { printf("answer: %d\n", accum); return accum; } char p[32] = {0}, q[32] = {0}; snprintf(p, 31, "%d", accum + n); snprintf(q, 31, "%d", n - 1); execlp("/proc/self/exe", "exe", p, q, NULL); return -1; }
...プログラムの内容はともかく、execve(2) するようなプログラムであっても、きちんとトレースを継続できていることが下記で確認できます。
$ ../src/tracef --synthetic -flATuv ./exec 0 5 [pid 30137] 13:59:40.506880 +++ process 30137 attached (ppid 30136) +++ [pid 30137] 13:59:40.516425 === symbols loaded: ‘./exec‘ === [pid 30137] 13:59:40.523785 ==> _start() at 0x08048340 [pid 30137] 13:59:40.526590 ==> __libc_start_main@plt() at 0x080482e4 [pid 30137] 13:59:40.528794 ==> __libc_csu_init() at 0x08048550 [pid 30137] 13:59:40.533544 ==> _init() at 0x080482ac [pid 30137] 13:59:40.536994 ==> call_gmon_start() at 0x08048364 [pid 30137] 13:59:40.540511 <== call_gmon_start() [eax = 0x0] [pid 30137] 13:59:40.545888 ==> frame_dummy() at 0x080483f0 [pid 30137] 13:59:40.549673 <== frame_dummy() [eax = 0x0] [pid 30137] 13:59:40.560435 ==> __do_global_ctors_aux() at 0x080485c0 [pid 30137] 13:59:40.585169 <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30137] 13:59:40.618919 <== _init() [eax = 0xffffffff] [pid 30137] 13:59:40.648524 <== __libc_csu_init() [eax = 0x8049638] [pid 30137] 13:59:40.674937 ==> main(int argc <3>, POINTER argv <0xbff88a44>) at 0x08048414 [/home/sato/tracef/sample/exec.c:6] [pid 30137] 13:59:40.718245 ==> atoi@plt() at 0x08048314 [pid 30137] 13:59:40.744948 <== atoi@plt() [eax = 0x0] [pid 30137] 13:59:40.770063 ==> atoi@plt() at 0x08048314 [pid 30137] 13:59:40.793048 <== atoi@plt() [eax = 0x5] [pid 30137] 13:59:40.819975 ==> snprintf@plt() at 0x08048324 [pid 30137] 13:59:40.843943 <== snprintf@plt() [eax = 0x1] [pid 30137] 13:59:40.873277 ==> snprintf@plt() at 0x08048324 [pid 30137] 13:59:40.898579 <== snprintf@plt() [eax = 0x1] [pid 30137] 13:59:40.923149 ==> execlp@plt() at 0x080482f4 [pid 30137] 13:59:40.947893 === execve(2) called. reloading symbols... === [pid 30137] 13:59:40.962784 === symbols loaded: ‘exe‘ === [pid 30137] 13:59:40.977023 ==> _start() at 0x08048340 ... [pid 30137] 13:59:42.522945 ==> execlp@plt() at 0x080482f4 [pid 30137] 13:59:42.546478 === execve(2) called. reloading symbols... === [pid 30137] 13:59:42.556684 === symbols loaded: ‘exe‘ === [pid 30137] 13:59:42.568359 ==> _start() at 0x08048340 [pid 30137] 13:59:42.580952 ==> __libc_start_main@plt() at 0x080482e4 [pid 30137] 13:59:42.594888 ==> __libc_csu_init() at 0x08048550 [pid 30137] 13:59:42.607220 ==> _init() at 0x080482ac [pid 30137] 13:59:42.616299 ==> call_gmon_start() at 0x08048364 [pid 30137] 13:59:42.625258 <== call_gmon_start() [eax = 0x0] [pid 30137] 13:59:42.643251 ==> frame_dummy() at 0x080483f0 [pid 30137] 13:59:42.654002 <== frame_dummy() [eax = 0x0] [pid 30137] 13:59:42.664041 ==> __do_global_ctors_aux() at 0x080485c0 [pid 30137] 13:59:42.673053 <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30137] 13:59:42.688869 <== _init() [eax = 0xffffffff] [pid 30137] 13:59:42.697093 <== __libc_csu_init() [eax = 0x8049638] [pid 30137] 13:59:42.706019 ==> main(int argc <3>, POINTER argv <0xbf966364>) at 0x08048414 [/home/sato/tracef/sample/exec.c:6] [pid 30137] 13:59:42.719013 ==> atoi@plt() at 0x08048314 [pid 30137] 13:59:42.726840 <== atoi@plt() [eax = 0xf] [pid 30137] 13:59:42.731108 ==> atoi@plt() at 0x08048314 [pid 30137] 13:59:42.735355 <== atoi@plt() [eax = 0x0] [pid 30137] 13:59:42.738764 ==> printf@plt() at 0x08048304 answer: 15 [pid 30137] 13:59:42.745753 <== printf@plt() [eax = 0xb] [pid 30137] 13:59:42.749255 <== main() [eax = 0xf] [pid 30137] 13:59:42.752250 ==> _fini() at 0x080485e8 [pid 30137] 13:59:42.755001 ==> __do_global_dtors_aux() at 0x08048390 [pid 30137] 13:59:42.758079 <== __do_global_dtors_aux() [eax = 0x0] [pid 30137] 13:59:42.767404 <== _fini() [eax = 0x0] [pid 30137] 13:59:42.780894 +++ process 30137 detached (ppid 30136) +++
3. 再帰
末尾再帰で足し算を行うプログラムです。最適化の有無でトレースの出力が変化します。 このほか、tar.gzの中には 相互再帰 (mutual recursion) を行うサンプルも含まれています。
#include <stdio.h> int sum(int n) { return n == 0 ? 0 : n + sum(n - 1); } int main() { int s = sum(10); printf("sum(10) = %d\n", s); return s; }
まず最適化のかかっていない実行ファイルのトレース結果から。再帰呼び出しの様子がわかりやすく出力されています。
$ ../src/tracef -lATv ./recursion [pid 30102] +++ process 30102 attached (ppid 30101) +++ [pid 30102] === symbols loaded: ‘./recursion‘ === [pid 30102] ==> _start() at 0x080482b0 [pid 30102] ==> __libc_csu_init() at 0x08048410 [pid 30102] ==> _init() at 0x08048250 [pid 30102] ==> call_gmon_start() at 0x080482d4 [pid 30102] <== call_gmon_start() [eax = 0x0] [pid 30102] ==> frame_dummy() at 0x08048360 [pid 30102] <== frame_dummy() [eax = 0x0] [pid 30102] ==> __do_global_ctors_aux() at 0x08048480 [pid 30102] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30102] <== _init() [eax = 0xffffffff] [pid 30102] <== __libc_csu_init() [eax = 0x80494e4] [pid 30102] ==> main() at 0x080483b4 [/home/sato/tracef/sample/recursion.c:9] [pid 30102] ==> sum(int n <10>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <9>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <8>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <7>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <6>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <5>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <4>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <3>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <2>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <1>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] ==> sum(int n <0>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30102] <== sum() [eax = 0x0] [pid 30102] <== sum() [eax = 0x1] [pid 30102] <== sum() [eax = 0x3] [pid 30102] <== sum() [eax = 0x6] [pid 30102] <== sum() [eax = 0xa] [pid 30102] <== sum() [eax = 0xf] [pid 30102] <== sum() [eax = 0x15] [pid 30102] <== sum() [eax = 0x1c] [pid 30102] <== sum() [eax = 0x24] [pid 30102] <== sum() [eax = 0x2d] [pid 30102] <== sum() [eax = 0x37] [pid 30102] <== main() [eax = 0x37] [pid 30102] ==> _fini() at 0x080484a8 [pid 30102] ==> __do_global_dtors_aux() at 0x08048300 [pid 30102] <== __do_global_dtors_aux() [eax = 0x0] [pid 30102] <== _fini() [eax = 0x0] sum(10) = 55 [pid 30102] +++ process 30102 detached (ppid 30101) +++
次に最適化あり (gcc -O1 -foptimize-sibling-calls) の場合の出力です。関数呼び出し sum(10); の中で行われているはずの足し算の様子が見えなくなりました。というわけで、最適化されたバイナリを相手にするときは少し注意が要ります。逆に、最適化がどう効いたかを調べるのにtracefを使うことも可能です。
$ ../src/tracef -lATv ./recursion_opt [pid 30104] +++ process 30104 attached (ppid 30103) +++ [pid 30104] === symbols loaded: ‘./recursion_opt‘ === [pid 30104] ==> _start() at 0x080482b0 [pid 30104] ==> __libc_csu_init() at 0x080483f0 [pid 30104] ==> _init() at 0x08048250 [pid 30104] ==> call_gmon_start() at 0x080482d4 [pid 30104] <== call_gmon_start() [eax = 0x0] [pid 30104] ==> frame_dummy() at 0x08048360 [pid 30104] <== frame_dummy() [eax = 0x0] [pid 30104] ==> __do_global_ctors_aux() at 0x08048460 [pid 30104] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30104] <== _init() [eax = 0xffffffff] [pid 30104] <== __libc_csu_init() [eax = 0x80494c4] [pid 30104] ==> main() at 0x0804839c [/home/sato/tracef/sample/recursion.c:9] [pid 30104] ==> sum(int n <10>) at 0x08048384 [/home/sato/tracef/sample/recursion.c:4] [pid 30104] <== sum() [eax = 0x37] [pid 30104] <== main() [eax = 0x37] [pid 30104] ==> _fini() at 0x08048488 [pid 30104] ==> __do_global_dtors_aux() at 0x08048300 [pid 30104] <== __do_global_dtors_aux() [eax = 0x0] [pid 30104] <== _fini() [eax = 0x0] sum(10) = 55 [pid 30104] +++ process 30104 detached (ppid 30103) +++
4. マルチスレッド
pthreadを使ったプログラムの解析も問題なく可能です。
#include <stdio.h> #include <pthread.h> void* thread_entry(void* p) { printf("pthread_self()=%lu\n", pthread_self()); return NULL; } int main() { pthread_t t; pthread_create(&t, NULL, thread_entry, 0); pthread_join(t, NULL); return 0; }
tracefでいうスレッドのIDは、$ ps -L で出力される "LWP" の数字や、スレッドを生成した親プロセスの /proc/pid/task/ 以下に現れる数字と同じものです。pthread_self() で得られる unsigned long int値とは別物です。混乱しがちな点なので念のため。
$ ../src/tracef --synthetic -flT ./thread [pid 30154] +++ process 30154 attached (ppid 30153) +++ [pid 30154] === symbols loaded: ‘./thread‘ === [pid 30154] ==> _start() at 0x080483c0 [pid 30154] ==> __libc_start_main@plt() at 0x08048380 [pid 30154] ==> __libc_csu_init() at 0x08048520 [pid 30154] ==> _init() at 0x08048338 [pid 30154] ==> call_gmon_start() at 0x080483e4 [pid 30154] <== call_gmon_start() [eax = 0x0] [pid 30154] ==> frame_dummy() at 0x08048470 [pid 30154] <== frame_dummy() [eax = 0x0] [pid 30154] ==> __do_global_ctors_aux() at 0x08048590 [pid 30154] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30154] <== _init() [eax = 0xffffffff] [pid 30154] <== __libc_csu_init() [eax = 0x80495f8] [pid 30154] ==> main() at 0x080484b6 [/home/sato/tracef/sample/thread.c:11] [pid 30154] ==> pthread_create@plt() at 0x080483a0 [pid 30155] +++ thread 30155 attached (ppid 30154) +++ [pid 30154] <== pthread_create@plt() [eax = 0x0] [pid 30154] ==> pthread_join@plt() at 0x08048360 [pid 30155] ==> thread_entry() at 0x08048494 [/home/sato/tracef/sample/thread.c:5] [pid 30155] ==> pthread_self@plt() at 0x080483b0 [pid 30155] <== pthread_self@plt() [eax = 0xb7efcb90] [pid 30155] ==> printf@plt() at 0x08048390 pthread_self()=3085945744 [pid 30155] <== printf@plt() [eax = 0x1a] [pid 30155] <== thread_entry() [eax = 0x0] [pid 30154] <== pthread_join@plt() [eax = 0x0] [pid 30154] <== main() [eax = 0x0] [pid 30154] ==> _fini() at 0x080485b8 [pid 30154] ==> __do_global_dtors_aux() at 0x08048410 [pid 30154] <== __do_global_dtors_aux() [eax = 0x0] [pid 30154] <== _fini() [eax = 0x0] [pid 30155] +++ thread 30155 detached (ppid 30154) +++ [pid 30154] +++ process 30154 detached (ppid 30153) +++ tracef: done
5. みんなだいすき例外スロー
例外がthrowされて、スタックが巻き戻る例です。
#include <stdio.h> int c(int i) { if (i == 0) throw 0xff; return c(--i); } void b() { c(3); } int a() { try { b(); } catch(int& e) { return e; } return 0; } int main() { return a(); }
c()が引数 i = 0 で呼ばれたタイミングで例外がスロー(__cxa_throw@plt)され、a()までスタックが巻戻った ことがわかります。a()が0xffをリターンしていることもきちんと表示できています。C++なシンボルのdemangleもできています。
$ ../src/tracef --synthetic -flT ./thread [pid 30110] +++ process 30110 attached (ppid 30109) +++ [pid 30110] === symbols loaded: ‘./throw‘ === [pid 30110] ==> _start() at 0x080484d0 [pid 30110] ==> __libc_start_main@plt() at 0x08048458 [pid 30110] ==> __libc_csu_init() at 0x08048680 [pid 30110] ==> _init() at 0x08048420 [pid 30110] ==> call_gmon_start() at 0x080484f4 [pid 30110] <== call_gmon_start() [eax = 0x2e75d4] [pid 30110] ==> frame_dummy() at 0x08048580 [pid 30110] <== frame_dummy() [eax = 0x0] [pid 30110] ==> __do_global_ctors_aux() at 0x080486f0 [pid 30110] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 30110] <== _init() [eax = 0xffffffff] [pid 30110] <== __libc_csu_init() [eax = 0x804982c] [pid 30110] ==> main() at 0x0804864c [/home/sato/tracef/sample/throw.cpp:26] [pid 30110] ==> a()() at 0x08048604 [/home/sato/tracef/sample/throw.cpp:16] [pid 30110] ==> b()() at 0x080485f0 [/home/sato/tracef/sample/throw.cpp:11] [pid 30110] ==> c(int)(int i <3>) at 0x080485a4 [/home/sato/tracef/sample/throw.cpp:5] [pid 30110] ==> c(int)(int i <2>) at 0x080485a4 [/home/sato/tracef/sample/throw.cpp:5] [pid 30110] ==> c(int)(int i <1>) at 0x080485a4 [/home/sato/tracef/sample/throw.cpp:5] [pid 30110] ==> c(int)(int i <0>) at 0x080485a4 [/home/sato/tracef/sample/throw.cpp:5] [pid 30110] ==> __cxa_allocate_exception@plt() at 0x08048468 [pid 30110] <== __cxa_allocate_exception@plt() [eax = 0x9e70058] [pid 30110] ==> __cxa_throw@plt() at 0x08048478 [pid 30110] ==> __gxx_personality_v0@plt() at 0x080484a8 [pid 30110] <== __gxx_personality_v0@plt() [eax = 0x8] ... [pid 30110] ==> __gxx_personality_v0@plt() at 0x080484a8 [pid 30110] <== __gxx_personality_v0@plt() [eax = 0x7] [pid 30110] ==> __cxa_begin_catch@plt() at 0x08048498 [pid 30110] <== __cxa_begin_catch@plt() [eax = 0x9e70058] [pid 30110] ==> __cxa_end_catch@plt() at 0x08048488 [pid 30110] <== __cxa_end_catch@plt() [eax = 0x0] [pid 30110] <== a()() [eax = 0xff] [pid 30110] <== main() [eax = 0xff] [pid 30110] ==> _fini() at 0x08048718 [pid 30110] ==> __do_global_dtors_aux() at 0x08048520 [pid 30110] <== __do_global_dtors_aux() [eax = 0x0] [pid 30110] <== _fini() [eax = 0x0] [pid 30110] +++ process 30110 detached (ppid 30109) +++
6. mainの前の処理
main関数が呼ばれるまでにどんな関数が呼ばれるか観察できます
#include <cstdio> #include <cstddef> // mainの前に呼ばれる関数3つ int foo() { return 1; } int g = foo(); struct bar { bar() {} ~bar() throw() {} } g2; __attribute__((constructor)) void baz() {} // mainの前で初期化される変数value template<const char* S, std::size_t L, std::size_t N = 0> struct strSum_ { static const unsigned long value; }; template<const char* S, std::size_t L, std::size_t N> const unsigned long strSum_<S, L, N>::value = S[N] + strSum_<S, L, N + 1>::value; // XXX: runtime computation template<const char* S, std::size_t L> struct strSum_<S, L, L> { static const unsigned long value = 0; }; // http://www.thescripts.com/forum/thread156880.html template<typename T, std::size_t L> char (&lengthof_helper_(T(&)[L]))[L]; #define LENGTHOF(array) sizeof(lengthof_helper_(array)) extern const char s[] = "C++0x"; // external linkage int main() { return (int) strSum_<s, LENGTHOF(s) - 1>::value; }
foo(), bar(), baz() 関数が、 main()の前に呼ばれる筈で、これらはきちんとトレースできています。メンバ変数valueの初期化もランタイムに起きます（コンパイル時計算になっていません。よくないコードですので真似しないでください ^^;）が、こちらは関数呼び出しによって初期化されるわけではないので残念ながらトレースできていません。
$ ../src/tracef --plt -ClAT ./before_main2 [pid 17098] +++ process 17098 attached (ppid 17097) +++ [pid 17098] === symbols loaded: ‘./before_main2‘ === [pid 17098] ==> _start() at 0x08048370 [pid 17098] ==> __libc_start_main@plt() at 0x08048358 [pid 17098] ==> __libc_csu_init() at 0x080485f0 [pid 17098] ==> _init() at 0x08048310 [pid 17098] ==> call_gmon_start() at 0x08048394 [pid 17098] <== call_gmon_start() [eax = 0x2e75d4] [pid 17098] ==> frame_dummy() at 0x08048420 [pid 17098] <== frame_dummy() [eax = 0x0] [pid 17098] ==> __do_global_ctors_aux() at 0x08048660 [pid 17098] ==> global constructors keyed to _Z3foov() at 0x080485ac [/home/sato/tracef-trunk/sample/before_main2.cpp:44] [pid 17098] ==> __static_initialization_and_destruction_0(int, int)() at 0x08048482 [/home/sato/tracef-trunk/sample/before_main2.cpp:43] [pid 17098] ==> foo()() at 0x08048444 [/home/sato/tracef-trunk/sample/before_main2.cpp:6] [pid 17098] <== foo()() [eax = 0x1] [pid 17098] ==> bar::bar()() at 0x080485c8 [/home/sato/tracef-trunk/sample/before_main2.cpp:10] [pid 17098] <== bar::bar()() [eax = 0x1] [pid 17098] ==> __cxa_atexit@plt() at 0x08048338 [pid 17098] <== __cxa_atexit@plt() [eax = 0x0] [pid 17098] <== __static_initialization_and_destruction_0(int, int)() [eax = 0x141] [pid 17098] ==> baz()() at 0x0804844e [/home/sato/tracef-trunk/sample/before_main2.cpp:16] [pid 17098] <== baz()() [eax = 0x141] [pid 17098] <== global constructors keyed to _Z3foov() [eax = 0x141] [pid 17098] <== __do_global_ctors_aux() [eax = 0xffffffff] [pid 17098] <== _init() [eax = 0xffffffff] [pid 17098] <== __libc_csu_init() [eax = 0x80496bc] [pid 17098] ==> main() at 0x08048454 [/home/sato/tracef-trunk/sample/before_main2.cpp:41] [pid 17098] <== main() [eax = 0x141] [pid 17098] ==> __tcf_0() at 0x0804846e [/home/sato/tracef-trunk/sample/before_main2.cpp:13] [pid 17098] ==> bar::~bar()() at 0x080485ce [/home/sato/tracef-trunk/sample/before_main2.cpp:11] [pid 17098] <== bar::~bar()() [eax = 0x804846e] [pid 17098] <== __tcf_0() [eax = 0x804846e] [pid 17098] ==> _fini() at 0x08048688 [pid 17098] ==> __do_global_dtors_aux() at 0x080483c0 [pid 17098] <== __do_global_dtors_aux() [eax = 0x0] [pid 17098] <== _fini() [eax = 0x0] [pid 17098] +++ process 17098 detached (ppid 17097) +++
制限事項
わかっている不具合を白状します:
- 行番号表示オプション -l を使うと、メモリを必要以上に食います。調査中。
- 位置独立実行形式(PIE)は未サポートです。
- PIEかどうかは、次のようにreadelf -hでELFヘッダのダンプすることで確認できます。ET_DYNならPIE, ET_EXECなら普通の実行ファイルです。fileコマンドでも区別できますが略。
$ readelf -h pie_binary | grep Type: Type: DYN (Shared object file)
- 次の2つの条件が重なると、throwされたC++の例外を正常にcatchできずに、プロセスがSIGABRTで終了(std::terminate)してしまいます。そのようなthrow&catchを行うC++のプログラムをトレースする場合は、--plt か -T のどちらかのオプションを使用しないようにしてください。詳しくは、samples/throw3.cpp を参照のこと。
- DSO内でC++の例外のthrowが行われ、tracefしている実行ファイル内でその例外のcatchが行われる
- tracefに--pltと-Tの両方を与えてトレースを行っている
- -Wl,-Bstaticと-Wl,-Bdynamicを駆使してリンクした実行ファイルは、うまく扱えないことがありそうです。
コマンドラインオプション
おすすめは tracef --plt -CflT です。
Usage:
% tracef [option ...] command [arg ...]
% tracef [option ...] -p pid
Options:
-? [ --help ]
このヘルプを表示
-V [ --version ]
バージョンを表示して終了
-o [ --output ] arg
トレース結果をstderrではなく、‘arg‘ で指定したファイルに出力する
--ff
プロセスあるいはスレッド毎に別のファイルにログを記録する。ログファイル名は
「-o で指定したファイル名」＋「プロセス/スレッドID」となる。
-f [ --trace-child ]
fork()やclone()で生成された子プロセス、子スレッドも追跡する。
--synthetic
--plt
合成シンボルもトレースの対象とする。このオプションを使うと、ライブラリ関数呼び出し
やシステムコール呼び出し（の一部）をトレースすることができる。たとえば、printf@plt()
や signal@plt() など。
-C [ --demangle ]
C++の低レベルな関数名を可読なものに変換して表示する。
-t [ --time ]
出力の各行に現在時刻を付加する。
-u [ --microseconds ]
出力の各行に現在時刻(マイクロ秒単位)を付加する。
-A [ --arg ]
関数の引数名を表示する(EXPERIMENTAL)
-v [ --arg-val ]
関数の引数の値を表示する(EXPERIMENTAL, x86のみ)
-T [ --call-tree ]
関数呼び出しをツリー状に表示する。解析対象がマルチプロセス/マルチスレッドの場合、
-o および --ff オプションと同時に使用することを推奨する。
--offset arg
ツリー表示時の関数呼び出しあたりのオフセット量(スペースの数)を指定します。
デフォルト値は3。
--no-pid
プロセスIDを表示しない。
-i [ --no-eip ]
関数のアドレスを表示しない。
-l [ --line-numbers ]
デバッグ情報を利用し、関数の定義されたファイル名、行番号を表示する。
-p [ --attach-process ] arg
プロセスID ‘arg‘ のプロセスにアタッチする。
-X [ --exclude ] arg
関数 ‘arg‘ をトレースせず、無視する。複数指定が可能。arg にはmangleされたシン
ボル名を指定。
仕組み (つぶやき)
気が向いたら日記に書きます。以下メモ。
- libbfdを使って解析対象のプログラムの.symtabを読んで、全関数の先頭アドレスを得ている。ついでに.plt上の合成(synthetic)シンボル(printf@pltとか)も得ている
- libopcodesで、さっき得た各関数の先頭アドレスから、バイナリを逆アセンブル、ret命令を探すことで関数からのリターンアドレスを静的に解析/特定している。スタック見て動的にやる方法もありますが、今回は静的にやった。ltraceとは違う方法にしてみたかったというのもあるし、マルチスレッド環境で動的にセットしたBPを別スレッドが踏むとめんどくさいというのもあったり。
- ret/retq命令探しの際、_start() はretじゃなくてhltだとか、末尾再帰関数で-O2だとretがないとか、throwで抜けてるとやっぱりretがないとか、構造体を値で戻すような関数だと0xC3ではなく0xC2だったりとか、__attribute((noreturn))されてるとretしないとか、そういう関数を呼ぶ側もcallではなくjmpにしちゃうとか、探すときに細かい注意点がある。
- ひとつの関数内に複数のretが存在することがある。switch使ったときとか? v0.11から全部探すようにした。ちゃんと探さないとインデントがどんどん深くなってしまう。
- ひとつの関数内に、普通のleave-retと、他の関数の「先頭への」jmp (callではなく) が共存していることがある。こういう関数に入ってjmp側に行かれてしまうと、-T 時のインデントが実際より1つ深くなってしまう。対策は.. 「関数先頭へのjmp」 は検出できるから可能だが、やめとく。そういう関数を -X してもらえばとりあえずindentはズレなくなる。あるいは検査対象を -O0 でコンパイルしてくれれば無問題になる。そういう関数を作るには、次のようなコードで -O2 すればOKな模様@gcc-4.1.2/x86。詳しくは samples/hard_to_find_ret.c とそのログを。
switch(...) { case X: return hoge; // leave-ret になる default: } return fuga(); // 自分以外の関数を呼ぶ。jmp になりがち } // 関数の終わり
- .debug_info 見て、関数の定義されているファイル名、行番号の情報を取得している。同じく.debug_info 見て、関数の引数の情報を取得している。
- 解析対象をforkしてptrace(TRACEME);してsetenv(LD_BIND_NOW=1);してexec。setenvしておかないと、PLT経由の関数呼びの初回(_dl_runtime_resolve時)がすぐにreturnするように表示されてしまう。子プロセスの起動時間を延ばしてしまう悪いhackかも。
- 解析対象がメモリにロードされたら、関数の先頭アドレス、RET命令アドレスにブレークポイント設定。ptrace(POKE)でそのアドレスに0xCCを書くだけ
- 解析対象が0xCCを踏むと、tracefにシグナルで通知がくる。ので、適当に情報を表示。0xCCで止まった解析対象の再開方法は、gdbとかと同じ(説明になっていない)。EIPを戻して元の命令書き戻してシングルステップして云々。詳しくは書籍「デバッガの理論と実装」あたりを。
- PLT経由のジャンプのフックは、まずPLT先頭の jmp *0x80... のとこに0xCCを仕掛け、その次の命令 push 0x.. にも0xCCを仕掛けておく。jmp*を踏んで解析対象が止まったら、解析対象のスタック上のリターンアドレスをPEEKして、tracef側に記憶する。そのリターンアドレスをpush 0x..のアドレスにすりかえる(POKE)。push 0xにリターンしてくるとまた0xCCを踏んで止まるので、tracef側に記憶しておいた本物のリターンアドレスを、今度はEIPに書き込んでcontinue。以上。これはひどい。
- この方法だと、DSO内で例外がthrowされて、それが解析対象のバイナリまで到達すると、abortする。ごめんなさいごめんなさいごめんなさい。
まぁ滅多にそんなことしないよね。 - 最低限の対策として、__cxa_throw@plt の先頭でブレークした時は、このリターンアドレスのtweakを行わないようにしておいた。これで、exe内でthrowして、exe内でcatchする場合は問題なくなった。dso内でthrowして、exe内でcatchするプログラムをtraceする場合は、--pltか-Tのどちらかをはずしてもらわないとダメだ...。やはりltrace風の(よくあるデバッガの)、スタック見てリターンアドレスに地雷置くやりかたのほうがよかったか。
- GOT/PLT回りは、arch毎にコードがいる。x86_64はx86とほとんど同じだけど、jmp* がPC相対なのでやっぱり#ifdefすることになった。
- 例外のthrowで表示(コールツリーのインデント具合)が乱れないよう、各プロセス/スレッドの関数呼び出し状況を、tracef側の std::stack<addr_t> にも記憶しておく。
- コマンドラインオプションの解析は、boost::program_optionsで。
- ptraceはぐぐってもあまり文献がなくて、結局頼りになるのはstraceとltraceのソースコードだけだった。straceは多OS対応で魔窟なので、ltraceを中心に見た。でもltraceはスレッドというかcloneというか PTRACE_O_TRACECLONE というかに対応していない。結局そこは試行錯誤。あと、ltraceの .dynほげ セクションの処理部分は面白かったのだけど、今回は使わない...
- straceをstraceしたり、ltraceをstraceしたりするといろいろなことがわかった。
- プロセスのptraceを終了する(detach)と、そのプロセスが即死する現象に悩んだ。単に、プロセスの0xCCを元に戻さないままデタッチしていたからシグナルで死んでいるだけだった。ありがとうございました。forkすると0xCCなまま.textがコピーされることも忘れずに。当然ですが。
- ptrace(GETREGS)に渡す構造体の初期化を省いたら、それが原因でvalgrindが死ぬほどの量の警告を出してくれた。ptraceの引数の初期化省略が原因だと気づくのにすこし時間がかかった。
- ptrace(2)は、以前straceもどきを作ってみてそれでおわりにしていたけど、いろいろ試してみたら想像以上におもしろかった。早いとこ遊んでおけばよかった。
なんだかすごく楽しんだ感あり。
類似ツール
実行ファイル内の、自分で書いた関数の動的なトレースができそうなツール一覧を集めてみました。仕組みをptraceに限定しなければ、いろいろありました。 ptraceベースのツールであるtracefは、速度ではoprofileに負け、視覚化も含めた機能ではcallgrindに負けるので、strace, ltrace のように気楽に使えるツールにすることに重点をおいたつもりです。
- CPUのシミュレーションによるもの
- callgrind + kcachegrind
- ptrace(2)によるもの
- ltraceの-xオプション (-xで指定した自作関数に限りトレースできます。「全部」というのは指定できません)
- itrace (全行程をsingle stepするという漢のツール)
- xtrace (makeできない...。clone(2)には対応していない模様)
- GCCの -finstrument-functions を使ったもの
- pvtrace
- KLabのftrace
- etrace
- glibc‘s xtrace
- カーネルでほげる奴
- oprofile (プロファイラだが一応call treeも出せる)
- ソースコードに手を加えるもの
- CTrace
- traceString
- 未調査
- Frysk (RedHatが開発していて、Fedoraに標準で入っているツール)
- fenris?
- dude?
callgrindやoprofileはやっぱりすごいです。いろいろ。
TODO
- PIE対応
- 設定ファイル ~/.tracefrc
- --exclude (-X) オプションのregex対応
- --ff 時のファイル名の .pid の前に、スレッドなのかプロセスなのか識別できる記号をつける?
- -l 時の.debug_info読みが重い件
- gettext対応
- ftraceのコードを使わせていただいている部分(.debug_info処理)を自分で書いてみる。で、libdrawf ではなく libdw (elfutils) を使うように変更しようかな。整数型/ポインタ型以外にも対応。名前空間対応、GNU C のnested-function対応。
- ptrace関連で、vfork対応、PTRACE_O_TRACESYSGOOD 対応、singlestep成功を、DRレジスタを見て確認 (x86)
- ARM対応、x86_64対応、arch依存部分の分離
- armなLinux側ではスタブだけ動かすようにして、tracef本体はPCで動かす形にしないといかんかな。
- C++シンボルのdemanglerがヘボいかもしれない (libibertyのを使ってます。global constructors keyed to ... のdemangleなど要改善かなぁ)
- システムコールの表示をする? これはpretty print以外は簡単だけど。pritty printが難しく、かつstrace以上のものは作れないと思うのでやめとこうかな。
- utraceサポート(?)
- x86_64での-vサポート、x86_64で-m32でコンパイルしたバイナリを--pltでトレースするとエラーが発生する件の対処。
ソフトウェアの名前があんまりだ。
謝辞
- 関数の引数情報を取得する部分のコード (src/ftrace/prototype.cpp) は、ftrace-0.94のprototype.c をほぼそのまま利用させていただきました。
- src/xelf.cpp の一部は、binutils-2.18/binutils/nm.c を参考にして書きました。
- このページのソースコードのsyntax highlitingには、google-code-prettifyを利用させていただいております。
不具合の報告
SATO Yusuke <ads01002 _at_ nifty.com> までメール and/or ブログで晒してhatenaのd:id:yupo5656にTB .. など適当な感じでお願いいたします。
ChangeLog
- 2007/09/16 v0.1
- つくってみた。
- 2007/09/18 v0.11
- 関数内のret命令を全部探すようにした。
- 2007/09/19 v0.12
- weak symbolもアドレスも収集してbreakするようにした。忘れてました...。
- --plt オプションを追加。意味は --synthetic と同じ。
- 2007/09/22 v0.13
- --offsetオプション追加。
- -X で指定した関数が呼ばれた時に、ツリー表示のインデントが実際より深くなってしまう場合があるのを修正。
- 2007/09/23 v0.14
- --no-pidオプション追加。ワタシ用。
- --ff 時、process/threadのattach/detachのログをattach/detachした側(parent側)のログファイルにも書くようにした。
- 2007/10/03 v0.15
- もともと、hogetraceという名前のソフトウェアだったが、あんまりなので自重してtracefに変えた。
- 2007/10/13 v0.16
- RHEL4対応
さいごにひとこと
ptraceシステムコールで遊んだことがあまりないなぁとふと思い、作ってみました。すでに類似ツールあるかなぁと思いつつも。 もともと、arm用のLinux上で自分が使うために作りはじめたのですが、x86対応したところで連休が終わったのでとりあえず公開します。 -- 2007.09.16 さとう ゆうすけ
$Id: index.html,v 1.7 2007/10/03 05:27:02 sato Exp $
声明：以上内容来自用户投稿及互联网公开渠道收集整理发布，本网站不拥有所有权，未作人工编辑处理，也不承担相关法律责任，若内容有误或涉及侵权可进行投诉： 投诉/举报 工作人员会在5个工作日内联系你，一经查实，本站将立刻删除涉嫌侵权内容。