perf trace で コールグラフを出す

以前こんなエントリを書いたが、それの perf trace 版

hiboma.hatenadiary.jp

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 の方が具体的に何をやっているかわかりやすい関数名を出してくれてるな. シンボルの扱いが違うんだろう

感想

ずいぶん前から対応していたのかもしれないけど、全く気がつかずに過ごしていた