例
以下は、入出力要求が発行されるたびに関連情報を出力するスクリプトです。
#pragma D option quiet
BEGIN
{
printf("%10s %58s %2s\n", "DEVICE", "FILE", "RW");
}
io:::start
{
printf("%10s %58s %2s\n", args[1]->dev_statname,
args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W");
}
x86 ラップトップシステム上で Acrobat Reader をコールドスタートした場合、次のような出力が得られます。
# dtrace -s ./iosnoop.d
DEVICE FILE RW
cmdk0 /opt/Acrobat4/bin/acroread R
cmdk0 /opt/Acrobat4/bin/acroread R
cmdk0 <unknown> R
cmdk0 /opt/Acrobat4/Reader/AcroVersion R
cmdk0 <unknown> R
cmdk0 <unknown> R
cmdk0 <none> R
cmdk0 <unknown> R
cmdk0 <none> R
cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R
cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R
cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R
cmdk0 <none> R
cmdk0 <unknown> R
cmdk0 <unknown> R
cmdk0 <unknown> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 <none> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 <unknown> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 <none> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R
cmdk0 <unknown> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R
cmdk0 <none> R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R
cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R
...
|
入出力が特定のファイル内のデータに関連していない場合、<none> エントリが出力されています。 これらの入出力は、任意の書式のメタデータ用です。ファイルのパス名が未知である場合、<unknown> エントリが出力されています。このような事態はめったに発生しません。
連想配列を使って各入出力の所要時間を追跡することにより、上のスクリプト例を少し複雑にすることもできます。次の例を参照してください。
#pragma D option quiet
BEGIN
{
printf("%10s %58s %2s %7s\n", "DEVICE", "FILE", "RW", "MS");
}
io:::start
{
start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}
io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
printf("%10s %58s %2s %3d.%03d\n", args[1]->dev_statname,
args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W",
this->elapsed / 10000000, (this->elapsed / 1000) % 1000);
start[args[0]->b_edev, args[0]->b_blkno] = 0;
}
アイドル状態の x86 ラップトップシステム上で上記スクリプト例を実行し、USB ストレージデバイスを差し込むと、次のような出力が得られます。
# dtrace -s ./iotime.d
DEVICE FILE RW MS
cmdk0 /kernel/drv/scsa2usb R 24.781
cmdk0 /kernel/drv/scsa2usb R 25.208
cmdk0 /var/adm/messages W 25.981
cmdk0 /kernel/drv/scsa2usb R 5.448
cmdk0 <none> W 4.172
cmdk0 /kernel/drv/scsa2usb R 2.620
cmdk0 /var/adm/messages W 0.252
cmdk0 <unknown> R 3.213
cmdk0 <none> W 3.011
cmdk0 <unknown> R 2.197
cmdk0 /var/adm/messages W 2.680
cmdk0 <none> W 0.436
cmdk0 /var/adm/messages W 0.542
cmdk0 <none> W 0.339
cmdk0 /var/adm/messages W 0.414
cmdk0 <none> W 0.344
cmdk0 /var/adm/messages W 0.361
cmdk0 <none> W 0.315
cmdk0 /var/adm/messages W 0.421
cmdk0 <none> W 0.349
cmdk0 <none> R 1.524
cmdk0 <unknown> R 3.648
cmdk0 /usr/lib/librcm.so.1 R 2.553
cmdk0 /usr/lib/librcm.so.1 R 1.332
cmdk0 /usr/lib/librcm.so.1 R 0.222
cmdk0 /usr/lib/librcm.so.1 R 0.228
cmdk0 /usr/lib/librcm.so.1 R 0.927
cmdk0 <none> R 1.189
...
cmdk0 /usr/lib/devfsadm/linkmod R 1.110
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_audio_link.so R 1.763
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_audio_link.so R 0.161
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_cfg_link.so R 0.819
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_cfg_link.so R 0.168
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_disk_link.so R 0.886
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_disk_link.so R 0.185
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_fssnap_link.so R 0.778
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_fssnap_link.so R 0.166
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_lofi_link.so R 1.634
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_lofi_link.so R 0.163
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_md_link.so R 0.477
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_md_link.so R 0.161
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.198
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.168
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.247
cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link_i386.so R 1.735
...
|
この出力から、このシステムの力学についてさまざまな観察が可能です。まず、最初のいくつかの入出力の実行に長い時間がかかっていること (それぞれの所要時間は約 25 ミリ秒) に注目します。これは、cmdk0 デバイスがラップトップによって電源管理されていたためと考えられます。次に、USB 大容量記憶装置の処理のため scsa2usb(7D) ドライバがロードされた際の入出力を観察します。さらに、この装置が報告される時点で、/var/adm/messages への書き込みが発生していることに注目します。最後に、デバイスリンクジェネレータ (ファイル名の末尾が link.so のファイル) の読み取りを観察します。デバイスリンクジェネレータは、新しく接続されたデバイスを処理していると考えられます。
io プロバイダを使用すると、iostat(1M) 出力について詳しい情報を得ることができます。次の例のような iostat 出力を調べるとします。
extended device statistics device r/s w/s kr/s kw/s wait actv svc_t %w %b cmdk0 8.0 0.0 399.8 0.0 0.0 0.0 0.8 0 1 sd0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 sd2 0.0 109.0 0.0 435.9 0.0 1.0 8.9 0 97 nfs1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 nfs2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 |
iotime.d スクリプトを使用して、次の例のように、入出力が行われるたびに確認できます。
DEVICE FILE RW MS
sd2 /mnt/archives.tar W 0.856
sd2 /mnt/archives.tar W 0.729
sd2 /mnt/archives.tar W 0.890
sd2 /mnt/archives.tar W 0.759
sd2 /mnt/archives.tar W 0.884
sd2 /mnt/archives.tar W 0.746
sd2 /mnt/archives.tar W 0.891
sd2 /mnt/archives.tar W 0.760
sd2 /mnt/archives.tar W 0.889
cmdk0 /export/archives/archives.tar R 0.827
sd2 /mnt/archives.tar W 0.537
sd2 /mnt/archives.tar W 0.887
sd2 /mnt/archives.tar W 0.763
sd2 /mnt/archives.tar W 0.878
sd2 /mnt/archives.tar W 0.751
sd2 /mnt/archives.tar W 0.884
sd2 /mnt/archives.tar W 0.760
sd2 /mnt/archives.tar W 3.994
sd2 /mnt/archives.tar W 0.653
sd2 /mnt/archives.tar W 0.896
sd2 /mnt/archives.tar W 0.975
sd2 /mnt/archives.tar W 1.405
sd2 /mnt/archives.tar W 0.724
sd2 /mnt/archives.tar W 1.841
cmdk0 /export/archives/archives.tar R 0.549
sd2 /mnt/archives.tar W 0.543
sd2 /mnt/archives.tar W 0.863
sd2 /mnt/archives.tar W 0.734
sd2 /mnt/archives.tar W 0.859
sd2 /mnt/archives.tar W 0.754
sd2 /mnt/archives.tar W 0.914
sd2 /mnt/archives.tar W 0.751
sd2 /mnt/archives.tar W 0.902
sd2 /mnt/archives.tar W 0.735
sd2 /mnt/archives.tar W 0.908
sd2 /mnt/archives.tar W 0.753
|
この出力からは、archives.tar というファイルが、cmdk0 によって (/export/archives で) 読み取られており、またデバイス sd2 へ (/mnt で) 書き込まれているかのように見えます。しかし、archives.tar という名前のファイルが 2 つ存在し、並行して別々に処理されるということは通常ありえません。さらに詳しく調べたい場合は、デバイス、アプリケーション、プロセス ID、および転送バイト数を集積します。次の例を参照してください。
#pragma D option quiet
io:::start
{
@[args[1]->dev_statname, execname, pid] = sum(args[0]->b_bcount);
}
END
{
printf("%10s %20s %10s %15s\n", "DEVICE", "APP", "PID", "BYTES");
printa("%10s %20s %10d %15@d\n", @);
}
このスクリプトを数秒間実行すると、次のような出力が得られます。
# dtrace -s ./whoio.d
^C
DEVICE APP PID BYTES
cmdk0 cp 790 1515520
sd2 cp 790 1527808
|
出力から、このアクティビティが、あるデバイスから別のデバイスへの archives.tar ファイルのコピーであったことがわかります。このことから別の疑問が自然にわいてきます: 一方のデバイスの速度がもう一方のデバイスよりも高速なのでしょうか。 コピーするときはどちらのデバイスがリミッタになるのでしょうか。こうした問題に答えるには、各デバイスの秒当たりの転送バイト数より、各デバイスの有効なスループットを把握する必要があります。スループットを特定するには、次のようなスクリプトを使用します。
#pragma D option quiet
io:::start
{
start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}
io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
/*
* We want to get an idea of our throughput to this device in KB/sec.
* What we have, however, is nanoseconds and bytes. That is we want
* to calculate:
*
* bytes / 1024
* ------------------------
* nanoseconds / 1000000000
*
* But we can't calculate this using integer arithmetic without losing
* precision (the denomenator, for one, is between 0 and 1 for nearly
* all I/Os). So we restate the fraction, and cancel:
*
* bytes 1000000000 bytes 976562
* --------- * ------------- = --------- * -------------
* 1024 nanoseconds 1 nanoseconds
*
* This is easy to calculate using integer arithmetic; this is what
* we do below.
*/
this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
@[args[1]->dev_statname, args[1]->dev_pathname] =
quantize((args[0]->b_bcount * 976562) / this->elapsed);
start[args[0]->b_edev, args[0]->b_blkno] = 0;
}
END
{
printa(" %s (%s)\n%@d\n", @);
}
このスクリプトを数秒間実行すると、次のような出力が得られます。
sd2 (/devices/pci@0,0/pci1179,1@1d/storage@2/disk@0,0:r)
value ------------- Distribution ------------- count
32 | 0
64 | 3
128 | 1
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2257
512 | 1
1024 | 0
cmdk0 (/devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0:a)
value ------------- Distribution ------------- count
128 | 0
256 | 1
512 | 0
1024 | 2
2048 | 0
4096 | 2
8192 |@@@@@@@@@@@@@@@@@@ 172
16384 |@@@@@ 52
32768 |@@@@@@@@@@@ 108
65536 |@@@ 34
131072 | 0
|
この出力から、sd2 がリミッタデバイスであることは明白です。sd2 のスループットは毎秒 256 - 512K バイトです。一方、cmdk0 は、毎秒 8M バイトから 64M バイトを超える速さで入出力を行います。このスクリプトは、iostat で出力されるデバイス名と、デバイスの完全パスとの両方を出力します。デバイスについてさらに詳しく知りたい場合は、次の例のように、prtconf にデバイスのパスを指定します。
# prtconf -v /devices/pci@0,0/pci1179,1@1d/storage@2/disk@0,0
disk, instance #2 (driver name: sd)
Driver properties:
name='lba-access-ok' type=boolean dev=(29,128)
name='removable-media' type=boolean dev=none
name='pm-components' type=string items=3 dev=none
value='NAME=spindle-motor' + '0=off' + '1=on'
name='pm-hardware-state' type=string items=1 dev=none
value='needs-suspend-resume'
name='ddi-failfast-supported' type=boolean dev=none
name='ddi-kernel-ioctl' type=boolean dev=none
Hardware properties:
name='inquiry-revision-id' type=string items=1
value='1.04'
name='inquiry-product-id' type=string items=1
value='STORAGE DEVICE'
name='inquiry-vendor-id' type=string items=1
value='Generic'
name='inquiry-device-type' type=int items=1
value=00000000
name='usb' type=boolean
name='compatible' type=string items=1
value='sd'
name='lun' type=int items=1
value=00000000
name='target' type=int items=1
value=00000000
|
強調部分からわかるように、このデバイスはリムーバブル USB 記憶装置です。
この節の例では、すべての入出力要求について調べてきました。しかし、1 種類の要求だけを調べたい場合もあります。以下の例では、書き込みが発生しているディレクトリと、この書き込みを実行しているアプリケーションを追跡します。
#pragma D option quiet
io:::start
/args[0]->b_flags & B_WRITE/
{
@[execname, args[2]->fi_dirname] = count();
}
END
{
printf("%20s %51s %5s\n", "WHO", "WHERE", "COUNT");
printa("%20s %51s %5@d\n", @);
}
このスクリプトを、デスクトップの作業負荷で一定期間実行すると、次に示すように、興味深い結果が得られます。
# dtrace -s ./whowrite.d
^C
WHO WHERE COUNT
su /var/adm 1
fsflush /etc 1
fsflush / 1
fsflush /var/log 1
fsflush /export/bmc/lisa 1
esd /export/bmc/.phoenix/default/78cxczuy.slt/Cache 1
fsflush /export/bmc/.phoenix 1
esd /export/bmc/.phoenix/default/78cxczuy.slt 1
vi /var/tmp 2
vi /etc 2
cat <none> 2
bash / 2
vi <none> 3
xterm /var/adm 3
fsflush /export/bmc 7
MozillaFirebird <none> 8
vim /export/bmc 9
MozillaFirebird /export/bmc 10
fsflush /var/adm 11
devfsadm /dev 14
ksh <none> 71
ksh /export/bmc 71
fsflush /export/bmc/.phoenix/default/78cxczuy.slt 119
MozillaFirebird /export/bmc/.phoenix/default/78cxczuy.slt 119
fsflush <none> 211
MozillaFirebird /export/bmc/.phoenix/default/78cxczuy.slt/Cache 591
fsflush /export/bmc/.phoenix/default/78cxczuy.slt/Cache 666
sched <none> 2385
|
この出力から、事実上すべての書き込みが Mozilla Firebird のキャッシュと関連付けられていることがわかります。<none> エントリが表示されている書き込みは、おそらく UFS ログに関連付けられている書き込みです。この書き込みは、ファイルシステム上の別の書き込みによって引き起こされます。ロギングの詳細については、ufs(7FS) のマニュアルページを参照してください。この例では、io プロバイダを使って、ソフトウェアの上位層で発生した問題の検出方法を示します。この場合、このスクリプトの構成に問題があります。 Web ブラウザのキャッシュが tmpfs(7FS) ファイルシステム内のディレクトリにあれば、この Web ブラウザによる入出力はずっと少なく(おそらく皆無に) なるはずです。
前の例では、start プローブと done プローブしか使われていません。アプリケーションの入出力がブロックされる理由と、その期間を調べたい場合は、wait-start プローブと wait-done プローブを使用します。以下のスクリプトでは、io プローブと sched プローブ (第 26 章sched プロバイダを参照) の両方を使って、StarSuite ソフトウェアの入出力待ち時間と CPU 時間とを比較します。
#pragma D option quiet
sched:::on-cpu
/execname == "soffice.bin"/
{
self->on = vtimestamp;
}
sched:::off-cpu
/self->on/
{
@time["<on cpu>"] = sum(vtimestamp - self->on);
self->on = 0;
}
io:::wait-start
/execname == "soffice.bin"/
{
self->wait = timestamp;
}
io:::wait-done
/self->wait/
{
@io[args[2]->fi_name] = sum(timestamp - self->wait);
@time["<I/O wait>"] = sum(timestamp - self->wait);
self->wait = 0;
}
END
{
printf("Time breakdown (milliseconds):\n");
normalize(@time, 1000000);
printa(" %-50s %15@d\n", @time);
printf("\nI/O wait breakdown (milliseconds):\n");
normalize(@io, 1000000);
printa(" %-50s %15@d\n", @io);
}
StarSuite ソフトウェアのコールドスタート実行中にこのスクリプトを実行すると、次のような結果が得られます。
Time breakdown (milliseconds): <on cpu> 3634 <I/O wait> 13114 I/O wait breakdown (milliseconds): soffice.tmp 0 Office 0 unorc 0 sbasic.cfg 0 en 0 smath.cfg 0 toolboxlayout.xml 0 sdraw.cfg 0 swriter.cfg 0 Linguistic.dat 0 scalc.cfg 0 Views.dat 0 Store.dat 0 META-INF 0 Common.xml.tmp 0 afm 0 libsimreg.so 1 xiiimp.so.2 3 outline 4 Inet.dat 6 fontmetric 6 ... libucb1.so 44 libj641si_g.so 46 libX11.so.4 46 liblng641si.so 48 swriter.db 53 libwrp641si.so 53 liblocaledata_ascii.so 56 libi18npool641si.so 65 libdbtools2.so 69 ofa64101.res 74 libxcr641si.so 82 libucpchelp1.so 83 libsot641si.so 86 libcppuhelper3C52.so 98 libfwl641si.so 100 libsb641si.so 104 libcomphelp2.so 105 libxo641si.so 106 libucpfile1.so 110 libcppu.so.3 111 sw64101.res 114 libdb-3.2.so 119 libtk641si.so 126 libdtransX11641si.so 127 libgo641si.so 132 libfwe641si.so 150 libi18n641si.so 152 libfwi641si.so 154 libso641si.so 173 libpsp641si.so 186 libtl641si.so 189 <unknown> 189 libucbhelper1C52.so 195 libutl641si.so 213 libofa641si.so 216 libfwk641si.so 229 libsvl641si.so 261 libcfgmgr2.so 368 libsvt641si.so 373 libvcl641si.so 741 libsvx641si.so 885 libsfx641si.so 993 <none> 1096 libsw641si.so 1365 applicat.rdb 1580 |
この出力からわかるように、StarSuite のコールドスタート時間の大部分は入出力待ち時間です。(入出力待ち時間が 13.1 秒であるのに対し、CPU 時間は 3.6 秒。)このスクリプトを StarSuite ソフトウェアのウォームスタートで実行すると、ページキャッシュによって入出力時間が短縮されることがわかります。次の出力例を参照してください。
Time breakdown (milliseconds): <I/O wait> 0 <on cpu> 2860 I/O wait breakdown (milliseconds): temp 0 soffice.tmp 0 <unknown> 0 Office 0 |
コールドスタートの出力から、applicat.rdb ファイルが一番入出力待ち時間が長いファイルであることがわかります。これはおそらく、ファイルへの入出力回数が多いためです。このファイルに対して実行された入出力について調べるには、次の D スクリプトを使用します。
io:::start
/execname == "soffice.bin" && args[2]->fi_name == "applicat.rdb"/
{
@ = lquantize(args[2]->fi_offset != -1 ?
args[2]->fi_offset / (1000 * 1024) : -1, 0, 1000);
}
このスクリプトは、fileinfo_t 構造体の fi_offset フィールドを使って、ファイルのどの部分がアクセスされているのかをメガバイトの粒度で調べます。StarSuite ソフトウェアのコールドスタート中にこのスクリプトを実行すると、次のような出力が得られます。
# dtrace -s ./applicat.d
dtrace: script './applicat.d' matched 4 probes
^C
value ------------- Distribution ------------ count
< 0 | 0
0 |@@@ 28
1 |@@ 17
2 |@@@@ 35
3 |@@@@@@@@@ 72
4 |@@@@@@@@@@ 78
5 |@@@@@@@@ 65
6 | 0
|
この出力から、ファイルの最初の 6M バイトだけがアクセスされていることがわかります。これは、おそらく、ファイルサイズが 6M バイトであるためです。また、ファイル全体がアクセスされているわけではないこともわかります。StarSuite のコールドスタートにかかる時間を短縮したい場合は、ファイルのアクセスパターンを把握する必要があります。ファイルの必要な部分がほぼ連続しているなら、StarSuite の実行前にスカウトスレッドを実行して、あらかじめファイルへの入出力を行なっておくと、コールドスタート時間を短縮できます。この方法は、ファイルのアクセスの手段が mmap(2) である場合に特に有効です。しかしながら、この方法で短縮できるコールドスタート時間は約 1.6 秒です。これだけのために、アプリケーションをさらに複雑にし、管理負荷を増やすメリットはありません。どちらにしても、io プロバイダで収集したデータを使って、最終的に得られる利益を正確に推測できます。
- © 2010, Oracle Corporation and/or its affiliates