読者です 読者をやめる 読者になる 読者になる

のぴぴのメモ

自分用のLinuxとかの技術メモ

(ftrace)trace-cmdでfunction_graphを使ってみる

はじめに

少し前にid:yohei-aさんに、Brendan Greggさんのfuncgraphを教わり、中身がシェルだったので、そのシェルでftraceの使い方が少し解りました。ありがとうございます。

今回は、funcgraphと同じ事をtrace-cmdコマンドで実現する方法をまとめます。(trace-cmdのfunction_graphを使います。)

ftraceを使うためのセットアップ

(1)kenelのリビルド

不要です。最近のディストリビューションは全てftraceがONになっています。少なくとも、RHEL6、Fedora22、ubuntu14.04では不要でした。

(2)debugfsの/sys/kernel/debugへのマウント

不要です。trace-cmdコマンド実行時に自動的にマウントしてくれます。

(3)trace-cmdのインストール。

trace-cmdコマンドがなかったら、yumやapt-getコマンドで、trace-cmdをインストールしてください。

■Fedora/RHEL
# yum install trace-cmd
■ubuntu
# apt-get install trace-cmd

trace-cmdを使う

基本的な使い方(trace-cmdからコマンドを実行する)

# trace-cmd record -p function_graph -g [トレースするfunction] コマンド
# trace-cmd report > trace.log
  • "trace-cmd record"でコマンドを実行しトレースを取得します。
  • "-g"オプションで取得したい関数を指定します。
    • 指定可能な関数は"/sys/kernel/debug/tracing/available_filter_functions"で確認できます。
    • 複数関数を指定する場合は、"-g"オプションを複数指定します。
  • トレース取得データは、デフォルトではカレントディレクトリのtrace.datになります。

実行例

# trace-cmd record -p function_graph -g SyS_mmap -g SyS_brk ls
  plugin 'function_graph'
a.log  a.out  ltrace.log  mem.c  test_ftrace.dat  trace.dat  trace.dat.cpu0  trace.dat.cpu1
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 1764
oldest event ts: 17309.292890
now ts: 17309.295092
dropped events: 0
read events: 7450

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 0
oldest event ts: 16818.044541
now ts: 17309.295277
dropped events: 0
read events: 0

CPU0 data recorded at offset=0x4e6000
    303104 bytes in size
CPU1 data recorded at offset=0x530000
    0 bytes in size

# trace-cmd report -t > trace.log

取得した結果(trace.log)

version = 6
CPU 1 is empty
cpus=2
              ls-10862 [000] 17309.286563606: funcgraph_entry:                   |  SyS_brk() {
              ls-10862 [000] 17309.286588309: funcgraph_entry:                   |    down_write() {
              ls-10862 [000] 17309.286589501: funcgraph_entry:        0.231 us   |      _cond_resched();
              ls-10862 [000] 17309.286591455: funcgraph_exit:         2.024 us   |    }
              ls-10862 [000] 17309.286592097: funcgraph_entry:        0.200 us   |    up_write();
              ls-10862 [000] 17309.286593610: funcgraph_exit:         5.743 us   |  }
              ls-10862 [000] 17309.286665524: funcgraph_entry:                   |  SyS_mmap() {
              ls-10862 [000] 17309.286666667: funcgraph_entry:                   |    sys_mmap_pgoff() {
              ls-10862 [000] 17309.286667488: funcgraph_entry:                   |      vm_mmap_pgoff() {
              ls-10862 [000] 17309.286668370: funcgraph_entry:                   |        security_mmap_file() {
              ls-10862 [000] 17309.286669192: funcgraph_entry:                   |          apparmor_mmap_file() {
              ls-10862 [000] 17309.286669904: funcgraph_entry:        0.201 us   |            common_mmap();
              ls-10862 [000] 17309.286671417: funcgraph_exit:         1.613 us   |          }
              ls-10862 [000] 17309.286672048: funcgraph_entry:        0.170 us   |          ima_file_mmap();
              ls-10862 [000] 17309.286673511: funcgraph_exit:         4.520 us   |        }
<以下略>

実行中のプロセスのトレースを取得する

実行中のプロセスのトレースを取得する場合は、"-P"オプションで取得したいプロセスのPIDを指定します。

# trace-cmd record -p function_graph -g [トレースするfunction] -P PID
# trace-cmd report > trace.log

実行例

# trace-cmd record -p function_graph -g SyS_mmap -g SyS_brk -P 10894
  plugin 'function_graph'
Hit Ctrl^C to stop recording
<取得が終了したら、Ctrl+Cで中止する>
^CKernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 2580
oldest event ts: 17631.193419
now ts: 17634.029942
dropped events: 0
read events: 166

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 0
oldest event ts: 16818.044541
now ts: 17634.030212
dropped events: 0
read events: 0

CPU0 data recorded at offset=0x4e6000
    8192 bytes in size
CPU1 data recorded at offset=0x4e8000
    0 bytes in size

# trace-cmd report -t > trace.log