概要
trace-cmdは、Linuxカーネルの機能ftraceを利用したツールであり、実行中のLinuxカーネルから関数コールスタックを取得できる。
本記事では、別のLinuxマシンにトレースデータをTCPで送ることで、lsコマンドを実行したときのカーネル関数のコールフローを取得する。
はじめに
Linuxカーネルには、デフォルトでカーネルをトレースする機能がいくつか提供されている。 ftraceはトレース機構の一つで、カーネルの実行中に実行されたさまざまな関数呼び出しに関連する情報を取得できる。
Ftrace is an internal tracer designed to help out developers and designers of systems to find what is going on inside the kernel. It can be used for debugging or analyzing latencies and performance issues that take place outside of user-space. https://www.kernel.org/doc/Documentation/trace/ftrace.txt
今回は、ftraceをユーザランドから使いやすくしたツールtrace-cmdを用いて、関数コールフローを追ってみる。
利用イメージは下記の通りとなっている。
ゲスト2で関数コールフローを採取し、同じネットワークにつながれているゲスト1へTCPでトレースデータtrace.datを取得する。
関数コールフローを採取するマシンと、トレースデータを取得するマシンを分けることで以下の利点がある。 *1
- トレースデータを一つに集約することができる
ftraceとtrace-cmdの使い方など先駆者の方のリンクにまとめられているので、そちらを参照することをオススメする。
準備
内部ネットワークの構築
仮想マシン同士を同一ネットワークでつなげる (ゲスト1: 192.168.7.11、ゲスト2: 192.168.7.12)
# -*- mode: ruby -*- # vi: set ft=ruby : Vagrant.configure("2") do |config| config.vm.box = "ubuntu/bionic64" config.vm.define "debugger" do |c| c.vm.provider "virtualbox" do |vb| vb.memory = "4096" vb.cpus = 2 end c.vm.network "private_network", ip: "192.168.7.11", virtualbox__intnet: "devnet" end config.vm.define "debuggee" do |c| c.vm.provider "virtualbox" do |vb| vb.memory = "4096" vb.cpus = 1 end c.vm.network "private_network", ip: "192.168.7.12", virtualbox__intnet: "devnet" end
前回からの記事と同様に、ゲスト1をdebugger、ゲスト2をdebuggeeと呼ぶことにする。
ftraceの設定
trace-cmdを使用するためには、ftraceが使用できることが条件となっている。 ftraceが使える条件は以下の二つが設定されていることが重要である。
- カーネルコンフィグレーションでftraceに対応している
- debugfsをマウントしている
カーネルコンフィグレーションは以下の設定が必要である。(前回の仮想マシンではデフォルトで有効化になっているので変更不要)
CONFIG_FTRACE = y
CONFIG_FUNCTION_TRACER = y
CONFIG_FUNCTION_GRAPH_TRAC = y
debugfsのマウントも確認が必要である。
debuggee:~$ mount | grep debugfs
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
trace-cmdのインストール
両方の仮想マシンにtrace-cmdをインストールする。
debuggee:~$ sudo apt install trace-cmd
debugger:~$ sudo apt install trace-cmd
トレースの取得
コマンドのトレースを取得する
ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)
debugger:~$ sudo trace-cmd listen -p 11111ゲスト2(debuggee)から
lsコマンドを実行し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送するdebuggee:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -F ls plugin 'function_graph'トレースを出力したら、ゲスト1(debugger)のトレース待ち受け状態を
^Cで解除するConnected with 192.168.7.11:40234 cpus=1 pagesize=4096 CPU0 data recorded at offset=0x4a8000 2039808 bytes in size ^C debugger:~$出力されたトレースデータ
trace.192.168.7.11:40234.datをプレーンテキスト形式trace.listに出力するdebugger:~$ sudo trace-cmd report trace.192.168.7.12\:48144.dat > trace.list出力結果の確認
debugger:~$ head -n 20 trace.list cpus=1 <...>-2278 [000] 4757.532540: funcgraph_entry: 1.148 us | mutex_unlock(); <...>-2278 [000] 4757.532541: funcgraph_entry: 0.274 us | __fsnotify_parent(); <...>-2278 [000] 4757.532541: funcgraph_entry: 0.164 us | fsnotify(); <...>-2278 [000] 4757.532542: funcgraph_entry: 0.114 us | __sb_end_write(); <...>-2278 [000] 4757.532542: funcgraph_entry: | __f_unlock_pos() { <...>-2278 [000] 4757.532542: funcgraph_entry: 0.122 us | mutex_unlock(); <...>-2278 [000] 4757.532542: funcgraph_exit: 0.341 us | } <...>-2278 [000] 4757.532544: funcgraph_entry: | __do_page_fault() { <...>-2278 [000] 4757.532544: funcgraph_entry: 0.118 us | down_read_trylock(); <...>-2278 [000] 4757.532544: funcgraph_entry: | _cond_resched() { <...>-2278 [000] 4757.532544: funcgraph_entry: 0.117 us | rcu_all_qs(); <...>-2278 [000] 4757.532545: funcgraph_exit: 0.347 us | } <...>-2278 [000] 4757.532545: funcgraph_entry: | find_vma() { <...>-2278 [000] 4757.532545: funcgraph_entry: 0.157 us | vmacache_find(); <...>-2278 [000] 4757.532545: funcgraph_exit: 0.398 us | } <...>-2278 [000] 4757.532545: funcgraph_entry: | handle_mm_fault() { <...>-2278 [000] 4757.532545: funcgraph_entry: 0.111 us | mem_cgroup_from_task(); <...>-2278 [000] 4757.532546: funcgraph_entry: | __handle_mm_fault() { <...>-2278 [000] 4757.532546: funcgraph_entry: 0.131 us | pmd_devmap_trans_unstable(); <snip>
プロセスのトレースを取得する
ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)
debugger:~$ sudo trace-cmd listen -p 11111ゲスト2(debuggee)において、トレース対象のプロセスのpidを確認する。(今回はjbd2を対象とする)
debuggee:~$ ps -e | grep jbd2 330 ? 00:00:00 jbd2/sda1-8ゲスト2(debuggee)からpidを指定し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送する
debuggee:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -P 330 plugin 'function_graph'プロセスが動作したことを確認したら、ゲスト2(debuggee)のトレース出力状態を
^Cで解除する^C debuggee:~$出力されたトレースデータ
trace.192.168.7.11:48148.datをプレーンテキスト形式trace.listに出力するConnected with 192.168.7.12:48148 cpus=1 pagesize=4096 CPU0 data recorded at offset=0x4ba000 debugger:~$ sudo trace-cmd report trace.192.168.7.12\:48148.dat > trace.list出力結果の確認
debugger:~$ head -n 20 trace.list cpus=1 <idle>-0 [000] 10069.427204: funcgraph_entry: + 12.184 us | enter_lazy_tlb(); jbd2/sda1-8-330 [000] 10069.427218: funcgraph_entry: | finish_task_switch() { jbd2/sda1-8-330 [000] 10069.427225: funcgraph_entry: | smp_irq_work_interrupt() { jbd2/sda1-8-330 [000] 10069.427226: funcgraph_entry: | irq_enter() { jbd2/sda1-8-330 [000] 10069.427226: funcgraph_entry: | rcu_irq_enter() { jbd2/sda1-8-330 [000] 10069.427227: funcgraph_entry: 0.638 us | rcu_nmi_enter(); jbd2/sda1-8-330 [000] 10069.427228: funcgraph_exit: 1.779 us | } jbd2/sda1-8-330 [000] 10069.427229: funcgraph_exit: 2.952 us | } jbd2/sda1-8-330 [000] 10069.427235: funcgraph_entry: | __wake_up() { jbd2/sda1-8-330 [000] 10069.427236: funcgraph_entry: | __wake_up_common_lock() { jbd2/sda1-8-330 [000] 10069.427236: funcgraph_entry: 0.568 us | _raw_spin_lock_irqsave(); jbd2/sda1-8-330 [000] 10069.427237: funcgraph_entry: 0.597 us | __wake_up_common(); jbd2/sda1-8-330 [000] 10069.427239: funcgraph_entry: 0.568 us | __lock_text_start(); jbd2/sda1-8-330 [000] 10069.427240: funcgraph_exit: 4.013 us | } jbd2/sda1-8-330 [000] 10069.427240: funcgraph_exit: 5.284 us | } jbd2/sda1-8-330 [000] 10069.427241: funcgraph_entry: | __wake_up() { jbd2/sda1-8-330 [000] 10069.427241: funcgraph_entry: | __wake_up_common_lock() { jbd2/sda1-8-330 [000] 10069.427242: funcgraph_entry: 0.550 us | _raw_spin_lock_irqsave(); jbd2/sda1-8-330 [000] 10069.427243: funcgraph_entry: | __wake_up_common() {
イベントのトレースを取得する
ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)
debugger:~$ sudo trace-cmd listen -p 11111ゲスト2(debuggee)からイベント
netを指定し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送する (指定できるイベントはtrace-cmd list -eで確認できる)debugger:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -e net ping -c 1 192.168.7.11 plugin 'function_graph' PING 192.168.7.11 (192.168.7.11) 56(84) bytes of data. 64 bytes from 192.168.7.11: icmp_seq=1 ttl=64 time=0.176 ms --- 192.168.7.11 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.176/0.176/0.176/0.000 msトレースを出力したら、ゲスト1(debugger)のトレース待ち受け状態を
^Cで解除するConnected with 192.168.7.12:48150 cpus=1 pagesize=4096 CPU0 data recorded at offset=0x4be000 1609728 bytes in size ^C debugger:~$出力されたトレースデータ
trace.192.168.7.11:48150.datをプレーンテキスト形式trace.listに出力するdebugger:~$ sudo trace-cmd report trace.192.168.7.12\:48150.dat > trace.list出力結果の確認
debugger:~$ head -n 20 trace.list cpus=1 <...>-2746 [000] 10875.245946: funcgraph_entry: | mutex_unlock() { <...>-2746 [000] 10875.245951: funcgraph_entry: | smp_irq_work_interrupt() { <...>-2746 [000] 10875.245951: funcgraph_entry: | irq_enter() { <...>-2746 [000] 10875.245952: funcgraph_entry: | rcu_irq_enter() { <...>-2746 [000] 10875.245952: funcgraph_entry: 0.154 us | rcu_nmi_enter(); <...>-2746 [000] 10875.245952: funcgraph_exit: 0.464 us | } <...>-2746 [000] 10875.245952: funcgraph_exit: 0.725 us | } <...>-2746 [000] 10875.245954: funcgraph_entry: | __wake_up() { <...>-2746 [000] 10875.245954: funcgraph_entry: | __wake_up_common_lock() { <...>-2746 [000] 10875.245954: funcgraph_entry: 0.121 us | _raw_spin_lock_irqsave(); <...>-2746 [000] 10875.245954: funcgraph_entry: 0.116 us | __wake_up_common(); <...>-2746 [000] 10875.245954: funcgraph_entry: 0.120 us | __lock_text_start(); <...>-2746 [000] 10875.245954: funcgraph_exit: 0.835 us | } <...>-2746 [000] 10875.245955: funcgraph_exit: 1.076 us | } <...>-2746 [000] 10875.245955: funcgraph_entry: | __wake_up() { <...>-2746 [000] 10875.245955: funcgraph_entry: | __wake_up_common_lock() { <...>-2746 [000] 10875.245955: funcgraph_entry: 0.114 us | _raw_spin_lock_irqsave(); <...>-2746 [000] 10875.245955: funcgraph_entry: 0.115 us | __wake_up_common(); <...>-2746 [000] 10875.245955: funcgraph_entry: 0.122 us | __lock_text_start(); <snip>
おわりに
今回は、カーネルのコードリーディングに役立つftrace/trace-cmdの導入方法についてまとめた。 trace-cmdでカーネルの関数コールフローを取得することで、kgdbでブレークするポイントを特定したり、Linuxカーネルのコードを効率的に読むことができる。
次回は、コードリーディングに役立つツールkprobeの紹介をしたいと思う。
変更履歴
- 2019/11/18: 記事公開
- 2022/06/05: デザイン修正
参考
- trace-cmdコマンドの使い方 - Qiita
- ftraceとtrace-cmdを使って、Linux Kernelのイベントログを簡単に取得する - グニャラくんのグニャグニャ備忘録@はてな
- Ftraceでカーネルの一部の処理を追いかける方法 - Qiita
- ftraceの使い方 - へにゃぺんて＠日々勉強のまとめ
- Linuxカーネルのデバッグでprintk(9)デバッグを卒業したいっ！ - φ(・・*)ゞ ｳｰﾝ カーネルとか弄ったりのメモ
*1:ただし、trace-cmdは採取するマシンと取得するマシンを分ける必要はない。
