プロセッサ:何が使われているか調べる
time(1)コマンドでコマンドの実行を計測すると、そのコマンドがユーザランドで消費した時間とカーネルランドで消費した時間が表示されます。DTraceを使うと具体的にカーネルランドでどの関数が何回実行されたとか、ユーザランドでどの関数が何回実行されたとか、といった情報を得ることができます。
次のようにdtrace(1)を実行すると、計測期間中に実行されたカーネル関数とその回数を表示させることができます。
図 カーネル関数が実行された回数
# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)]=count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
kernel`uhub_read_port_status 1
kernel`intr_event_execute_handlers 1
kernel`ithread_loop 1
kernel`_mtx_trylock_flags_ 1
kernel`critical_exit 1
kernel`softclock 1
kernel`pctrie_lookup 1
kernel`selfdfree 1
kernel`ffs_sync 1
kernel`spinlock_enter 1
kernel`bcopy 1
kernel`kbdc_data_ready 1
kernel`rdtsc 1
kernel`acpi_cpu_idle 2
dtrace.ko`dtrace_state_clean 2
kernel`sched_idletd 3
kernel`uhci_interrupt 8
dtrace.ko`dtrace_dynvar_clean 17
kernel`spinlock_exit 20
kernel`acpi_cpu_c1 58753
#
次のように実行するとコマンドが使った関数の回数を表示させることができます。こっちはそれようにビルドしておかないと表示される関数名がわからないので意味が不明ですが、今はこういったことができるんだということがわかってもらえればと思います。
図 ユーザ関数が実行された回数
# dtrace -n 'profile-997hz /arg1/ { @[execname,ufunc(arg1)] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
csh libc.so.7`memset 1
dtrace 0x800cf1484 1
dtrace 0x8011aad8d 1
dtrace 0x8011b0dea 1
dtrace 0x8011b87ed 1
dtrace 0x8011ba27d 1
dtrace 0x80124bf18 1
dtrace 0x801f2453b 1
sshd libprivatessh.so.5`Fssh_channel_output_poll 1
sshd libprivatessh.so.5`Fssh_cipher_crypt 1
sshd libc.so.7`sigemptyset 1
sshd libc.so.7`__sys_getpid 1
sshd libthr.so.3`0x8037ed830 1
top 0x4078ca 1
top 0x80061552f 1
top 0x80117dc5d 1
top 0x8011b97df 1
top 0x801202347 1
top 0x801220449 1
#
FreeBSDだと次のようにスレッド名で実行回数を集計して表示させることもできます。
図 スレッド名で集計
# dtrace -n 'profile-997hz { @[stringof(curthread->td_name)] = count()}'
dtrace: description 'profile-997hz ' matched 1 probe
^C
atrun 1
irq15: ata1 1
newsyslog 1
sysctl 1
doneq0 2
irq17: mpt0 ehci0 2
mv 2
irq18: uhci0 3
irq257: vmx0 3
vmtoolsd 3
cron 5
dtrace 5
rand_harvestq 5
top 5
sshd 8
sh 9
syncer 10
swi4: clock (0) 19
idle: cpu0 36807
#
カーネルがパニックした時なんかにバックトレースが表示されることがあると思いますが、この情報はDTraceでも取得できます。どの関数がどの関数を経由して呼ばれてきたのかを調べることができます。
カーネルスタックトレースは次のようにすると表示させることができます。ここでは上位5個に表示を絞っています。
図 カーネルスタックトレースを表示
# dtrace -n 'profile-997hz { @[stack()] = count(); } END { trunc(@,5); }'
dtrace: description 'profile-997hz ' matched 2 probes
^C
CPU ID FUNCTION:NAME
0 2 :END
kernel`mnt_vnode_next_active+0x3c0
kernel`sched_sync+0x3be
kernel`fork_exit+0x85
kernel`0xffffffff80f8467e
4
kernel`spinlock_exit+0x2d
7
dtrace.ko`dtrace_dynvar_clean+0x40
kernel`intr_event_execute_handlers+0x20f
kernel`ithread_loop+0xc6
kernel`fork_exit+0x85
kernel`0xffffffff80f8467e
8
kernel`mpt_send_cmd+0x8c
kernel`xpt_action_default+0x81d
kernel`dastart+0xc5b
kernel`xpt_run_allocq+0x163
kernel`dastrategy+0xef
kernel`g_disk_start+0x34e
kernel`g_io_request+0x4a7
kernel`g_part_start+0x2a4
kernel`g_io_request+0x4a7
kernel`ufs_strategy+0x80
kernel`VOP_STRATEGY_APV+0x8d
kernel`bufstrategy+0x2c
kernel`bufwrite+0x267
kernel`vfs_bio_awrite+0x3ca
kernel`ffs_syncvnode+0x383
kernel`ffs_fsync+0x25
kernel`VOP_FSYNC_APV+0x8d
kernel`sched_sync+0x3be
kernel`fork_exit+0x85
kernel`0xffffffff80f8467e
10
kernel`acpi_cpu_c1+0x6
kernel`sched_idletd+0x3d3
kernel`fork_exit+0x85
kernel`0xffffffff80f8467e
38811
#
ユーザランドの方も同じようにスタックトーレスを表示させることができます。ユーザランドの方はそれようにビルドしておかないとスタックトレースを表示させてもちょっと意味がわからないのですが、とりあえず次のような感じで表示させることができます。
図 ユーザスタックトレースを表示
# dtrace -n 'profile-997hz { @[ustack()] = count(); } END { trunc(@,5); }'
dtrace: description 'profile-997hz ' matched 2 probes
^C
CPU ID FUNCTION:NAME
0 2 :END
0x8008aca78
0x40afd4
0x41e1d7
0x4142cd
0x41b453
0x413b42
0x40eadd
0x4093d4
0x406850
0x40600f
0x80064e000
3
libc.so.7`_write+0xa
libprivatessh.so.5`Fssh_ssh_packet_write_poll+0x3e
libprivatessh.so.5`Fssh_packet_write_poll+0x15
sshd`0x418182
sshd`0x4182a9
sshd`0x41c946
sshd`0x40ee5d
sshd`0x40c56f
ld-elf.so.1`0x800666000
4
5
18
12811
#
処理がどの経路でやってきているのか調べたいときがあったりしますが、こうやってスタックトレースを表示させると簡単にその経路を調べることができます。
※ ここに掲載したサンプルコマンドは“ DTrace Dynamic Tracing In Oracle Solaris, Mac OS X & FreeBSD” , by Brendan Gregg and Jim Mauro P.59より抜粋したものです(コマンドの実行結果はFreeBSDで実行したものを掲載しています) 。
勉強会
第60回 2月23日(木)19:00~FreeBSD勉強会
発表内容検討中。発表ネタをお持ちの方、ぜひご連絡ください。
参加申請はこちら から。
第61回 3月23日(木)19:00~リキャップ・ザ・AsiaBSDCon 2017~日本語でふりかえるABC~
2017年3月9~12日まで、東京でAsiaBSDCon 2017 が開催される予定です。ぜひこのカンファレンスにご参加いただきたいわけなのですが、なかにはどうしても仕事の都合で参加できなかったとか、正直英語がよくわからなかったとか、そういった方もいらっしゃるのではないかと思います。
3月のFreeBSD勉強会では、AsiaBSDCon 2017のあとというこのタイミングを活かして、AsiaBSDCon 2017の発表内容を振り返ってみよう、というのをやってみようと思います。AsiaBSDConに参加しているにもかかわらず、これまで一度もプロシーディングを読み返したことすらないというあなた、ぜひプロシーディングを持参してご参加ください :) AsiaBSDConに参加できなかったというあなたも、この機会をお見逃しなく(できればAsiaBSDConそのものに参加した方が絶対的によいです、あしからず) 。
FreeBSD勉強会 発表者募集
FreeBSD勉強会では発表者を募集しています。FreeBSDに関して発表を行いたい場合、@daichigoto までメッセージをお願いします。1時間半~2時間ほどの発表資料を作成していただき発表をお願いできればと思います。