SystemTap Begginers Guide 5.2 のメモ
5.2 ディスク
以下のセスクションではディスクとIOの状況について監視するスクリプトを説明する。
5.2.1 ディスク読み書きトラフィックの集計
disktop.stpは実行中のプロセスで最も重いディスク読み書きをしているプロセスを特定する。
#!/usr/bin/stap
#
# Copyright (C) 2007 Oracle Corp.
#
# Get the status of reading/writing disk every 5 seconds,
# output top ten entries
#
# This is free software,GNU General Public License (GPL);
# either version 2, or (at your option) any later version.
#
# Usage:
# ./disktop.stp
#
global io_stat,device
global read_bytes,write_bytes
probe vfs.read.return {
if ($return>0) {
if (devname!="N/A") {/*skip read from cache*/
io_stat[pid(),execname(),uid(),ppid(),"R"] += $return
device[pid(),execname(),uid(),ppid(),"R"] = devname
read_bytes += $return
}
}
}
probe vfs.write.return {
if ($return>0) {
if (devname!="N/A") { /*skip update cache*/
io_stat[pid(),execname(),uid(),ppid(),"W"] += $return
device[pid(),execname(),uid(),ppid(),"W"] = devname
write_bytes += $return
}
}
}
probe timer.ms(5000) {
/* skip non-read/write disk */
if (read_bytes+write_bytes) {
printf("\n%-25s, %-8s%4dKb/sec, %-7s%6dKb, %-7s%6dKb\n\n",
ctime(gettimeofday_s()),
"Average:", ((read_bytes+write_bytes)/1024)/5,
"Read:",read_bytes/1024,
"Write:",write_bytes/1024)
/* print header */
printf("%8s %8s %8s %25s %8s %4s %12s\n",
"UID","PID","PPID","CMD","DEVICE","T","BYTES")
}
/* print top ten I/O */
foreach ([process,cmd,userid,parent,action] in io_stat- limit 10)
printf("%8d %8d %8d %25s %8s %4s %12d\n",
userid,process,parent,cmd,
device[process,cmd,userid,parent,action],
action,io_stat[process,cmd,userid,parent,action])
/* clear data */
delete io_stat
delete device
read_bytes = 0
write_bytes = 0
}
probe end{
delete io_stat
delete device
delete read_bytes
delete write_bytes
printf("END!\n");
}disktop.stpは最もディスク読み書きが重い順に、
以下のデータを出力する。
- UID ユーザID ID0はroot
- PID プロセスID
- PPID 親プロセスのプロセスID
- CMD プロセス名
- DEVICE プロセスが読み書きを行なっているデバイス
- T Wであれば書き込みを、Rであれば読み込みを行なっている
- BYTES 読み書きしたサイズ
ctime関数は、gettimeofday_s関数で得たUNIXエポックでの秒数をカレンダー時刻に変換する。
このスクリプト中の$returnはプロセスが仮想ファイルシステムから読み書きしたバイト数が格納されている。
以下は実行例。
sudo stap ./disktop.stp
Sun Jul 29 05:03:33 2012 , Average: 0Kb/sec, Read: 0Kb, Write: 0Kb
UID PID PPID CMD DEVICE T BYTES
1000 1108 989 thunderbird dm-1 R 166
Sun Jul 29 05:03:38 2012 , Average: 0Kb/sec, Read: 0Kb, Write: 0Kb
UID PID PPID CMD DEVICE T BYTES
1000 1326 989 gnome-terminal dm-1 W 560
5.2.2 各ファイル読み書きにおけるIOの時間
このセクションでは、プロセスがファイルに対して読み書きに要する時間を計測する方法を説明する。
iotime.stp
#!/usr/bin/stap
/*
* Copyright (C) 2006-2007 Red Hat Inc.
*
* This copyrighted material is made available to anyone wishing to use,
* modify, copy, or redistribute it subject to the terms and conditions
* of the GNU General Public License v.2.
*
* You should have received a copy of the GNU General Public License
* along with this program. If not, see <http://www.gnu.org/licenses/>.
*
* Print out the amount of time spent in the read and write systemcall
* when each file opened by the process is closed. Note that the systemtap
* script needs to be running before the open operations occur for
* the script to record data.
*
* This script could be used to to find out which files are slow to load
* on a machine. e.g.
*
* stap iotime.stp -c 'firefox'
*
* Output format is:
* timestamp pid (executabable) info_type path ...
*
* 200283135 2573 (cupsd) access /etc/printcap read: 0 write: 7063
* 200283143 2573 (cupsd) iotime /etc/printcap time: 69
*
*/
global start
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 filehandles, fileread, filewrite
probe syscall.open.return {
filename = user_string($filename)
if ($return != -1) {
filehandles[pid(), $return] = filename
} else {
printf("%d %s access %s fail\n", timestamp(), proc(), filename)
}
}
probe syscall.read.return {
p = pid()
fd = $fd
bytes = $return
time = gettimeofday_us() - @entry(gettimeofday_us())
if (bytes > 0)
fileread[p, fd] += bytes
time_io[p, fd] <<< time
}
probe syscall.write.return {
p = pid()
fd = $fd
bytes = $return
time = gettimeofday_us() - @entry(gettimeofday_us())
if (bytes > 0)
filewrite[p, fd] += bytes
time_io[p, fd] <<< time
}
probe syscall.close {
if ([pid(), $fd] in filehandles) {
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 time_io[pid(),$fd]
}iotime.stpは、あるファイルへのシステムコールopen, close, read, writeのそれぞれの時間を追跡する。
それぞれのファイルに関して、システムコールへのアクセスがあると、iotime.stpは読み書きが完了するまでの時間をマイクロ秒単位で数えて、
データ量をバイト単位で追跡する。
iotime.stpは、$countに読み書きしたデータ量をバイト単位で保存する。$returnには、読み書きしたデータ量が保存されている。
$countはデータの読み書きが起こった際にのみ使われる。
sudo stap ./iotime.stp 1043730 900 (sendmail) access /proc/loadavg read: 26 write: 0 1043736 900 (sendmail) iotime /proc/loadavg time: 7 6048731 900 (sendmail) access /proc/loadavg read: 26 write: 0 6048737 900 (sendmail) iotime /proc/loadavg time: 7 11053729 900 (sendmail) access /proc/loadavg read: 26 write: 0 11053735 900 (sendmail) iotime /proc/loadavg time: 6 16058728 900 (sendmail) access /proc/loadavg read: 26 write: 0 16058734 900 (sendmail) iotime /proc/loadavg time: 7 18589249 679 (crond) access /etc/passwd read: 1800 write: 0 18589255 679 (crond) iotime /etc/passwd time: 12 18589299 679 (crond) access /etc/passwd read: 1800 write: 0 18589302 679 (crond) iotime /etc/passwd time: 5 18589328 679 (crond) access /etc/passwd read: 1800 write: 0 18589331 679 (crond) iotime /etc/passwd time: 5 21063733 900 (sendmail) access /proc/loadavg read: 26 write: 0 21063739 900 (sendmail) iotime /proc/loadavg time: 7
iotime.stpは、以下の情報を出力する。
- タイムスタンプ マイクロ秒単位
- プロセスIDとプロセス名
- access と iotime フラグ
- アクセスしたファイル
プロセスがファイルに読み書きを行えるようになると、accessかiotimeの行が出力される。
accessは、ファイルにアクセスを始めた事を示し、行末の数値は読み書きを試みたデータサイズをバイト単位で示す。
iotimeは、プロセスが読み書きを実行する過程の時間をマイクロ秒単位で示す。
accessの後にiotimeが現れない場合、それは単純にデータを読み書きしていない事を示す。
5.2.3 累積するIOの追跡
このセクションでは、累積したIOの量を追跡する方法について示す。
traceio.stp
#!/usr/bin/stap
# traceio.stp
# Copyright (C) 2007 Red Hat, Inc., Eugene Teo <eteo@redhat.com>
# Copyright (C) 2009 Kai Meyer <kai@unixlords.com>
# Fixed a bug that allows this to run longer
# And added the humanreadable function
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License version 2 as
# published by the Free Software Foundation.
#
global reads, writes, total_io
probe vfs.read.return {
reads[pid(),execname()] += $return
total_io[pid(),execname()] += $return
}
probe vfs.write.return {
writes[pid(),execname()] += $return
total_io[pid(),execname()] += $return
}
function humanreadable(bytes) {
if (bytes > 1024*1024*1024) {
return sprintf("%d GiB", bytes/1024/1024/1024)
} else if (bytes > 1024*1024) {
return sprintf("%d MiB", bytes/1024/1024)
} else if (bytes > 1024) {
return sprintf("%d KiB", bytes/1024)
} else {
return sprintf("%d B", bytes)
}
}
probe timer.s(1) {
foreach([p,e] in total_io- limit 10)
printf("%8d %15s r: %12s w: %12s\n",
p, e, humanreadable(reads[p,e]),
humanreadable(writes[p,e]))
printf("\n")
# Note we don't zero out reads, writes and total_io,
# so the values are cumulative since the script started.
}traceio.stpは、IOトラフィックを生成する実行ファイルのトップ10を表示する。
加えて、それら実行ファイルがIO読み書きを実施した量の合計を追跡する。
この情報は1秒毎に出力される。
traceio.stpのローカル変数$returnは、disktop.stpと同様に、読み書きしたバイト数を示す。
以下に実行例を示す。
sudo stap ./traceio.stp
793 Xorg r: 1 MiB w: 0 B
1246 firefox r: 223 KiB w: 326 KiB
1494 alsa-sink r: 1 KiB w: 1 KiB
1494 pulseaudio r: 1 KiB w: 1 KiB
1326 gnome-terminal r: 940 B w: 1 KiB
8069 stapio r: 972 B w: 971 B
4166 threaded-ml r: 115 B w: 60 B
8007 gdbus r: -6 B w: 176 B
1326 gdbus r: 10 B w: 128 B
8007 ibus-daemon r: 48 B w: 16 B
1246 firefox r: 6 MiB w: 1 MiB
793 Xorg r: 1 MiB w: 0 B
4166 plugin-containe r: 2 KiB w: 999 B
1326 gnome-terminal r: 1 KiB w: 1 KiB
8069 stapio r: 1 KiB w: 1 KiB
1494 alsa-sink r: 1 KiB w: 1 KiB
1494 pulseaudio r: 1 KiB w: 1 KiB
4166 threaded-ml r: 147 B w: 67 B
8007 gdbus r: -6 B w: 176 B
1326 gdbus r: 10 B w: 128 B
5.2.4 IO監視(デバイス毎に)
このセクションでは、特定のデバイスに対するIOの状況を監視する方法を説明する。
traceio2.stp
#!/usr/bin/stap
global device_of_interest
probe begin {
/* The following is not the most efficient way to do this.
One could directly put the result of usrdev2kerndev()
into device_of_interest. However, want to test out
the other device functions */
dev = usrdev2kerndev($1)
device_of_interest = MKDEV(MAJOR(dev), MINOR(dev))
}
probe vfs.write, vfs.read
{
if (dev == device_of_interest)
printf ("%s(%d) %s 0x%x\n",
execname(), pid(), probefunc(), dev)
}traceio2.stpは、デバイス番号をコマンドライン引数として取る。この値は、'stat -c "0x%D" ディレクトリ名'で得られる。
usrdev2kerndev関数は、デバイス番号をカーネルが理解出来る形式に変換するものである。
usrdef2kerndev関数はMKDEV(),MINOR(),MAJOR()と合わせて、各デバイスのメジャー番号とマイナー番号を決定するために使う。
traceio2.stpの出力は、各プロセスの名前とプロセスID、実行した関数名、カーネルのデバイス番号から成る。
以下は、'stap traceio2.stp 0x805'を実行した例である。
0x805は、/homeのデバイス番号である。/homeは/dev/sda5に含まれおり、そのデバイスが我々が監視したい対象である。
synergyc(3722) vfs_read 0x800005 synergyc(3722) vfs_read 0x800005 cupsd(2889) vfs_write 0x800005 cupsd(2889) vfs_write 0x800005 cupsd(2889) vfs_write 0x800005
5.2.5 ファイルへの読み書きを監視する
このセクションではファイルに対する読み書きをリアルタイムに監視する方法を説明する。
inodewatch.stp
#!/usr/bin/stap
global device_of_interest
probe begin {
/* The following is not the most efficient way to do this.
One could directly put the result of usrdev2kerndev()
into device_of_interest. However, want to test out
the other device functions */
dev = usrdev2kerndev($1)
device_of_interest = MKDEV(MAJOR(dev), MINOR(dev))
}
probe vfs.write, vfs.read
{
if (dev == device_of_interest)
printf ("%s(%d) %s 0x%x\n",
execname(), pid(), probefunc(), dev)
}
[ito@earth stap]$ cat inodewatch.stp
#!/usr/bin/stap
probe vfs.write, vfs.read
{
# dev and ino are defined by vfs.write and vfs.read
if (dev == MKDEV($1,$2) # major/minor device
&& ino == $3)
printf ("%s(%d) %s 0x%x/%u\n",
execname(), pid(), probefunc(), dev, ino)
}inodewatch.stpは、以下の３つのコマンドライン引数に取る。
これらの情報は'stat -c "%D %i" ファイル名'で得ることが出来る。
例えば、/etc/crontabを監視したい場合、'stat -c "%D %i" /etc/crontab'を実行する。
このコマンドの実行例は以下の通りである。
805 1078319
805は16進数のデバイス番号である。下位2桁の数字がマイナーデバイス番号で、上位の数字がメジャーデバイス番号である。
1078319はiノード番号である。/etc/crontabの監視を開始するためには、'stap inodewatch.stp 0x8 0x05 1078319
'と実行する。接頭辞0xは16進数を示す。
このコマンドの実行結果は、読み書きを実行しているプロセスの名前とID、実行中の関数(例えばvfs_read, vfs_write)、
デバイス番号(16進数)、iノード番号から成る。
以下の実行例は、cat /etc/crontabを実行中に'stap inodewatch.stp 0x8 0x05 1078319'を実行した結果である。
cat(16437) vfs_read 0x800005/1078319
cat(16437) vfs_read 0x800005/1078319
||<
** 5.2.6 ファイル属性変更の監視
このセクションでは対象ファイルの属性変更をリアルタイムに監視する。
>||
#!/usr/bin/stap
global ATTR_MODE = 1
probe kernel.function("setattr_copy")!,
kernel.function("generic_setattr")!,
kernel.function("inode_setattr") {
dev_nr = $inode->i_sb->s_dev
inode_nr = $inode->i_ino
if (dev_nr == MKDEV($1,$2) # major/minor device
&& inode_nr == $3
&& $attr->ia_valid & ATTR_MODE)
printf ("%s(%d) %s 0x%x/%u %o %d\n",
execname(), pid(), probefunc(), dev_nr, inode_nr, $attr->ia_mode, uid())
}inodewatch2.stpは、コマンドライン引数に対象となるファイルのデバイス番号とiノード番号を取る。
この情報について詳しく知りたい場合は、5.2.5を参照せよ。
inodewatch2.stpの出力はinodewatch.stpと似ており、違いは監視対象のファイルの変更された属性と、
変更したユーザーのIDである。
/home/joe/bigfileに対してユーザーjoeが'chmod 777 /home/joe/bigfile'と'chmod 666 /home/joe/bigfile'を実行した場合の例を示す。
chmod(17448) inode_setattr 0x800005/6011835 100777 500 chmod(17449) inode_setattr 0x800005/6011835 100666 500
5.2.7 IOブロックの時間の周期表示
このセクションでは、IO要求が完了するまでの待ち時間の合計を追跡する方法を示す。
これは過剰な未完了ブロックIO操作を特定するのに役に立つ。
#!/usr/bin/stap
global req_time, etimes
probe ioblock.request
{
req_time[$bio] = gettimeofday_us()
}
probe ioblock.end
{
t = gettimeofday_us()
s = req_time[$bio]
delete req_time[$bio]
if (s) {
etimes[devname, bio_rw_str(rw)] <<< t - s
}
}
/* for time being delete things that get merged with others */
probe kernel.trace("block_bio_frontmerge"),
kernel.trace("block_bio_backmerge")
{
delete req_time[$bio]
}
probe timer.s(10), end {
ansi_clear_screen()
printf("%10s %3s %10s %10s %10s\n",
"device", "rw", "total (us)", "count", "avg (us)")
foreach ([dev,rw] in etimes - limit 20) {
printf("%10s %3s %10d %10d %10d\n", dev, rw,
@sum(etimes[dev,rw]), @count(etimes[dev,rw]), @avg(etimes[dev,rw]))
}
delete etimes
}
ioblktime.stpは、各デバイスのブロックIOを待つ時間の平均を計算し、10秒毎に出力する。
この頻度は、timer.s(10)の数値を書き換えることで変更出来る。
未完了ブロックIOが多すぎる場合には、MAXMAPENTRIESの数分だけ出力される。
MAXMAPENTRIESの値を変更して実行したい場合には、-DMAXMAPENTRIES=10000をstapのオプションに指定して実行せよ。
以下は実行例である。
device rw total (us) count avg (us)
dm-1 W 80425 11 7311
dm-2 W 76476 10 7647
sda W 51706 10 5170
sda2 W 92400 2 46200この例は、デバイス名、実行している操作(rw)、全ての操作での待ち時間の合計(total(us))、操作の数(count)、全ての操作での待ち時間の平均時間(avg(us))を示す。
スクリプトによる時間の計算にはマイクロ秒単位の時間がかかる。
