CPU情報の詳細を探る

表１．　ポイントと項目

No ポイント コマンドとオプション 内容
@ プロセスアカウント情報の活用方法は? accton accountfile プロセスアカウント起動
accton プロセスアカウント停止
acctcom -f -m -t accountfile プロセスアカウント情報の編集
A コールの内訳はどうなっているのか?
【備考1】		 truss -c [ -o tracefile ] -p PID PIDプロセスのコールサマリ出力
truss -c [ -o tracefile ] command ..... commandのコールサマリ出力
truss -f [ -o tracefile ] -p PID PIDプロセスの詳細トレース出力
truss -f [ -o tracefile ] command ..... commandの詳細トレース出力
truss -lDdaf [ -o tracefile ] -p PID PIDプロセスのより詳細なトレースを出力
truss -lDdaf [ -o tracdfile ] command ..... commandのより詳細なトレースを出力
sotruss [ -f ] [ -o tracefile ] command ...... ライブラリトレースの出力
apptrace [ -f ] [ -o tracefile ] command ..... アプリケーショントレースの出力
B ロック待ちの内訳はどうなっているのか? lockstat sleep 10 10秒間のロック情報を表示
lockstat -l lockname sleep 10 10秒間のlocknameで示す情報を表示
lockstat -kgIW プロファイルデータの表示
C コンテクストスイッチの内訳は? mpstat migr項目の確認
D ディスパッチャテーブルの内容は? dispadmin -l スケジューリングクラスの表示
dispadmin -c TS|RT -g > disp_table ディスパッチャテーブルの出力
dispadmin -c TS|RT -s disp_table ディスパッチャテーブルのセット
E プライオリティを固定する方法は? dispadmin -c TS -d|-s ディスパッチャテーブルの出力とセット
priocntl -s -p 59 -i pid PID -p 59にPIDを固定する
F LWPの状態はどうなっているのか? ps -efcL LWP情報の表示
G カーネルコンポーネントの統計情報は? netstat -k カーネル統計情報の表示
kstat [module]:[instance]:[name]:[statistic] カーネル統計情報の表示(Solaris8以降)
H カーネルコンポーネントの動きは? kgmon プロファイラの実行【備考2】
gprof gmon.syms gmon[n].out　> kgmon_filen プロファイルデータの編集(CPU毎)【備考2】
prex カーネルトレーシングとTNFプルーブの操作
tnfxtract tracefile カーネルTNFプルーブの抜き出し
tnfdump　tracefile TNFファイルの編集
I CPUイベントの内訳は? cpustat -h イベント一覧を表示する
cputrack -c eventspec　command CPUイベントの表示

【備考】

１． プログラムのデバッグ段階では、GNUのgccによるgprof(プロファイラ)や、TNF(Trace Normal Form)プローブの埋め込みによるデバッグ手法を用いることが出来ます。本コンテンツでは解説を省略させていただきます。
２． kgmonはSolaris2.6までのコマンドです。Solaris7以降で無くなりました。かわりにlockstatコマンド-kgIWオプションが類似の出力を表示してくれます。


@プロセスアカウント情報の活用方法は?

プロセスアカウント情報は、CPU時間、プロセスサイズ、終了ステータス等を記録しています。acctcomコマンドは編集オプションをいくつか持っていますが、本コンテンツでは、-f、-m、および-tによって表示された情報を用いることにします。図1.1にその表示例、表1.1に表示情報の内容を解説します。

COMMAND START END REAL CPU (SECS) MEAN
NAME USER TTYNAME TIME TIME (SECS) SYS USER SIZE(K) F STAT
#accton root pts/2 17:03:16 17:03:16 0.01 0.00 0 920 42 0
echo root pts/2 17:03:16 17:03:16 0.02 0.01 0 1424 40 0
date root pts/2 17:03:16 17:03:16 0.01 0.00 0 920 40 0
nawk root pts/2 17:03:16 17:03:16 0.01 0.01 0 920 40 0
mkdir root pts/2 17:03:17 17:03:17 0.02 0.00 0 920 40 0
wc root pts/2 17:03:17 17:03:17 0.01 0.00 0 208 40 0
awk root pts/2 17:03:17 17:03:17 0.01 0.00 0 920 40 0
cat root pts/2 17:03:17 17:03:17 0.01 0.01 0 392 40 0
expr root pts/2 17:03:17 17:03:17 0.01 0.00 0 920 40 0
echo root pts/2 17:03:17 17:03:17 0.01 0.00 0 208 40 0
awk root pts/2 17:03:17 17:03:17 0.01 0.01 0 1224 40 0
date root pts/2 17:03:17 17:03:17 0.01 0.00 0 920 40 0
sed root pts/2 17:03:17 17:03:17 0.02 0.01 0 1656 40 0
echo root pts/2 17:03:17 17:03:17 0.01 0.00 0 920 40 0
#crash root pts/2 17:03:17 17:03:17 0.30 0.11 0.19 2129.6 42 0

図１．１　プロセスアカウントの出力(部分)

　

表１．１　プロセスアカウント情報の内容

項目 内容
COMMAND NAME コマンド名です。8文字に切り詰められます。ルートユーザから実行されるとコマンド名の先頭に"#"(シャープ)が付けられます。
USER コマンドを実行したユーザIDです。
TTYNAME コマンドを実行したTTY名です。
START TIME コマンドの開始時刻です。
END TIME コマンドの終了時刻です。終了時にプロセスアカウント情報が記録されます。
REAL(SECS) エラプス時間です。
CPU(SECS)SYS 秒単位のシステムCPU時間です。
CPU(SECS)USER 秒単位のユーザCPU時間です。
MEAN SIZE(K) 推定のプロセスサイズです。mallocで獲得されたヒープや、スタック、共有メモリは反映されません。
F フラグです。通常0x00000028が10進数"40"で表示されます。SPREXECとSLOADを示します。
【参考】/usr/include/sys/proc.hをご覧下さい。
STAT 戻り値です。通常"0"です。終了コード、またはシグナル番号がセットされます。

ちりも積もれば山になります。何気なく使用しているコマンドのシステムCPUやユーザCPU時間、それらがエラプス時間に占める割合を見ることで、より効率の良いコマンドや特徴をつかむことが出来ます。これには、情報採取区間内に実行されたコマンドを集計して、各コマンドのシステムとCPU時間、およびコマンド単体のシステムとCPU時間を求めます。図1.2に求め方を示します(図中、<CR>は省略しています)。

TIMEDIFF=300; export TIMEDIFF　　　←測定区間の時間を秒単位で指定します。
acctcom -f -m -t accountfile |
sed -n '5,$p' |
awk '{
　　　　cmd=sprintf("%s~%s",$1,$2)
　　　　elaps[cmd] = elaps[cmd] + $6
　　　　sys[cmd] = sys[cmd] + $7
　　　　user[cmd] = user[cmd] + $8
　　　　count[cmd] = count[cmd] + 1
　　}
　　END {
　　　　for ( proc in user) {
　　　　　　　　split(proc,array,"~")
　　　　　　　　printf"%-12s ",array[1]
　　　　　　　　printf"%-12s ",array[2]
　　　　　　　　printf"%15.2f ",elaps[proc]
　　　　　　　　printf"%14.0f ",count[proc]
　　　　　　　　printf"%12.2f ",sys[proc]+user[proc]
　　　　　　　　printf"%6.2f ",(sys[proc]+user[proc])/'"$TIMEDIFF"'*100
　　　　　　　　printf"%12.2f ",sys[proc]
　　　　　　　　printf"%12.4f ",sys[proc]/count[proc]*1000
　　　　　　　　printf"%12.2f ",user[proc]
　　　　　　　　printf"%12.4f\n",user[proc]/count[proc]*1000
　　　　}
}' > result

図１．２　コマンドのCPU統計情報を求める

この出力をユーザCPUでソートした結果を図1.3に示します。ヘッダーは別に付け加えました。

command userid elaps callcount totalcpu rate% syscpu sysmsec usercpu usermsec
w root 174.96 10000 168.54 28.09 131.77 13.177 36.77 3.677
uptime root 101.2 10000 55.09 9.18 34.75 3.475 20.34 2.034
add root 201.29 20000 47.75 7.96 31.48 1.574 16.27 0.8135
expr root 101.74 10087 28.24 4.71 16.8 1.6655 11.44 1.1341
average root 100.51 10000 23.77 3.96 16.28 1.628 7.49 0.749
cpu12.sh root 96.72 1 5.98 1 4.66 4660 1.32 1320
cpu11.sh root 211.36 1 5.41 0.9 4.11 4110 1.3 1300
ps root 4.83 140 2.95 0.49 1.68 12 1.27 9.0714
cpu13.sh root 57.14 1 5.46 0.91 4.24 4240 1.22 1220
netstat root 1213.36 245 2.17 0.36 1.22 4.9796 0.95 3.8776
pmap root 3.08 156 2.98 0.5 2.22 14.2308 0.76 4.8718
sleep root 2986.89 481 1.47 0.25 0.9 1.8711 0.57 1.185
echo root 7.25 693 1.44 0.24 1.01 1.4574 0.43 0.6205
#crash root 0.63 2 0.62 0.1 0.24 120 0.38 190
vmstat root 1205.87 123 0.69 0.12 0.4 3.252 0.29 2.3577
sardo.sh root 2431.48 8 1.11 0.18 0.82 102.5 0.29 36.25
awk root 1.32 116 0.44 0.07 0.28 2.4138 0.16 1.3793
date root 5.32 530 1.22 0.2 1.07 2.0189 0.15 0.283
cat root 0.3 30 0.09 0.01 0.04 1.3333 0.05 1.6667
sed root 0.28 26 0.06 0.01 0.02 0.7692 0.04 1.5385
uname root 0.03 3 0.02 0 0 0 0.02 6.6667
swap root 0.02 2 0.02 0 0 0 0.02 10
wc root 0.04 4 0.01 0 0 0 0.01 2.5
nawk root 0.31 31 0.1 0.02 0.09 2.9032 0.01 0.3226
kill root 0.06 4 0.02 0 0.01 2.5 0.01 2.5
ipcs root 0.02 2 0.02 0 0.01 5 0.01 5
sort root 0.04 1 0 0 0 0 0 0
sadc root 600 1 0.01 0 0.01 10 0 0
rm root 0.08 4 0 0 0 0 0 0
pwd root 0.05 5 0.04 0.01 0.04 8 0 0
mv root 0.03 1 0 0 0 0 0 0
mkdir root 0.1 4 0.01 0 0.01 2.5 0 0
iostat root 600.08 1 0.01 0 0.01 10 0 0
id root 0.01 1 0.01 0 0.01 10 0 0
df root 0.02 2 0 0 0 0 0 0
#sendmail root 0.01 1 0 0 0 0 0 0
#mpstat root 601.12 1 0 0 0 0 0 0

図１．３　コマンドのCPU統計情報

ヘッダー項目の内容を表1.2に示します。

表１．２　プロセスアカウント統計情報の内容

項目 内容
command コマンド名です。
userid ユーザIDです。
elaps エラプス時間の合計秒です。
callcount 当該コマンドのコール回数です。
totalcpu CPU時間の合計秒です。
rate% 測定時間全体に占めるCPU時間の割合です。CPUが複数ある場合、枚数分で割り算して下さい。
syscpu システムCPUの秒です。
sysmsec コマンド1回あたりのシステムCPUミリ秒です。
usercpu ユーザCPUの秒です。
usermsec コマンド1回あたりのユーザCPUミリ秒です。

このようにして、各種コマンドの特徴を、システムCPU時間が高い、ユーザCPU時間が高い、あるいはエラプス時間に対してCPU消費が少ない…何らかの待ちやディスク入出力が多いことを意味します…等をつかみ、改善できるものがあれば改修することが出来ます。

　

Aコールの内訳はどうなっているのか?

リード・ライト、exec/fork、IPC関連システムコールの発行量、程度はsarコマンドで知ることが出来ます。一方、そのシステムコールを誰が実行したのか、またはその他のシステムコールはどの程度発行されているのかはsarコマンドだけでは分かりません。少なくともプロセスのあたりをつけ、そのプロセスがどのようなシステムコールをどの程度発行したのかを知るためのコマンドがtrussです。まず、コマンドのサマリをtrussコマンド-cオプションで調べてみましょう。

# ps -efl | grep ckpt <CR>
　8 S oracle 563 1 1 51 20 ? 53304 ? 18:29:23 ? 0
:00 ora_ckpt_ora900
# truss -c -p 563 <CR>
syscall seconds calls errors
_exit 0 1
write 0.01 53
close 0 7
creat 0 1
stat 0 2 1
getpid 0 2
kill 0 8
shmdt 0 1
semctl 0.02 222
semtimedop 0.01 316 153
fcntl 0 3
sigprocmask 0 2
sigaction 0.01 19
yield 0 30
lwp_cond_wait 0.02 459
lwp_cond_signal 0.04 459
llseek 0 1
kaio 0.12 3931 3931
pread64 0 48
pwrite64 0 459
------- ------ ----
sys totals: 0.23 6024 4085
usr time: 0.64
elapsed: 479.81
#

図２．１　trussコマンド-cオプションによるコールサマリ

ORACLEのチェックポイントプロセスをトレースしたものです。trussコマンドはそのプロセスが終了した時に同時に終了し、図2.1にあるサマリを表示します。オプション-p PIDのかわりに、調査したいコマンドをそのまま指定しても良いです。通常、プロセスの開始処理でファイルオープンしたりすることが多いので、-p PIDでは途中からのトレースになります。プロセスの処理開始から終了までの全コール情報を得たい場合は、trussコマンドの実行と同時に、調査したいコマンドを起動する必要があります。図2.1の例では発行したシステムコール、回数、エラーの有無が表示されています。sys totals:はシステムCPU時間、usr time:はユーザCPU時間で、elapsed:に実行時間が表示されています。単位は秒です。この中から、問題となっている部分を確認し、対処します。

trussコマンド-fオプションは詳細なトレース情報を表示します。次にechoコマンドのトレース出力例を示します。

# truss -f echo A <CR>
5606: execve("/usr/bin/echo", 0xFFBEFEC4, 0xFFBEFED0)argc = 2
5606: mmap(0x00000000, 8192, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFF3A0000
5606: resolvepath("/usr/lib/ld.so.1", "/usr/lib/ld.so.1", 1023)= 16
5606: open("/var/ld/ld.config", O_RDONLY) Err#2 ENOENT= 3
5606: open("/usr/lib/libc.so.1", O_RDONLY)= 0
5606: fstat(3, 0xFFBEF5FC)
5606: mmap(0x00000000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF390000
5606: mmap(0x00000000, 794624, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF280000
5606: mmap(0xFF33A000, 24692, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 696320) = 0xFF33A000
5606: munmap(0xFF32A000, 65536)= 0
5606: memcntl(0xFF280000, 113380, MC_ADVISE, MADV_WILLNEED, 0, 0)= 0
5606: close(3)= 0
5606: open("/usr/lib/libdl.so.1", O_RDONLY)= 3
5606: fstat(3, 0xFFBEF5FC)= 0
5606: mmap(0xFF390000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF390000
5606: close(3)= 0
5606: open("/usr/platform/SUNW,Sun-Blade-1000/lib/libc_psr.so.1", O_RDONLY)= 3
5606: fstat(3, 0xFFBEF48C)= 0
5606: mmap(0x00000000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF380000
5606: close(3)= 0
5606: ioctl(1, TCGETA, 0xFFBEFBB4)= 0
A
5606: write(1, " A\n", 2)= 2
5606: llseek(0, 0, SEEK_CUR)= 3847
5606: _exit(0)
#

図２．２　ftrssコマンド-fオプションのトレース

trussコマンド-fオプションは大量にトレース情報を出力します。トレース情報表示のため、本体コマンドの実行は遅くなります。このことは、trussコマンドは時間的な関係を知るためには不向きで、ロジック上の動作確認のために使用することがポイントと考えます。なお参考文献2はtrussコマンドの-lDdafオプションがお勧めになっています。LWPや時間スタンプが詳細に出力されます。出力例を次に示します。

# truss -lDdaf echo A <CR>
Base time stamp: 1089627919 .9242 [ Mon Jul 12 19:25:19 JST 2004 ]
5610/1: 0.0000 0.0000 execve("/usr/bin/echo", 0xFFBEFEC4, 0xFFBEFED0) argc = 2
5610/1: argv: echoA
5610/1: 0.2242 0.2242 mmap(0x00000000, 8192, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) = 0xFF3A0000
5610/1: 0.2244 0.0002 resolvepath("/usr/lib/ld.so.1", "/usr/lib/ld.so.1", 1023) = 16
5610/1: 0.2246 0.0002 open("/var/ld/ld.config", O_RDONLY) Err#2 ENOENT
5610/1: 0.2248 0.0002 open("/usr/lib/libc.so.1", O_RDONLY)= 3
5610/1: 0.2249 0.0001 fstat(3, 0xFFBEF5FC)= 0
5610/1: 0.2250 0.0001 mmap(0x00000000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF390000
5610/1: 0.2251 0.0001 mmap(0x00000000, 794624, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF280000
5610/1: 0.2252 0.0001 mmap(0xFF33A000, 24692, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 696320) = 0xFF33A000
5610/1: 0.2254 0.0002 munmap(0xFF32A000, 65536)= 0
5610/1: 0.2257 0.0003 memcntl(0xFF280000, 113380, MC_ADVISE, MADV_WILLNEED, 0, 0) = 0
5610/1: 0.2258 0.0001 close(3)= 0
5610/1: 0.2259 0.0001 open("/usr/lib/libdl.so.1", O_RDONLY)= 3
5610/1: 0.2260 0.0001 fstat(3, 0xFFBEF5FC)= 0
5610/1: 0.2261 0.0001 mmap(0xFF390000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF390000
5610/1: 0.2263 0.0002 close(3)= 0
5610/1: 0.2264 0.0001 open("/usr/platform/SUNW,Sun-Blade-1000/lib/libc_psr.so.1", O_RDONLY) = 3
5610/1: 0.2266 0.0002 fstat(3, 0xFFBEF48C)= 0
5610/1: 0.2266 0.0000 mmap(0x00000000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xFF380000
5610/1: 0.2268 0.0002 close(3)= 0
5610/1: 0.2276 0.0008 ioctl(1, TCGETA, 0xFFBEFBB4)= 0
A
5610/1: 0.2278 0.0002 write(1, " A\n", 2)= 2
5610/1: 0.2279 0.0001 llseek(0, 0, SEEK_CUR)= 5708
5610/1: 0.2280 0.0001 _exit(0)
#

図２．３　trussコマンド-lDdafオプションのトレース

　sotrussコマンドはSolaris8から提供された共用ライブラリコールをトレースするコマンドです。

# sotruss -f date <CR>
18012:date -> libc.so.1:*atexit(0xff3bc558,0x21800,0x0)
18012:date -> libc.so.1:*atexit(0x115cc,0xff23a004,0xff3bc558)
18012:date -> libc.so.1:*setlocale(0x6,0x11624,0xff23c5a8)
18012:date -> libc.so.1:*textdomain(0x11628,0xff23d9fc,0xff23a004)
18012:date -> libc.so.1:*getopt(0x1,0xffbefdcc,0x11638)
18012:date -> libc.so.1:*time(0x21cbc,0xffffffff,0xff23cc48)
18012:date -> libc.so.1:*nl_langinfo(0x3a,0xffffffff,0x21cbc)
18012:date -> libc.so.1:*localtime(0x21cbc,0x3a,0xff23a004)
18012:date -> libc_psr.so.1:*memcpy(0xffbefd3c,0xff240988,0x24)
18012:date -> libc.so.1:*strftime(0x21cc0,0x400,0xff227f14)
18012:date -> libc.so.1:*puts(0x21cc0,0x400,0x21cc0)
Tue Jul 13 17:54:50 JST 2004
18012:date -> libc.so.1:*exit(0x0,0xff227f14,0xffbefdd4)
#

図２．４　sotrussコマンドの出力

　

Bロック待ちの内訳はどうなっているのか?

マルチスレッド環境で、メモリ空間を共用して更新する際、ミューテックスロックと呼ばれる機構を用いてメモリ内容の一貫性を保っています。メモリのある領域を更新中、他のスレッドが同じ領域を更新するのを防ぐわけです。CPUが一個でも複数でも仕組みは同じです。ロック待ちが亢進すると資源の充分な活用が図れません。lockstatコマンドは、引数にsleepで休眠(採取)時間を指定し、その時間内に幾つのロックがどの程度発生していたかを収集するコマンドです。

# lockstat sleep 10 <CR>
Adaptive muex block:3 mutex events 10.064 seconds (0 events/sec)
Count indv cuml rcnt nsec Lock Caller
------- ------- ----------- ----- -------- ------------- ------------
1 33% 33% 1.00 19200 0x30001f429f8 putnext+0x54
1 33% 67% 1.00 45296800 0x300010780e0 alloccg+0x11c
1 33% 100% 1.00 21400 0x3000005eda0 ssdintr+0x38
------- ------- ----------- ----- -------- ------------- ------------
#

図３．１　ロックの調査

この例は、UFS(UNIXファイルシステム)のcg(シリンダーグループ)を割当てる関数alloccgのところで、約45ミリ秒待ったことがわかります。-lオプションを指定し、Callerにあるイベントを引数に指定することでより絞り込んだステータスを表示することが出来ます(-lオプションの適切な例を作ることができませんでした。弊社のテスト環境がシングルCPUなので、かなり難しいことでした。すいません…)。次の図は、Solaris8からの新たなlockstat機能で、kgmonの代わりとなるオプションの表示例です。

# lockstat -kgIW sleep 5 <CR>
Profiling interrupt: 485 events in 5.001 sedonds (97 events/sec)
Count genr cuml rcnt nsec Hottest CPU+PIL Caller
-------------------------------------------------------------------------------
892 184% ---- 1.00 1000 cpu[0] idle
485 100% ---- 1.00 1021 cpu[0] lockstat_intr
485 100% ---- 1.00 1021 cpu[0] cyclic_fire
485 100% ---- 1.00 1021 cpu[0] cbe_level14
485 100% ---- 1.00 1021 cpu[0] current_thread
482 99% ---- 1.00 1000 cpu[0] thread_start
19 4% ---- 1.00 920 cpu[0] generic_idle_cpu
2 0% ---- 1.00 4112 cpu[0] fifo_poll
2 0% ---- 1.00 4489 cpu[0] fsflush
1 0% ---- 1.00 4112 cpu[0] pcache_poll
1 0% ---- 1.00 4112 cpu[0] poll
1 0% ---- 1.00 4150 cpu[0] page_trylock
1 0% ---- 1.00 4828 cpu[0] mutex_exit
1 0% ---- 1.00 4150 cpu[0] mutex_enter
-------------------------------------------------------------------------------
#

図３．２　プロファイルデータの表示

　

Cコンテクストスイッチの内訳は?

コンテクストスイッチはユーザモードからカーネルモード、またはその逆の動作の総称です。コンテクストは大きく実行コンテクストと仮想メモリコンテクストに分けられます。実行コンテクストはプロセス、割り込み、カーネルの3種類に分けられます。仮想メモリコンテクストは、スケジューラが、あるプロセスから別プロセスに実行を切り替える時、割り込みやトラップによってユーザモードからカーネルモードへ切り替わる時等に、メモリアドレスを変換する処理として実行されます。

(1)より高い優先度のスレッドに制御を横取り(preemption)された時。
(2)スレッドがCPU使用可能時間(ディスパッチャテーブルの解説で後述します)を使い果たした時。
(3)システムコールを発行した時やその処理待ち時。

(1)と(2)は非自発的コンテクストスイッチ、(3)は自発的コンテクストスイッチと呼ばれます。

コンテクストスイッチの秒あたりの発生回数は、sarコマンド-wオプションで表示されるpswch/s、またはvmstatコマンドのcsです。これらの値はシステム全体の発生量を示しています。mpstatコマンドのithr、csw、icsw、およびmigrはCPU毎のコンテクストスイッチを表示してくれます。ithrは割り込んだスレッドの数(クロック割り込みは含みません)、cswはsarコマンドのpswch/sや、vmstatのcsと同様のコンテクストスイッチです。mpstatのicswは非自発的コンテクストスイッチを表します(無作為コンテクストスイッチとも呼ばれます)。migrは他のCPU(またはスレッド)に制御が移ったことを表します。仮想メモリコンテクストが含まれることがあります。なんだか文章では分かりにくいので、一覧表にしました。

表４．mpstatのコンテクスト項目

項目 計数モジュール【備考】 関数名 きっかけ 値の足し算の仕方
ithr uts/sun4u/ml/interrupt.s intr_thread 割り込み CPU_SYSINFO_INTRTHREADの値をプラス(inc)。
csw uts/common/disp/disp.c swtch
swtch_to
swtch_from_zombie		 ディスパッチ CPU_STAT_ADDQマクロを使用して、cpu_sysinfo.pswitchの値をプラス。
icsw uts/common/disp/disp.c preempt 横取り CPU_STAT_ADDQマクロを使用して、cpu_sysinfo.inv_swtchの値をプラス。
uts/common/syscall/yield.c yield システムコール 同上。
migr uts/sun4u/ml/swtch.s resume スレッド切り換え CPU_SYSINFO_CPUMIGRATEの値をプラス(inc)。

　 【備考】sun4uのディレクトリ名はハードウェアアーキテクチャによって変わります。

これらのことから、システムコールが多く発行された、割り込みが多発した、あるいは実行可能なスレッドが数多くあると、コンテクストスイッチの値が高まることが分かります。

　

Dディスパッチャテーブルの内容は?

ディスパッチャテーブルはRT(リアルタイム)、SYS(システム)、およびTS(タイムシェアリング)のクラスにわけられています。これらの全部をグローバル優先度として管理します。値が大きいと優先度が高いことを示しています。表5.1にその関係を示します。

表５．１　スケジューリングクラス

グローバル優先度の範囲 クラス名 対象
100〜159 RT リアルタイムクラス。システムでもっとも優先度の高いクラスです。グローバル優先度100〜109は割り込みスレッドです。
60〜99 SYS システムクラスです。
0〜59 TS/IA 一般の優先度であるタイムシェアリング、または対話型クラスです。

このディスパッチャテーブルの内容を表示・書き込みするコマンドがdispadminです。dispadminコマンド-lオプションは、構成されているクラスの一覧表を表示します。この構成一覧から目的のディスパッチャーテーブルを選択します。実際に設定可能なディスパッチャテーブルは、TSのタイムシェアリングクラスのみです。RT(リアルタイム)のディスパッチャテーブルは調整しない方が良いでしょう。チューニングの方法は、dispadminコマンドで表示されたテーブルの内容を変更して、同じくdispadminコマンドで書き込み、ディスパッチャのプロセス(スレッド)優先度の動作を変化させるというものです。よく行うチューニングは、ts_quantumの値や、次に移されるプライオリティレベルを変更する方法です(あまり一般的ではありませんが、他のUNIXシステムのディスパッチャテーブルはSolarisのものと大きな違いがあります)。

# dispadmin -l CR>
CONFIGURED CLASSES
===================

SYS　　　（System Class)
TS　　　　(Time Sharing)
RT　　　　(Real Time)
IA　　　　 (Interactive)
# dispadmin -c TS -g <CR>
# Time Sharing Dispatcher Configuration
RES=1000
# ts_quantum ts_tqexp ts_slpret ts_maxwait ts_lwait PRIORITY LEVEL
200 0 50 0 50 # 0
200 0 50 0 50 # 1
：
200 0 50 0 50 # 8
200 0 50 0 50 # 9
160 0 51 0 51 # 10
160 1 51 0 51 # 11
：
160 8 51 0 51 # 18
160 9 51 0 51 # 19
120 10 52 0 52 # 20
120 11 52 0 52 # 21
：
120 18 52 0 52 # 28
120 19 52 0 52 # 29
80 20 53 0 53 # 30
80 21 53 0 53 # 31
：
80 28 54 0 54 # 38
80 29 54 0 54 # 39
40 30 55 0 55 # 40
40 31 55 0 55 # 41
：
40 47 58 0 59 # 57
40 48 58 0 59 # 58
20 49 59 32000 59 # 59

#

図５．TSディスパッチャテーブルの内容(抜粋)

　

表５．２　ディスパッチャテーブルの内容

項目 内容
RES 秒あたりのレゾリューションで、1000の場合は1ミリ秒がその解像度になります。項目ts_quantumとts_maxwaitの単位になります。
ts_quantum この間、タイムシェアリングプロセス(スレッド)は中断しないで実行が許されます。このタイムクォンタムを使い切るとts_toexpに設定された優先度に置かれます。
ts_toexp ts_quantmを使い切るとそのプロセス(スレッド)が次ぎに移される優先度です。
ts_slpret プロセスがts_quantumを使い切る前に自分自身が入出力やその他のスリープに移った時、そのプロセス(スレッド)に割り当てられる優先度を示します。
ts_maxwait このレベルで実行されているプロセス(スレッド)が使うことを許される最大の時間です。
ts_lwait ts_maxwaitを経過すると次に割り当てられる優先度です。
PRIORITY LEVEL プライオリティのレベルです。高い値ほど優先度が高いことを示しています。

　

Eプライオリティを固定する方法は?

参考文献2の「ディスパッチテーブルをチューニングする」、「優先度を調整する」の「TSクラスの優先度を囲い込む(fence off)方法」に手順が記述されていますのでご覧下さい。本コンテンツでは解説を省略させていただきます。

　

FLWPの状態はどうなっているのか?

psコマンド-efcLオプションを使用すると、LWP(ライトウェイトプロセス)単位の状態を見ることができます。項目LWPはスレッドの番号、NLWPはそのプロセスの合計スレッド数を示しています。

# ps -efcL <CR>
UID PID PPID LWP NLWP CLS PRI STIME TTY LTIME CMD
root 0 0 1 1 SYS 96 12:04:59 ? 0:01 sched
root 1 0 1 1 TS 58 12:05:00 ? 0:04 /etc/init -
root 2 0 1 1 SYS 98 12:05:00 ? 0:00 pageout
root 3 0 1 1 SYS 60 12:05:00 ? 0:52 fsflush
root 73 1 1 7 TS 59 12:05:14 ? 0:00 devfsadmd
：
root 73 1 8 7 TS 59 12:05:16 ? 0:00 devfsadmd
：
root 335 333 1 5 TS 43 12:05:28 ? 0:00 htt_server -port 9010 -syslog -message_locale C
：
root 335 333 5 5 TS 53 12:05:29 ? 0:00 htt_server -port 9010 -syslog -message_locale C
root 354 1 1 1 TS 58 12:05:31 ? 0:00 /usr/lib/locale/ja/atokserver/atokmngdaemon
root 388 1 1 1 TS 55 12:05:33 ? 0:00 /opt/SUNWspci2/bin/sunpcid
daemon 348 1 1 3 TS 32 12:05:30 ? 0:00 /usr/lib/ab2/dweb/sunos5/bin/dwhttpd /usr/lib/ab2/dweb/data
：
daemon 349 348 4 4 TS 59 12:05:30 ? 0:00 /usr/lib/ab2/dweb/sunos5/bin/dwhttpd /usr/lib/ab2/dweb/data
：
oracle 445 1 1 1 TS 59 12:07:53 ? 0:00 ora_pmon_ora900
oracle 447 1 1 16 TS 59 12:07:53 ? 0:00 ora_dbw0_ora900
：
oracle 447 1 16 16 TS 60 12:39:06 ? 0:00 ora_dbw0_ora900
oracle 449 1 1 11 TS 59 12:07:53 ? 0:00 ora_lgwr_ora900
：
oracle 449 1 11 11 TS 58 12:08:01 ? 0:00 ora_lgwr_ora900
oracle 451 1 1 11 TS 58 12:07:53 ? 0:52 ora_ckpt_ora900
：
oracle 451 1 11 11 TS 58 12:08:03 ? 0:00 ora_ckpt_ora900
oracle 453 1 1 1 TS 58 12:07:53 ? 0:01 ora_smon_ora900
oracle 455 1 1 1 TS 58 12:07:53 ? 0:00 ora_reco_ora900
oracle 457 1 1 1 TS 59 12:07:53 ? 0:00 ora_cjq0_ora900
oracle 459 1 1 1 TS 59 12:07:53 ? 0:00 ora_s000_ora900
oracle 461 1 1 1 TS 59 12:07:54 ? 0:00 ora_d000_ora900
oracle 463 1 1 1 TS 59 12:07:54 ? 0:00 ora_d001_ora900
oracle 465 1 1 1 TS 59 12:07:54 ? 0:00 ora_d002_ora900

#

図７．psコマンド-efcLオプション(抜粋)

　

Gカーネルコンポーネントの統計情報は?

Solaris 8以降ではkstatコマンド【備考1】、全てのSolarisレベルではnetstatコマンド-kオプション【備考2】でさまざまなカーネルコンポーネントの統計情報を出力することが出来ます。kstatの引数無し、およびnetstatコマンド-kオプションも大量の情報が出ますので、一旦ファイルに書き込んでから参照されると良いでしょう。kstatはモジュール、インスタンス、名前等を指定することで目的の統計情報を選択出来るようになっています。次に例を示します。

kstatコマンドによるIPCセマフォの統計情報 netstatコマンド -kオプションで出力したIPCセマフォの統計情報
# kstat vme:39:semaphore <CR>
module: vmem instance: 39
name: semaphore class: vmem
alloc 4
contains 0
contains_search 0
crtime 225.3602432
fail 0
free 3
lookup 0
mem_import 0
mem_inuse 154
mem_total 1024
populate_fail 0
populate_wait 0
search 8
snaptime 16892.09894
vmem_source 0
wait 0
#
# netstat -k | tail -5 <CR>
semaphore:
mem_inuse 154 mem_import 0 mem_total 1024 vmem_source 0 alloc 4
free 3 wait 0 fail 0 lookup 0 search 8 populate_wait 0
populate_fail 0 contains 0 contains_search 0

#

【備考】

１． kstatコマンドはperlスクリプトです。興味のある方はエディタでご覧下さい。
２． 将来にわたってnetstatコマンド-kオプションの出力は保証されないとベンダーは言っています。困った…

図８．カーネルコンポーネントの統計情報

　

Hカーネルコンポーネントの動きは?

カーネルの詳細な動きを調べてみます。コマンドはSolaris2.6以前とSolaris8以降に違いがあります。最初にSolaris2.6のkgmon/gprofを紹介します。

Solaris2.6カーネルプロファイラ

次のようにkgmonコマンドでカーネルプロファイラを起動し、gprofによって情報を編集します。

# kgmon -i <CR>
one moment
disabling module unloading.
NOTE:modules loaded after this point will not be profiled.

profiling has been initialized
WARNING:call graph profiling is not compiled into this kernel
WARNING:only clock sample profiling is available
# kgmon -b <CR>
kernel profiling for cpu 1, is running【備考】

　[[ この間にプロセスやトランザクションを実行します。 ]]

# kgmon -h <CR>
kernel profiling for cpu 1, is off
# kgmon -p <CR>
dumping cpu 1 - one moment
a.out symbols for the kernel and modules have been dumped to gmon.syms
profiling data has been dumped to gmon[n].out
# /usr/ccs/bin/gprof gmon.syms gmon1.out > cpu1profile <CR>
#

【備考】CPUが32個以上のシステムでは採取できませんでした（経験的情報です）。

図９．１　Solaris2.6カーネルプロファイラ

次はプロファイラの出力例(抜粋)です。なお、各ファンクションのアルファベット順インデックスは省略させていただきます。

granularity: each sample hit covers 2 byte(s) for 0.05% of 23.75 seconds
% cumulative self self total
time seconds seconds calls ms/call ms/call name
24.7 5.86 5.86 splx[1]
23.5 11.43 5.57 disp_getwork[2]
13.8 14.71 3.28 idle[3]
11.2 1738 2.67 spltty[4]
3.1 18.12 0.75 spl0[5]
2.2 18.64 0.52 splzs[6]
2.1 19.13 0.49 diap_ratify[7]
1.3 19.43 0.6 bcopy[8]
1.1 19.99 0.27 sfmmutteload_addentry[9]
0.7 20.13 0.18 mutex_enter[10]
0.7 20.18 0.15 hwblkclr[11]

図９．２　kgmon/gprofプロファイラの出力例

続いてSolaris8のカーネルトレースを紹介します。

Solaris8カーネルトレース

次のように、prexコマンドでトレースをセットし、tnfxtracｔコマンドでデータを抽出、tnfdumpコマンドで編集します。prexの解説はprex(1)カーネルトレースをご覧下さい。

# prex -k <CR>
Type "help" for help ...
prex> buffer alloc 4m <CR>
Buffer of size 4194304 bytes allocated
prex> enable $all <CR>
prex> trace $all <CR>
prex> ktrace on <CR>

　　　　　　：　この間にトレースしたい処理を実行します。

prex> ktrace off <CR>
prex> quit <CR>
# tnfxtract tracefile.trc <CR>
# tnfdump tracefile.trc > tracefile.dump <CR>
#

図９．３　カーネルトレース

次にtnfdumpコマンドの出力例を示します(抜粋)。

---------- --------- ----- ---- ----- ------ ------------ ------ ------------ ---- ----------- ------ -- ----------
Elapsed(ms) Delta(ms) PID LWPID TID CPU Probe Name Data / Description
---------- --------- ----- ---- ----- ------ ------------ ------ ------------ ---- ----------- ------ -- ----------
0 0 435 1 0x300 0 syscall_end rval1: 0 rval2: 4 errno: 0
0.0624 0.0624 435 1 0x300 0 syscall_start sysnum: 4
0.1094 0.047 435 1 0x300 0 syscall_end rval1: 6 rval2: 6 errno: 0
0.1212 0.0118 435 1 0x300 0 syscall_start sysnum: 3
0.1598 0.0386 435 1 0x300 0 thread_block reason: 0x300021d2a02 stack: <tnf_symbols>
0.1776 0.0178 435 1 0x300 0 thread_state state: 7
0.1868 0.0092 435 1 0x300 0 thread_state tid: 0x2a10001fd20 state: 1
4276.9288 4276.742 0 0 0x2a1 0 thread_block reason: 0x300007d3c58 stack: <tnf_symbols>
4276.9364 0.0076 0 0 0x2a1 0 thread_state state: 7
4276.9372 0.0008 0 0 0x2a1 0 thread_state tid: 0x30001885c40 state: 1
5733.5158 1456.5786 0 0 0x2a1 0 thread_block reason: 0x300007d3c58 stack: <tnf_symbols>
5733.5242 0.0084 0 0 0x2a1 0 thread_state state: 7
5733.525 0.0008 0 0 0x2a1 0 thread_state tid: 0x30001aaf440 state: 1
7900.4296 2166.9046 0 0 0x2a1 0 thread_block reason: 0x300007d3c58 stack: <tnf_symbols>
7900.4354 0.0058 0 0 0x2a1 0 thread_state state: 7
7900.4362 0.0008 0 0 0x2a1 0 thread_state tid: 0x30001e1e440 state: 1
8684.9232 784.487 0 0 0x2a1 0 thread_block reason: 0x300007d3c58 stack: <tnf_symbols>
8684.9304 0.0072 0 0 0x2a1 0 thread_state state: 7
8684.9314 0.001 0 0 0x2a1 0 thread_state tid: 0x30001e5ba60 state: 1
12740.737 4055.8056 374 1 0x300 0 syscall_end rval1: 0 rval2: 24 errno: 0
12740.7594 0.0224 374 1 0x300 0 syscall_start sysnum: 43
12740.7638 0.0044 374 1 0x300 0 syscall_end rval1: 614499 rval2: 3.29857E+12 errno: 0
12740.7806 0.0168 374 1 0x300 0 syscall_start sysnum: 87
12740.792 0.0114 374 1 0x300 0 thread_block reason: 0x30001c74e02 stack: <tnf_symbols>
12740.7986 0.0066 374 1 0x300 0 thread_state state: 7
12740.7994 0.0008 374 1 0x300 0 thread_state tid: 0x2a10001fd20 state: 1
13400.6996 659.9002 0 0 0x2a1 0 thread_create tid: 0x2a100831d20 pid: 0 start_pc: 0x7815434c
13400.7054 0.0058 0 0 0x2a1 0 thread_queue tid: 0x2a100831d20 cpuid: 0 priority: 60 queue_length: 0
13400.7068 0.0014 0 0 0x2a1 0 thread_state tid: 0x2a100831d20 state: 8
13400.7124 0.0056 0 0 0x2a1 0 thread_block reason: 0x2a10058beb2 stack: <tnf_symbols>
13400.7182 0.0058 0 0 0x2a1 0 thread_state state: 7
13400.7192 0.001 0 0 0x2a1 0 thread_state tid: 0x2a100831d20 state: 1
15363.6284 1962.9092 219 1 0x300 0 syscall_end rval1: 0 rval2: 4290705264 errno: 0
15363.6328 0.0044 219 1 0x300 0 syscall_start sysnum: 95
15363.634 0.0012 219 1 0x300 0 syscall_end rval1: 0 rval2: 0 errno: 0
15363.6366 0.0026 219 1 0x300 0 syscall_start sysnum: 95
15363.6384 0.0018 219 1 0x300 0 syscall_end rval1: 0 rval2: 4290705264 errno: 0
15363.6508 0.0124 219 1 0x300 0 syscall_start sysnum: 87
15363.86 0.2092 219 1 0x300 0 thread_block reason: 0x300015643da stack: <tnf_symbols>
15363.8646 0.0046 219 1 0x300 0 thread_state state: 7
15363.8652 0.0006 219 1 0x300 0 thread_state tid: 0x2a10001fd20 state: 1
22305.8478 6941.9826 276 1 0x300 0 thread_state state: 7
22305.849 0.0012 276 1 0x300 0 thread_state tid: 0x3000169f960 state: 0
23520.642 1214.793 0 0 0x2a1 0 thread_queue tid: 0x2a100071d20 cpuid: 0 priority: 99 queue_length: 0
23520.644 0.002 0 0 0x2a1 0 thread_state tid: 0x2a100071d20 state: 8
24290.6388 769.9948 0 0 0x2a1 0 thread_queue tid: 0x2a100077d20 cpuid: 0 priority: 99 queue_length: 0
24290.6406 0.0018 0 0 0x2a1 0 thread_state tid: 0x2a100077d20 state: 8
25280.6458 990.0052 0 0 0x2a1 0 thread_queue tid: 0x2a100071d20 cpuid: 0 priority: 99 queue_length: 1
25280.6474 0.0016 0 0 0x2a1 0 thread_state tid: 0x2a100071d20 state: 8
25430.6406 149.9932 0 0 0x2a1 0 thread_queue tid: 0x2a100077d20 cpuid: 0 priority: 99 queue_length: 1
25430.6416 0.001 0 0 0x2a1 0 thread_state tid: 0x2a100077d20 state: 8
29402.7118 3972.0702 0 0 0x2a1 0 thread_block reason: 0x300007d3e38 stack: <tnf_symbols>

図９．４　tnfdumpの出力(抜粋)

表9に項目の内容を示します。

表９．tnfdumpの出力項目

項目 内容
Elapsed(ms) ミリ秒(ms)単位の最初のプローブからの経過時間。
Delta(ms) ミリ秒(ms)単位の処理時間。
PID プロセスID
LWPID LWPのID
TID トレースID
CPU 実行CPU
Probe Name プローブ名
Data 各プローブに対応したデータ。
Description 詳細な情報【備考】

【備考】プローブによって内容が異なります。prex(1)カーネルトレースをご覧下さい。

　

ICPUイベントの内訳は?

CPUに発生している各種イベントの見方を解説します(ここまで詳細に調査することは稀ですが…)。

# cpustat -h <CR>
Usage:
　　　　　　cpustat [-c events] [-nhD] [interval [count]]

　　　　　　-c events specify processor events to be monitored
　　　　　　-n suppress titles
　　　　　　-t include %tick register
　　　　　　-D enable debug mode
　　　　　　-h print extended usage information

　　　　　　Use cputrack(1) to monitor per-process statistics.

　　　　　　CPU performance counter interface: UltraSPARC III+

　　　　　　events pic0=<event0>,pic1=<event1>[,sys][,nouser]

　　　　　　event0: 　Cycle_cnt Instr_cnt Dispatch0_IC_miss IC_ref DC_rd DC_wr
　　　　　　　　　　　　EC_ref EC_snoop_inv Dispatch0_br_target Dispatch0_2nd_br
　　　　　　　　　　　　Rstall_storeQ Rstall_IU_use EC_write_hit_RTO EC_rd_miss
　　　　　　　　　　　　PC_port0_rd SI_snoop SI_ciq_flow SI_owned SW_count_0
　　　　　　　　　　　　IU_Stat_Br_miss_taken IU_Stat_Br_count_taken
　　　　　　　　　　　　Dispatch_rs_mispred FA_pipe_completion MC_reads_0
　　　　　　　　　　　　MC_reads_1 MC_reads_2 MC_reads_3 MC_stalls_0 MC_stalls_2
　　　　　　　　　　　　EC_wb_remote EC_miss_local EC_miss_mtag_remote

　　　　　　event1: 　Cycle_cnt Instr_cnt Dispatch0_mispred EC_wb EC_snoop_cb
　　　　　　　　　　　　IC_miss_cancelled Re_FPU_bypass Re_DC_miss Re_EC_miss
　　　　　　　　　　　　IC_miss DC_rd_miss DC_wr_miss Rstall_FP_use EC_misses
　　　　　　　　　　　　EC_ic_miss Re_PC_miss ITLB_miss DTLB_miss WC_miss
　　　　　　　　　　　　WC_snoop_cb WC_scrubbed WC_wb_wo_read PC_soft_hit
　　　　　　　　　　　　PC_snoop_inv PC_hard_hit PC_port1_rd SW_count_1
　　　　　　　　　　　　IU_Stat_Br_miss_untaken IU_Stat_Br_count_untaken
　　　　　　　　　　　　PC_MS_misses MC_writes_0 MC_writes_1 MC_writes_2
　　　　　　　　　　　　MC_writes_3 MC_stalls_1 MC_stalls_3 Re_RAW_miss
　　　　　　　　　　　　FM_pipe_completion Re_DC_missovhd EC_miss_mtag_remote
　　　　　　　　　　　　EC_miss_remote

　　　　　　See the "SPARC V9 JPS1 Implementation Supplement: Sun
　　　　　　UltraSPARC-III+"
#

図１０．１　cpustatコマンドの出力

図10.1の11行目のpicは、Performance Instrumentation Counterの略です。このeventsをcputrackコマンドの引数に指定します。

# cputrack -c pic0=Cycle_cnt,pic1=Instr_cnt sweep <CR>
　　time lwp 　　　　 event　 pic0　　　　　pic1
　　1.024　 1　　　　　 tick　 549287730 361513532
　　2.014　 1 　　　　　tick　 471780029 310465907
　　3.014　 1 　　　　　tick　 427952560 281452157
　　4.024　 1 　　　　　tick　 405079082 267091704
　　5.004　 1 　　　　　tick　 358544103 236641843
　　6.014　 1 　　　　　tick　 344758443 228059522
　　7.025　 1 　　　　　tick　 337806506 223112694
　　8.004　 1 　　　　　tick　 306581324 202556383
#

図１０．２　cputrackコマンドの出力例

cpustatで表示されるイベント詳細は、UltraSPARC III Cu User's Manual( http://www.sun.com/processors/manuals/USIIIv2.pdf…CPUアーキテクチャによってマニュアル名称、およびURLアドレスが異なります)をご覧ください。また、参考文献2にすっきりとまとまった表がありますので、ご覧ください。　

　

Copyright (C) 2004 by The Art of Computer Technologies, Corp.  All rights reserved.