Red Hat Training

A Red Hat training course is available for Red Hat Enterprise Linux

4.2.2. ファイル読み取り/書き込みの I/O 時間の追跡

このセクションでは、各プロセスのファイルの読み取りおよび書き込み時間を監視する方法を説明します。これは、あるシステム上でどのファイルの読み込みが遅いかということを判断する際に便利です。

例4.11 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]
}
例4.11「iotime.stp」 では、システムコールが開かれる、閉じる、ファイルから読み取る、およびファイルに書き込む際に、毎回これを追跡します。例4.11「iotime.stp」 はシステムコールがアクセスする各ファイルについて、読み取りもしくは書き込みが終了するまでの時間をマイクロ秒単位でカウントし、読み取りもしくは書き込みされたデータ量をバイト単位で追跡します。
例4.11「iotime.stp」 は、ローカル変数 $count を使用してシステムコールが読み取りまたは書き込みを 試みた データ量 (バイト単位) も追跡します。$return (「ディスク読み取り/書き込みトラフィックの要約」 の 例4.9「disktop.stp」 で使用) には、読み書きされた 実際 のデータ量が保存されます。$count は、データの読み取りまたは書き込みを追跡するプローブ (syscall.read、syscall.write など) でのみ使用できます。

例4.12 例4.11「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.12「例4.11「iotime.stp」 出力サンプル」 では、以下のデータが出力されます。
  • タイムスタンプ (マイクロ秒単位)
  • プロセス ID およびプロセス名
  • access または iotime のフラグ
  • アクセスされたファイル
プロセスがデータの読み取りまたは書き込みを実行すると、access と iotime の行のペアが一緒に表示されます。access 行のタイムスタンプは、そのプロセスがファイルにアクセスを開始した時間を指します。その行の最後には、読み取り/書き込みされたデータ量がバイト単位で表示されます。iotime の行では、読み取り/書き込みにプロセスが費やした時間がマイクロ秒単位で表示されます。
access 行の後に iotime 行が続いていない場合は、プロセスがデータの読み取りまたは書き込みを行わなかったことを意味します。