はじめに
少し前に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
