以前こんなエントリを書いたが、それの perf trace 版
perf trace で --call-graph というオプションを指定する
環境
CentOS7.5 で試した
使い方
こんな感じでワラワラと コールグラフ を出しつつトレースできる
-bash-4.2$ sudo perf trace --call-graph dwarf id uid=0(root) gid=0(root) groups=0(root) 0.079 ( 0.018 ms): id/1783 brk( ) = 0x1c72000 brk (/usr/lib64/ld-2.17.so) _dl_sysdep_start (/usr/lib64/ld-2.17.so) _dl_start (/usr/lib64/ld-2.17.so) _dl_start_user (/usr/lib64/ld-2.17.so) 0.196 ( 0.024 ms): id/1783 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1 ) = 0x7fcac5a5c000 mmap64 (/usr/lib64/ld-2.17.so) __libc_memalign (/usr/lib64/ld-2.17.so) _dl_init_paths (/usr/lib64/ld-2.17.so) dl_main (/usr/lib64/ld-2.17.so) _dl_sysdep_start (/usr/lib64/ld-2.17.so) _dl_start (/usr/lib64/ld-2.17.so) _dl_start_user (/usr/lib64/ld-2.17.so) 0.270 ( 0.024 ms): id/1783 access(filename: 0xc585a0b0, mode: R ) = -1 ENOENT No such file or directory access (/usr/lib64/ld-2.17.so) dl_main (/usr/lib64/ld-2.17.so) _dl_sysdep_start (/usr/lib64/ld-2.17.so) _dl_start (/usr/lib64/ld-2.17.so) _dl_start_user (/usr/lib64/ld-2.17.so) 0.327 ( 0.020 ms): id/1783 open(filename: 0xc5858987, flags: CLOEXEC ) = 3 open64 (/usr/lib64/ld-2.17.so) _dl_sysdep_read_whole_file (/usr/lib64/ld-2.17.so) _dl_load_cache_lookup (/usr/lib64/ld-2.17.so) _dl_map_object (/usr/lib64/ld-2.17.so) openaux (/usr/lib64/ld-2.17.so) _dl_catch_error (/usr/lib64/ld-2.17.so) _dl_map_object_deps (/usr/lib64/ld-2.17.so) dl_main (/usr/lib64/ld-2.17.so) _dl_sysdep_start (/usr/lib64/ld-2.17.so) _dl_start (/usr/lib64/ld-2.17.so) _dl_start_user (/usr/lib64/ld-2.17.so) 0.365 ( 0.013 ms): id/1783 fstat(fd: 3, statbuf: 0x7ffd78c913a0 ) = 0 _fxstat (/usr/lib64/ld-2.17.so) _dl_sysdep_read_whole_file (/usr/lib64/ld-2.17.so) _dl_load_cache_lookup (/usr/lib64/ld-2.17.so) _dl_map_object (/usr/lib64/ld-2.17.so) openaux (/usr/lib64/ld-2.17.so) _dl_catch_error (/usr/lib64/ld-2.17.so) _dl_map_object_deps (/usr/lib64/ld-2.17.so) dl_main (/usr/lib64/ld-2.17.so) _dl_sysdep_start (/usr/lib64/ld-2.17.so) _dl_start (/usr/lib64/ld-2.17.so) _dl_start_user (/usr/lib64/ld-2.17.so)
--pf min と併用する
--pf min と併用すると、マイナーページフォルトが起きた箇所のコールグラフも出せる
-bash-4.2$ sudo perf trace --pf min --call-graph fp id ... 8.226 ( 0.000 ms): id/1831 minfault [getpwuid+0x0] => /usr/lib64/libc-2.17.so@0xbdbf0 (x.) getpwuid (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.236 ( 0.000 ms): id/1831 minfault [getpwuid_r@@GLIBC_2.2.5+0x0] => /usr/lib64/libc-2.17.so@0xbe3d0 (x.) getpwuid_r@@GLIBC_2.2.5 (/usr/lib64/libc-2.17.so) 8.372 ( 0.000 ms): id/1831 minfault [getpwuid_r@@GLIBC_2.2.5+0x14] => //anon@0x7fcb3b777150 (d.) getpwuid_r@@GLIBC_2.2.5 (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.383 ( 0.000 ms): id/1831 minfault [__nscd_getpwuid_r+0x0] => /usr/lib64/libc-2.17.so@0x12d990 (x.) __nscd_getpwuid_r (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.392 ( 0.000 ms): id/1831 minfault [_itoa_word+0x0] => /usr/lib64/libc-2.17.so@0x46e20 (x.) _itoa_word (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.400 ( 0.000 ms): id/1831 minfault [__nscd_get_map_ref+0x0] => /usr/lib64/libc-2.17.so@0x130be0 (x.) __nscd_get_map_ref (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.408 ( 0.000 ms): id/1831 minfault [__GI___socket+0x0] => /usr/lib64/libc-2.17.so@0xf94c0 (x.) __GI___socket (/usr/lib64/libc-2.17.so) __nscd_get_mapping (/usr/lib64/libc-2.17.so) __nscd_get_map_ref (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.416 ( 0.012 ms): id/1831 socket(family: LOCAL, type: STREAM|CLOEXEC|NONBLOCK ) = 3 __GI___socket (/usr/lib64/libc-2.17.so) __nscd_get_mapping (/usr/lib64/libc-2.17.so) __nscd_get_map_ref (/usr/lib64/libc-2.17.so) [0] ([unknown]) 8.436 ( 0.020 ms): id/1831 connect(fd: 3, uservaddr: 0x7ffdb1cb1f50, addrlen: 110 ) = -1 ENOENT No such file or directory __GI___libc_connect (/usr/lib64/libc-2.17.so) __nscd_get_mapping (/usr/lib64/libc-2.17.so) __nscd_get_map_ref (/usr/lib64/libc-2.17.so) [0] ([unknown])
これはよい! production 環境でメモリリークしているプロセスがいる ... といったシチュエーションで強力な武器になりそうだ
カーネルモードのバックトレースもとれている. read(2) の際にデータをカーネル空間 -> ユーザ空間 へコピーする際に起きるマイナーページフォルトも捉えてくれている
43.585 ( 0.021 ms): id/1889 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1 ) = 0x7f859a044000 __mmap64 (/usr/lib64/libc-2.17.so) 43.644 ( 0.000 ms): id/1889 minfault [copy_user_generic_string+0x30] => 0x7f859a044000 (?k) 👈 copy_user_generic_string ([kernel.kallsyms]) generic_file_aio_read ([kernel.kallsyms]) xfs_file_buffered_aio_read ([kernel.kallsyms]) xfs_file_aio_read ([kernel.kallsyms]) do_sync_read ([kernel.kallsyms]) vfs_read ([kernel.kallsyms]) sys_read ([kernel.kallsyms]) tracesys ([kernel.kallsyms]) __GI___libc_read (/usr/lib64/libc-2.17.so) [0] ([unknown]) 43.624 ( 0.056 ms): id/1889 read(fd: 3, buf: 0x7f859a044000, count: 4096 ) = 1746 __GI___libc_read (/usr/lib64/libc-2.17.so) [0] ([unknown])
--help の詳細
dwarf 以外に fp lbr というのを指定できるようだが、まだ詳細は調べていない.
-bash-4.2$ sudo perf trace --call-graph Error: option `call-graph' requires a value Usage: perf trace [<options>] [<command>] or: perf trace [<options>] -- <command> [<options>] or: perf trace record [<options>] [<command>] or: perf trace record [<options>] -- <command> [<options>] --call-graph <record_mode[,record_size]> setup and enables call-graph (stack chain/backtrace): record_mode: call graph recording mode (fp|dwarf|lbr) record_size: if record_mode is 'dwarf', max size of stack recording (<bytes>) default: 8192 (bytes) Default: fp
--pf min と併用するときは fp の方が具体的に何をやっているかわかりやすい関数名を出してくれてるな. シンボルの扱いが違うんだろう
感想
ずいぶん前から対応していたのかもしれないけど、全く気がつかずに過ごしていた
