プロセッサ：何が使われているか調べる
time(1)コマンドでコマンドの実行を計測すると、
次のように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
#
カーネルがパニックした時なんかにバックトレースが表示されることがあると思いますが、
カーネルスタックトレースは次のようにすると表示させることができます。ここでは上位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
#
処理がどの経路でやってきているのか調べたいときがあったりしますが、
※ ここに掲載したサンプルコマンドは
勉強会
第60回 2月23日（木）19:00～FreeBSD勉強会
発表内容検討中。発表ネタをお持ちの方、
参加申請はこちらから。
第61回 3月23日（木）19:00～リキャップ・ザ・AsiaBSDCon 2017～日本語でふりかえるABC～
2017年3月9～12日まで、
3月のFreeBSD勉強会では、
FreeBSD勉強会 発表者募集
FreeBSD勉強会では発表者を募集しています。FreeBSDに関して発表を行いたい場合、