ftraceについての勉強メモ

ftraceとは

Linuxカーネルに組み込まれているトレース機構。
動作中のカーネルのイベントを記録し、ログとして採取することができる。

使い方

主な使い方は以下

1. debugfs
debugfsを経由して使用。
debugfsをマウント。

# mount debugfs /sys/kernel/debug

/sys/kernel/debug/tracing配下に、
traceで使用するファイルがマウントされる。

# ls /sys/kernel/debug/tracing/
available_events            buffer_total_size_kb   events                    kprobe_events   printk_formats       set_event           snapshot            trace          trace_pipe           tracing_on
available_filter_functions  current_tracer         free_buffer               kprobe_profile  README               set_ftrace_filter   stack_max_size      trace_clock    trace_stat           tracing_thresh
available_tracers           dyn_ftrace_total_info  function_profile_enabled  options         saved_cmdlines       set_ftrace_notrace  stack_trace         trace_marker   tracing_cpumask      uprobe_events
buffer_size_kb              enabled_functions      instances                 per_cpu         saved_cmdlines_size  set_ftrace_pid      stack_trace_filter  trace_options  tracing_max_latency  uprobe_profile

各ファイルの説明はlinux/Documentation/trace/ftrace.txtに記載。
available_tracerから現在利用可能なトレーサを参照可能。

#  /sys/kernel/debug/tracing/available_tracers
blk mmiotrace wakeup_dl wakeup_rt wakeup function nop

current_tracerにトレーサを登録。

# echo function > /sys/kernel/debug/tracing/current_tracer

トレース開始

# echo 1 > /sys/kernel/debug/tracing/tracing_on

監視したいプロセスがあれば実行。

# ./execute_process

トレース終了

# echo 0 > /sys/kernel/debug/tracing/tracing_on

トレースログを採取して確認。

# cat /sys/kernel/debug/tracing/trace_pipe > trace.log
# cat trace.log
CPU:0 [LOST 487966 EVENTS]
          <idle>-0     [000] dN..  6128.249396: ktime_get <-clockevents_program_event
          <idle>-0     [000] dN..  6128.249397: lapic_next_deadline <-clockevents_program_event
          <idle>-0     [000] dN..  6128.249400: _raw_spin_unlock_irqrestore <-hrtimer_start_range_ns
          <idle>-0     [000] dN..  6128.249400: _raw_write_unlock_irqrestore <-_raw_spin_unlock_irqrestore
          <idle>-0     [000] dN..  6128.249401: account_idle_ticks <-tick_nohz_idle_exit
...

2. trace-cmdコマンド
trace-cmdのインストール

# yum install trace-cmd

recordオプションを指定して実行すると、イベントを記録する。

# trace-cmd record -p function
  plugin 'function'
Hit Ctrl^C to stop recording
^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: 3883424
commit overrun: 0
bytes: 3960
oldest event ts:  6437.427336
now ts:  6437.435387
dropped events: 0
read events: 12180017

CPU0 data recorded at offset=0x306000

    244555776 bytes in size

実行後、カレントディレクトリにtrace.datが作成される。

# ls
trace.dat

カレントディレクトリにtrace.datがあれば、
reportオプションでトレース結果を確認できる。

# trace-cmd report | less
version = 6
cpus=1
       trace-cmd-4102  [000]  6431.748176: function:             mutex_unlock
       trace-cmd-4102  [000]  6431.748177: function:             __fsnotify_parent
       trace-cmd-4102  [000]  6431.748177: function:             fsnotify
       trace-cmd-4102  [000]  6431.748177: function:                __srcu_read_lock
       trace-cmd-4102  [000]  6431.748178: function:                __srcu_read_unlock
       trace-cmd-4102  [000]  6431.748178: function:             __sb_end_write
       trace-cmd-4102  [000]  6431.748178: function:             mutex_unlock
       trace-cmd-4102  [000]  6431.748179: function:             SyS_fstat64
       trace-cmd-4102  [000]  6431.748180: function:                vfs_fstat
       trace-cmd-4102  [000]  6431.748180: function:                   __fdget_raw
       trace-cmd-4102  [000]  6431.748180: function:                      __fget_light
       trace-cmd-4102  [000]  6431.748180: function:                   vfs_getattr
       trace-cmd-4102  [000]  6431.748180: function:                      security_inode_getattr
       trace-cmd-4102  [000]  6431.748180: function:                         selinux_inode_getattr
       trace-cmd-4102  [000]  6431.748180: function:                            avc_has_perm
       trace-cmd-4102  [000]  6431.748181: function:                      vfs_getattr_nosec
       trace-cmd-4102  [000]  6431.748181: function:                         generic_fillattr
       trace-cmd-4102  [000]  6431.748181: function:                cp_new_stat64
       trace-cmd-4102  [000]  6431.748181: function:                   from_kuid_munged
       trace-cmd-4102  [000]  6431.748181: function:                   from_kgid_munged
       trace-cmd-4102  [000]  6431.748181: function:                   _copy_to_user
       trace-cmd-4102  [000]  6431.748181: function:                      __copy_from_user_ll_nozero
...

3. kernelshark(GUI)
trace-cmdの出力結果をグラフィカルに表示する。
CLIでは使わない。

参考

linux/Documentation/trace/ftrace.txt
(株)日立製作所 横浜研究所　"ftraceの解説と最近の動向"
http://www.hitachi.co.jp/rd/portal/contents/research/itp_06/pdf/kernelvm8th_ftrace-1.pdf
グニャラくんのグニャグニャ備忘録@はてな
"ftraceとtrace-cmdを使って、Linux Kernelのイベントログを簡単に取得する"
http://d.hatena.ne.jp/tasukuchan/20100516/lets_use_ftrace_with_trace_cmd