ディスクIOをトレースする

KVM上のSolaris 11のデバイスツリー。

# prtconf -D
System Configuration:  Oracle Corporation  i86pc
Memory size: 1024 Megabytes
System Peripherals (Software Nodes):

i86pc (driver name: rootnex)
    scsi_vhci, instance #0 (driver name: scsi_vhci)
    pci, instance #0 (driver name: pci)
        pci1af4,1100
        isa, instance #0 (driver name: isa)
            i8042, instance #0 (driver name: i8042)
                keyboard, instance #0 (driver name: kb8042)
                mouse, instance #0 (driver name: mouse8042)
            fdc
            asy, instance #0 (driver name: asy)
            pit_beep, instance #0 (driver name: pit_beep)
        pci-ide, instance #0 (driver name: pci-ide)
            ide, instance #0 (driver name: ata)
                cmdk, instance #0 (driver name: cmdk)
            ide, instance #1 (driver name: ata)
                sd, instance #0 (driver name: sd)
        pci1af4,1100 (driver name: uhci)
        pci1af4,1100
        display, instance #0 (driver name: vgatext)
        pci1af4,1100, instance #0 (driver name: rtls)
        pci1af4,5
    fw, instance #0 (driver name: acpinex)
        sb, instance #1 (driver name: acpinex)
            cpu, instance #0 (driver name: cpudrv)
            cpu, instance #1 (driver name: cpudrv)
            cpu, instance #2 (driver name: cpudrv)
            cpu, instance #3 (driver name: cpudrv)
    used-resources
    fcoe, instance #0 (driver name: fcoe)
    iscsi, instance #0 (driver name: iscsi)
    xsvc, instance #0 (driver name: xsvc)
    vga_arbiter, instance #0 (driver name: vga_arbiter)
    options, instance #0 (driver name: options)
    pseudo, instance #0 (driver name: pseudo)

HBAドライバはataが使われている。
次にataの関数(プローブ)一覧から、HBAにパケットを送出する関数にあたりをつける。関数名にstartとかtranという名前がついている場合が多い。

# dtrace -l -m ata | grep start | grep entry
45190        fbt               ata                     ata_hba_start entry
45206        fbt               ata                     ata_start_arq entry
45264        fbt               ata                    ata_disk_start entry
45278        fbt               ata             ata_disk_start_pio_in entry
45282        fbt               ata             ata_disk_start_dma_in entry
45286        fbt               ata            ata_disk_start_pio_out entry
45290        fbt               ata            ata_disk_start_dma_out entry
45300        fbt               ata             ata_disk_start_common entry
45320        fbt               ata                  atapi_tran_start entry
45344        fbt               ata                   atapi_start_cmd entry
45348        fbt               ata                   atapi_start_dma entry
45416        fbt               ata              ata_pciide_dma_start entry
45500        fbt               ata                   atapi_fsm_start entry
45530        fbt               ata                   ghd_timer_start entry

あたりをつけた関数のスタックトレースから、その関数までのルートがわかる。

# dtrace -qn 'fbt:ata:ata_hba_start:entry { stack(); }'

              ata`ghd_waitq_process_and_mutex_hold+0xe0
              ata`ghd_waitq_process_and_mutex_exit+0x15
              ata`ghd_transport+0xbd
              ata`ata_disk_transport+0x4e
              dadk`dadk_transport+0x2d
              strategy`dmult_enque+0xbf
              dadk`dadk_strategy+0x83
              cmdk`cmdkstrategy+0x163
              genunix`default_physio+0x349
              genunix`physio+0x25
              cmdk`cmdkrw+0xb4
              cmdk`cmdkread+0x22
              genunix`cdev_read+0x4a
              specfs`spec_read+0x23a
              genunix`fop_read+0xa9
              genunix`read+0x2c9
              genunix`read32+0x22
              unix`_sys_sysenter_post_swapgs+0x149

ターゲットドライバであるcmdkのcmdkreadが、一連の処理の始まりとなる。次に、cmdkread(or cmdkstrategy)がコールされてからリターンするまでの関数をトレースする。下記のスクリプトを使ってトレースする。

#!/usr/sbin/dtrace -s

#pragma D option flowindent

fbt::$1:entry
{
        self->traceme = 1;
}

fbt:::
/self->traceme/
{}

fbt::$1:return
/self->traceme/
{
        self->traceme = 0;
}

こんな感じでどばーっと結果が出力されるのでillumosのソースブラウザなどを見ながら動作を確認する。

# ./func_trace.d cmdkread
dtrace: script './func_trace.d' matched 64679 probes
CPU FUNCTION
  0  -> cmdkread
  0    -> cmdkrw
  0      -> ddi_get_soft_state
  0      <- ddi_get_soft_state
  0      -> physio
  0        -> default_physio
  0          -> kmem_cache_alloc
  0          <- kmem_cache_alloc
  0          -> cmdkinfo
  0            -> ddi_get_soft_state
  0            <- ddi_get_soft_state
  0          <- cmdkinfo
  0          -> cmdkmin
  0          <- cmdkmin
    :
    :
  0            <- segvn_pagelock
  0          <- as_pageunlock
  0          -> kmem_cache_free
  0          <- kmem_cache_free
  0        <- default_physio
  0      <- physio
  0    <- cmdkrw
  0  <- cmdkread

あと非同期IOは、完了がデバイス割り込みで上がってくる。ハンドルされているata_intrと、デバイス割り込みからトリガーされるソフトウェア割り込みにハンドルされているghd_doneq_processなどをトレースしてみるとよい。