BSD界隈四方山話

第84回 DTraceの使い方 その4

この記事を読むのに必要な時間:およそ 5.5 分

プロセッサ:何が使われているか調べる

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時間ほどの発表資料を作成していただき発表をお願いできればと思います。

コメント

コメントの記入