第 27 章 io プロバイダ
io プロバイダは、ディスク入出力に関連したプローブを使用できるようにします。io プロバイダでは、iostat(1M) のような入出力監視ツールで監視している動作をすばやく調べることができます。たとえば、io プロバイダを使用すると、入出力に関する情報を、デバイス別、入出力の種類別、入出力サイズ別、プロセス別、アプリケーション名別、ファイル名別、またはファイルオフセット別に確認できます。
プローブ
表 27–1 は、io プローブの説明です。
表 27–1 io プローブ|
プローブ |
説明 |
|---|---|
|
start |
周辺機器 (デバイス) または NFS サーバーに対する入出力要求が発行される直前に起動するプローブ。args[0] は、入出力要求の bufinfo_t をポイントしています。args[1] は、入出力要求の受け取り側デバイスの devinfo_t をポイントしています。args[2] は、入出力要求に対応するファイルの fileinfo_t をポイントしています。ファイル情報を利用できるかどうかは、入出力要求の発行元ファイルシステムによって決まります。詳細については、「fileinfo_t」を参照してください。 |
|
done |
入出力要求が満たされたあと起動するプローブ。args[0] は、入出力要求の bufinfo_t をポイントしています。done プローブは、入出力が完了してから、バッファー上で完了処理が実行されるまでの間に起動します。したがって、done プローブが起動した時点では、b_flags に B_DONE は設定されていません。args[1] は、入出力要求を受け取ったデバイスの devinfo_t をポイントしています。args[2] は、入出力要求に対応するファイルの fileinfo_t をポイントしています。 |
|
wait-start |
スレッドが入出力要求の完了を待って保留状態に入る直前に起動するプローブ。args[0] は、スレッドが待機する入出力要求の、buf(9S) 構造体をポイントしています。args[1] は、入出力要求を受け取ったデバイスの devinfo_t をポイントしています。args[2] は、入出力要求に対応するファイルの fileinfo_t をポイントしています。wait-start プローブの起動後しばらくすると、同じスレッド内で wait-done プローブが起動します。 |
|
wait-done |
スレッドが入出力要求の完了待ち状態を抜けたときに起動するプローブ。args[0] は、スレッドが待機する入出力要求の、bufinfo_t をポイントしています。args[1] は、入出力要求を受け取ったデバイスの devinfo_t をポイントしています。args[2] は、入出力要求に対応するファイルの fileinfo_t をポイントしています。wait-done プローブは、同じスレッド内で wait-start プローブが起動したあとでのみ起動します。 |
io プローブは、周辺機器 に対する入出力要求が発行されたときと、NFS サーバーに対するファイルの読み取り/書き込み要求が発行されたときに起動します。たとえば、NFS サーバーに対してメタデータの要求が発行されても、readdir(3C) によって io プローブがトリガーされることはありません。
引数
表 27–2 に、io プローブの引数の型を示します。引数については、表 27–1 を参照してください。
表 27–2 io プローブ引数|
プローブ |
args[0] |
args[1] |
args[2] |
|---|---|---|---|
|
start |
struct buf * |
devinfo_t * |
fileinfo_t * |
|
done |
struct buf * |
devinfo_t * |
fileinfo_t * |
|
wait-start |
struct buf * |
devinfo_t * |
fileinfo_t * |
|
wait-done |
struct buf * |
devinfo_t * |
fileinfo_t * |
io プローブの引数は、buf(9S) 構造体のポインタ、devinfo_t のポインタ、および fileinfo_t のポインタで構成されます。以下では、これらの構造体について詳しく説明します。
bufinfo_t 構造体
bufinfo_t 構造体は、入出力要求について説明する抽象化オブジェクトです。start プローブ、done プローブ、wait-start プローブ、および wait-done プローブ内の args[0] は、入出力要求のバッファーをポイントしています。以下は、bufinfo_t 構造体の定義です。
typedef struct bufinfo {
int b_flags; /* flags */
size_t b_bcount; /* number of bytes */
caddr_t b_addr; /* buffer address */
uint64_t b_blkno; /* expanded block # on device */
uint64_t b_lblkno; /* block # on device */
size_t b_resid; /* # of bytes not transferred */
size_t b_bufsize; /* size of allocated buffer */
caddr_t b_iodone; /* I/O completion routine */
dev_t b_edev; /* extended device */
} bufinfo_t;
b_flags メンバーは、複数の状態値のビット単位の論理和であり、入出力バッファーの状態を表します。表 27–3 に、有効な状態値を示します。
表 27–3 b_flags の値|
B_DONE |
データ転送が完了しました。 |
|
B_ERROR |
入出力転送エラーが発生しました。この値は、b_error フィールドとともに設定されます。 |
|
B_PAGEIO |
バッファーは、呼び出された入出力要求内で使用されています。詳細については、b_addr フィールドの説明を参照してください。 |
|
B_PHYS |
バッファーは、ユーザーデータ領域への物理 (直接) 入出力で使用されています。 |
|
B_READ |
周辺機器から主記憶へデータが読み込まれます。 |
|
B_WRITE |
主記憶から周辺機器へデータが転送されます。 |
|
B_ASYNC |
非同期入出力要求です。この要求は待機されません。非同期入出力要求が発行されても、wait-start プローブや wait-done プローブは起動しません。ただし、非同期として指定された一部の入出力要求には、B_ASYNC が設定されていないことがあります。 非同期入出力サブシステムは、別のワークスレッドに非同期入出力操作を行わせることによって、非同期要求に応じることがあります。 |
b_bcount フィールドには、入出力要求の一環として転送されるバイト数が入ります。
B_PAGEIO が設定されていない場合、b_addr フィールドには、入出力要求の仮想アドレスが入ります。B_PHYS が設定されていない場合、これはカーネル仮想アドレスです。B_PHYS が設定されている場合は、ユーザー仮想アドレスです。B_PAGEIO が設定されている場合、b_addr フィールドには、カーネル非公開データが入ります。B_PHYS と B_PAGEIO は、どちらか 1 つだけを設定してください。そうしないと、両方とも設定されません。
b_lblkno フィールドは、デバイス上のどの論理ブロックがアクセスされるかを表します。論理ブロックから物理ブロック (シリンダ、トラックなど) へのマッピングは、デバイスごとに定義されています。
b_resid フィールドには、エラーのため転送されなかったバイト数が入ります。
b_bufsize フィールドには、割り当て済みのバッファーのサイズが入ります。
b_iodone フィールドは、入出力の完了時に呼び出されるカーネル内の特定のルーチンを表します。
b_error フィールドには、入出力エラーの際ドライバから返されるエラーコードが入ります。b_error が設定されるときは、b_flags メンバー内にも B_ERROR ビットが設定されます。
b_edev フィールドには、アクセス対象のデバイスのメジャーデバイス番号とマイナーデバイス番号が入ります。コンシューマは、D サブルーチン getmajor() と getminor() を使って、b_edev フィールドからメジャーデバイス番号とマイナーデバイス番号を抽出します。
devinfo_t
devinfo_t 構造体は、デバイスに関する情報を提供します。start プローブ、done プローブ、wait-start プローブ、および wait-done プローブ内の args[1] は、入出力のターゲットデバイスの devinfo_t 構造体をポイントしています。devinfo_t は、次のメンバーから成ります。
typedef struct devinfo {
int dev_major; /* major number */
int dev_minor; /* minor number */
int dev_instance; /* instance number */
string dev_name; /* name of device */
string dev_statname; /* name of device + instance/minor */
string dev_pathname; /* pathname of device */
} devinfo_t;
dev_major フィールドには、メジャーデバイス番号が入ります。詳細については、getmajor(9F) のマニュアルページを参照してください。
dev_minor フィールドには、マイナーデバイス番号が入ります。詳細については、getminor(9F) のマニュアルページを参照してください。
dev_instance フィールドには、デバイスのインスタンス番号が入ります。デバイスのインスタンス番号は、マイナーデバイス番号とは別のものです。マイナーデバイス番号は、デバイスドライバの管理下にある抽象化オブジェクトです。インスタンス番号は、デバイスノードのプロパティです。デバイスノードのインスタンス番号を表示するには、prtconf(1M) を実行します。
dev_name フィールドには、デバイスを管理するデバイスドライバの名前が入ります。デバイスドライバ名を表示するには、prtconf(1M) に -D を指定して実行します。
dev_statname フィールドには、デバイス名が入ります。このデバイス名は、iostat(1M) を実行したとき出力されるデバイス名と同じです。この名前は、kstat(1M) を実行したとき出力されるカーネル統計情報の名前とも一致しています。このフィールドは、iostat や kstat の出力内容に異常があったとき、この出力を実際の入出力アクティビティとすばやく対応付けるために提供されているものです。
dev_pathname フィールドには、デバイスの完全パスが入ります。このパスを prtconf(1M) の引数に指定すると、詳しいデバイス情報を得ることができます。dev_pathname のパスには、デバイスノード、インスタンス番号、およびマイナーノードを表す要素が含まれています。しかし、統計情報名に、これら 3 つの要素全部が含まれているとはかぎりません。デバイスによっては、統計情報名がデバイス名とインスタンス番号で構成されていることがあります。デバイスによってはまた、デバイス名とマイナーノード番号で構成されていることもあります。その結果、2 つのデバイスの dev_statname は同じでも、dev_pathname は異なるということが起こり得ます。
fileinfo_t
fileinfo_t 構造体は、ファイルに関する情報を提供します。start プローブ、done プローブ、wait-start プローブ、および wait-done プローブの args[2] は、入出力関連のファイルをポイントしています。ファイル情報が存在するかどうかは、入出力要求のディスパッチ時にこの情報を提供するファイルシステムによって決まります。一部のファイルシステム、特に第三者のファイルシステムは、この情報を提供しない場合があります。また、入出力要求の発行元ファイルシステムのファイル情報が存在しない場合もあります。たとえば、ファイルシステムのメタデータへの入出力には、関連ファイルはありません。さらに、高度に最適化されたファイルシステムは、複数の互いに無関係なファイルからの入出力を集積して、単一の入出力要求を作成することがあります。このようなファイルシステムからは、入出力の大部分を表現するファイルまたは入出力の「一部」を表現するファイルのファイル情報が提供されることがあります。また、このようなファイルシステムからファイル情報がまったく提供されないこともあります。
以下に、fileinfo_t 構造体の定義を示します。
typedef struct fileinfo {
string fi_name; /* name (basename of fi_pathname) */
string fi_dirname; /* directory (dirname of fi_pathname) */
string fi_pathname; /* full pathname */
offset_t fi_offset; /* offset within file */
string fi_fs; /* filesystem */
string fi_mount; /* mount point of file system */
} fileinfo_t;
fi_name フィールドには、ファイル名だけが入ります。ここには、ディレクトリ要素は含まれません。入出力に関連ファイル情報がない場合、fi_name フィールドには文字列 <none> が入ります。まれに、ファイルのパス名が未知であることもあります。この場合、fi_name フィールドには文字列 <unknown> が入ります。
fi_dirname フィールドには、ファイル名のディレクトリ要素だけが入ります。fi_name の場合と同じく、ファイル情報が存在しない場合、この文字列は <none> になります。ファイルのパス名が未知である場合、この文字列は <unknown> になります。
fi_pathname フィールドには、ファイルの完全パス名が入ります。fi_name の場合と同じく、ファイル情報が存在しない場合、この文字列は <none> になります。ファイルのパス名が未知である場合、この文字列は <unknown> になります。
fi_offset フィールドには、ファイル内のオフセットが入ります。ファイル情報が存在しない場合や、ファイルシステムがオフセットを指定していない場合は、-1 が入ります。
例
以下は、入出力要求が発行されるたびに関連情報を出力するスクリプトです。
#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 プロバイダで収集したデータを使って、最終的に得られる利益を正確に推測できます。
安定性
以下の表に、io プロバイダの安定性を DTrace の安定性機構に従って示します。安定性機構の詳細については、第 39 章安定性を参照してください。
|
要素 |
名前の安定性 |
データの安定性 |
依存クラス |
|---|---|---|---|
|
プロバイダ |
発展中 |
発展中 |
ISA |
|
モジュール |
非公開 |
非公開 |
不明 |
|
機能 |
非公開 |
非公開 |
不明 |
|
名前 |
発展中 |
発展中 |
ISA |
|
引数 |
発展中 |
発展中 |
ISA |
- © 2010, Oracle Corporation and/or its affiliates