trace-cmd は、カーネル関数をトレースするための、使いやすく機能豊富なコマンドです。
記事では、ftraceを使ってカーネル関数をトレースする方法を説明しました。ファイルに書き込んだりファイルから読み込んだりしてftraceを使うのは面倒なので、トレースの有効化・無効化、フィルターの設定、出力の表示、出力のクリアなどのオプションを持つコマンドを実行するためのラッパーを作りました。
trace-cmd のインストール
この記事のコマンドはすべてrootユーザーで実行されます。
ftraceメカニズムはカーネルに組み込まれているので、以下のコマンドで有効になっていることを確認できます:
# mount | grep tracefsnone on /sys/kernel/tracing type tracefs (rw,relatime,seclabel)
しかし、手動で trace-cmd コマンドをインストールしようとする必要があります:
# dnf install trace-cmd -y
利用可能なトラッカーのリスト
ftrace を使用する場合、どのトレーサーが使用可能かを確認するには、ファイルの中身を見なければなりません。しかし、trace-cmd を使えば、次のようにしてこの情報を得ることができます。
# trace-cmd list -thwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
ファンクショントラッカーの有効化
私の 記事 2つのトラッカーを使いましたが、ここでも同じようにします。最初のトラッカーを関数で有効にします:
$ trace-cmd start -p functionplugin 'function'
トレース出力の表示
トラッカーを有効にすると、show パラメーターを使って出力を見ることができます。例を短くするため、最初の20行のみを表示します:
# trace-cmd show | head -20## tracer: function# entries-in-buffer/entries-written: 80032 #P:8# _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# / _--=> preempt-depth# / delay# TASK-PID CPU# TIMESTAMP FUNCTION# | | | | |gdbus-2606 ..s. 8759: __msecs_to_jiffies <-rebalance_domainsgdbus-2606 ..s. 8760: load_balance <-rebalance_domainsgdbus-2606 ..s. 8761: idle_cpu <-load_balancegdbus-2606 ..s. 8762: group_balance_cpu <-load_balancegdbus-2606 ..s. 8762: find_busiest_group <-load_balancegdbus-2606 ..s. 8763: update_group_capacity <-update_sd_lb_stats.constprop.0gdbus-2606 ..s. 8763: __msecs_to_jiffies <-update_group_capacitygdbus-2606 ..s. 8765: idle_cpu <-update_sd_lb_stats.constprop.0gdbus-2606 ..s. 8766: __msecs_to_jiffies <-rebalance_domains
トラッキングを停止し、バッファをクリアします。
トレースはバックグラウンドで実行され続け、showで出力を見続けることができます。
トラッキングを停止するには、stopパラメータを付けて trace-cmd コマンドを実行します:
# trace-cmd stop
バッファをクリアするには、 clear パラメータを指定して実行します:
# trace-cmd clear
関数呼び出しグラフの追跡を有効にします。
2番目のトラッカーを実行し、 function_graph パラメータで有効にします。
# trace-cmd start -p function_graphPlugin 'function_graph'
出力を表示するには、show パラメータを再度使用します。予想通り、出力は最初のトレース出力とは少し異なります。今回は、関数呼び出しの連鎖が含まれています:
# trace-cmd show | head -20## tracer: function_graph# CPU DURATION FUNCTION CALLS# | | | | | | |4) 0.079 us | } /* rcu_all_qs */4) 0.327 us | } /* __cond_resched */4) 0.081 us | rcu_read_unlock_strict();4) | __cond_resched() {4) 0.078 us | rcu_all_qs();4) 0.243 us | }4) 0.080 us | rcu_read_unlock_strict();4) | __cond_resched() {4) 0.078 us | rcu_all_qs();4) 0.241 us | }4) 0.080 us | rcu_read_unlock_strict();4) | __cond_resched() {4) 0.079 us | rcu_all_qs();4) 0.235 us | }4) 0.095 us | rcu_read_unlock_strict();4) | __cond_resched() {
トレースを停止し、バッファをクリアするには、stopコマンドとclearコマンドを使用します:
# trace-cmd stop# trace-cmd clear
深さを増すためにトラッキングを調整
関数コールをもっと深く見たい場合は、トラッカーを微調整することができます:
# trace-cmd start -p function_graph --max-graph-depth 5plugin 'function_graph'
さて、この出力とあなたが見ているものを比較すると、より多くのネストされた関数呼び出しが見えるはずです:
# trace-cmd show | head -20## tracer: function_graph# CPU DURATION FUNCTION CALLS# | | | | | | |6) | __fget_light() {6) 0.804 us | __fget_files();6) 2.708 us | }6) 3.650 us | } /* __fdget */6) 0.547 us | eventfd_poll();6) 0.535 us | fput();6) | __fdget() {6) | __fget_light() {6) 0.946 us | __fget_files();6) 1.895 us | }6) 2.849 us | }6) | sock_poll() {6) 0.651 us | unix_poll();6) 1.905 us | }6) 0.475 us | fput();6) | __fdget() {
トレーサブル・ファンクションの理解
特定の関数だけを追跡し、他の関数を無視したい場合は、正確な関数名を知る必要があります。list -f 引数で取得できます。例えば、一般的なカーネル関数 kmalloc を検索してください:
# trace-cmd list -f | grep kmallocbpf_map_kmalloc_nodemempool_kmalloc__traceiter_kmalloc__traceiter_kmalloc_nodekmalloc_slabkmalloc_orderkmalloc_order_tracekmalloc_large_node__kmalloc__kmalloc_track_caller__kmalloc_node__kmalloc_node_track_caller
# trace-cmd list -f | wc -l
カーネルモジュール関連関数のトレース
特定のカーネルモジュールに関連する関数をトレースすることもできます。kvmカーネルモジュールに関連する関数をトレースしたいとします。モジュールがロードされていることを確認してください:
# lsmod | grep kvm_intelkvm_intelkvm kvm_intel
引数 list を使って trace-cmd を再度実行し、出力から [] で終わる行を grep してください。これでカーネルモジュールがフィルタリングされます。次に、カーネルモジュールkvm_intelをgrepすると、そのカーネルモジュールに関連するすべての関数が表示されます。
# trace-cmd list -f | grep ]$ | grep kvm_intelvmx_can_emulate_instruction [kvm_intel]vmx_update_emulated_instruction [kvm_intel]vmx_setup_uret_msr [kvm_intel]vmx_set_identity_map_addr [kvm_intel]handle_machine_check [kvm_intel]handle_triple_fault [kvm_intel]vmx_patch_hypercall [kvm_intel]vmx_dump_dtsel [kvm_intel]vmx_dump_sel [kvm_intel]
特定機能のトレース
startパラメータでコマンドを実行する代わりに、recordパラメータにトレースしたい関数の "mode "を追加します。この場合、function_graphで、Ctrl+Cで止めるまでトレースを記録し続けます。数秒後、Ctrl+Cでトレースを停止してください:
# trace-cmd list -f | grep ^ext4_# trace-cmd record -l ext4_* -p function_graphplugin 'function_graph'Hit Ctrl^C to stop recordingCPU0 data recorded at offset=0x8192 bytes in size
トラッキング記録の表示
トレース履歴を見るには、report パラメータを指定してコマンドを実行してください。出力から、フィルターが機能しており、ext4関連の関数のトレースだけが表示されていることがわかります:
# trace-cmd report | head -20trace-cmd-.: funcgraph_entry: | ext4_show_options() {trace-cmd-.: funcgraph_entry: 0.187 us | ext4_get_dummy_policy();trace-cmd-.: funcgraph_exit: 1.583 us | }trace-cmd-.: funcgraph_entry: | ext4_create() {trace-cmd-.: funcgraph_entry: | ext4_alloc_inode() {trace-cmd-.: funcgraph_entry: 0.101 us | ext4_es_init_tree();trace-cmd-.: funcgraph_entry: 0.083 us | ext4_init_pending_tree();trace-cmd-.: funcgraph_entry: 0.141 us | ext4_fc_init_inode();trace-cmd-.: funcgraph_exit: 0.931 us | }trace-cmd-.: funcgraph_entry: 0.081 us | ext4_get_dummy_policy();trace-cmd-.: funcgraph_entry: 0.133 us | ext4_get_group_desc();trace-cmd-.: funcgraph_entry: 0.115 us | ext4_free_inodes_count();trace-cmd-.: funcgraph_entry: 0.114 us | ext4_get_group_desc();
特定のPIDを追跡
あるプロセスに関連する関数をトレースしたいとします。別のターミナルを開き、実行中のシェルの PID を記録します:
# echo $$
recordコマンドをもう一度実行し、-PオプションでPIDを渡します:
# trace-cmd record -P 10885 -p function_graphPlugin 'function_graph'Hit Ctrl^C to stop recording
シェルでコマンドを実行
特定のPIDでシェルを実行している別のターミナルに移動し、任意のコマンド、例えばファイルを一覧表示するlsコマンドを実行します:
Temp-9b-fdc1--5cd207tracker-extract-3-files.0010v8-compile-cache-0010
トラッキングを有効にした端末に移動し、 Ctrl+C トラッキングを停止します:
# trace-cmd record -P 10885 -p function_graphplugin 'function_graph'Hit Ctrl^C to stop recordingCPU1 data recorded at offset=0xbytes in size
トレースの出力では、左側にPIDとBashシェル、右側にそれに関連する関数コールを見ることができます。これはトレースを絞り込むのにとても便利です:
# trace-cmd report | head -20<idle>-0 0581: funcgraph_entry: | switch_mm_irqs_off() {<idle>-0 0583: funcgraph_entry: 1.703 us | load_new_mm_cr3();<idle>-0 0586: funcgraph_entry: 0.493 us | switch_ldt();<idle>-0 0587: funcgraph_exit: 7.235 us | }bash-.: funcgraph_entry: 1.046 us | finish_task_switch.isra.0();bash-.: funcgraph_entry: | __fdget() {bash-.: funcgraph_entry: 2.036 us | __fget_light();bash-.: funcgraph_exit: 3.256 us | }bash-.: funcgraph_entry: | tty_poll() {bash-.: funcgraph_entry: | tty_ldisc_ref_wait() {bash-.: funcgraph_entry: | ldsem_down_read() {bash-.: funcgraph_entry: | __cond_resched() {
試してみてください。
これらの短い例は、基本的な ftrace メカニズムではなく trace-cmd コマンドを使うことで、いかに使いやすく、機能が豊富であるか、この記事ではカバーしきれない部分が多いかを示しています。より多くの情報と、より上手に使うためには、マニュアルを参照し、他の便利なコマンドを試してみてください。





