4.2.2. ファイル読み取り/書き込みの I/O 時間の追跡
このセクションでは、各プロセスのファイルの読み取りおよび書き込み時間を監視する方法を説明します。これは、あるシステム上でどのファイルの読み込みが遅いかということを判断する際に便利です。
iotime.stp
global start global entry_io global fd_io global time_io function timestamp:long() { return gettimeofday_us() - start } function proc:string() { return sprintf("%d (%s)", pid(), execname()) } probe begin { start = gettimeofday_us() } global filenames global filehandles global fileread global filewrite probe syscall.open { filenames[pid()] = user_string($filename) } probe syscall.open.return { if ($return != -1) { filehandles[pid(), $return] = filenames[pid()] fileread[pid(), $return] = 0 filewrite[pid(), $return] = 0 } else { printf("%d %s access %s fail\n", timestamp(), proc(), filenames[pid()]) } delete filenames[pid()] } probe syscall.read { if ($count > 0) { fileread[pid(), $fd] += $count } t = gettimeofday_us(); p = pid() entry_io[p] = t fd_io[p] = $fd } probe syscall.read.return { t = gettimeofday_us(); p = pid() fd = fd_io[p] time_io[p,fd] <<< t - entry_io[p] } probe syscall.write { if ($count > 0) { filewrite[pid(), $fd] += $count } t = gettimeofday_us(); p = pid() entry_io[p] = t fd_io[p] = $fd } probe syscall.write.return { t = gettimeofday_us(); p = pid() fd = fd_io[p] time_io[p,fd] <<< t - entry_io[p] } probe syscall.close { if (filehandles[pid(), $fd] != "") { printf("%d %s access %s read: %d write: %d\n", timestamp(), proc(), filehandles[pid(), $fd], fileread[pid(), $fd], filewrite[pid(), $fd]) if (@count(time_io[pid(), $fd])) printf("%d %s iotime %s time: %d\n", timestamp(), proc(), filehandles[pid(), $fd], @sum(time_io[pid(), $fd])) } delete fileread[pid(), $fd] delete filewrite[pid(), $fd] delete filehandles[pid(), $fd] delete fd_io[pid()] delete entry_io[pid()] delete time_io[pid(),$fd] }
iotime.stp では、システムコールが開かれる、閉じる、ファイルから読み取る、およびファイルに書き込む際に、毎回これを追跡します。iotime.stp はシステムコールがアクセスする各ファイルについて、読み取りもしくは書き込みが終了するまでの時間をマイクロ秒単位でカウントし、読み取りもしくは書き込みされたデータ量をバイト単位で追跡します。
iotime.stp は、ローカル変数
$count
を使用してシステムコールが読み取りまたは書き込みを 試みた データ量 (バイト単位) も追跡します。(「ディスク読み取り/書き込みトラフィックの要約」 の disktop.stp で使用されている) $return
は、読み取り/書き込みされた 実際の データ量を保存することに注意してください。$count
を使用できるのは、(syscall.read
および syscall.write
など) データの読み取りや書き込みを追跡するプローブのみです。
例4.6 iotime.stp のサンプル出力
[...] 825946 3364 (NetworkManager) access /sys/class/net/eth0/carrier read: 8190 write: 0 825955 3364 (NetworkManager) iotime /sys/class/net/eth0/carrier time: 9 [...] 117061 2460 (pcscd) access /dev/bus/usb/003/001 read: 43 write: 0 117065 2460 (pcscd) iotime /dev/bus/usb/003/001 time: 7 [...] 3973737 2886 (sendmail) access /proc/loadavg read: 4096 write: 0 3973744 2886 (sendmail) iotime /proc/loadavg time: 11 [...]
例4.6「iotime.stp のサンプル出力」 では、以下のデータがプリントアウトされます。
- タイムスタンプ (マイクロ秒単位)
- プロセス ID およびプロセス名
access
またはiotime
のフラグ- アクセスされたファイル
プロセスがデータの読み取りまたは書き込みを実行すると、
access
と iotime
の行のペアが一緒に表示されます。access
行のタイムスタンプは、そのプロセスがファイルにアクセスを開始した時間を指します。その行の最後には、読み取り/書き込みされたデータ量がバイト単位で表示されます。iotime
の行では、読み取り/書き込みにプロセスが費やした時間がマイクロ秒単位で表示されます。
access
行の後に iotime
行が続いていない場合は、プロセスがデータの読み取りまたは書き込みを行わなかったことを意味します。