2009年 1月 27日 火曜日
やっぱり Sun がスキ！
2009年 1月 27日 火曜日
sys の原因を解析するコマンドの紹介
はじめに
サーバ OS として Solaris が素晴らしい点の一つは信頼性の高い解析ツールが豊富に用意されている事です（その最も顕著な例が DTrace です）。今回は Solaris の解析コマンドを使用して sys(system time) の発生原因を探る手順をご紹介致します。
システムの負荷が高い状態をチューニングで解決しようと考えた時に、闇雲にパラメータを弄るのは非効率的です。まず何が高負荷の要因になっているのかをある程度正確に把握しておく必要があります。CPU 使用率に占める usr の割合が高い場合はプログラムの中に書かれている処理が CPU を使用していますので、どの処理が負荷の原因になっているかを見極めるのは比較的容易です。反対に sys の割合が高い場合はシステム全体の解析が必要になるため、プログラムの知識に加えて OS の知識も必要になります。
sys の原因は大きく分けて二つ考えられます。一つはシステムコールに起因する物、もう一つはシステムコール以外のカーネルサービスに起因する物です。システムコールに起因する sys は、プログラムが呼び出した write(2) や poll(2) 等のシステムコールに費やされた時間です。システムコールの情報はプロセスの統計情報を参照する事で把握する事が出来ます。システムコール以外のカーネルサービスは、ファイルシステムやスケジューラ、インタラプト処理など、直接プロセスから呼び出されていない、カーネル内に閉じた処理の事です。これに起因する sys を測定するのはそれ程容易ではありません。
今回ご紹介する手順に沿ってシステムコールやカーネルサービスを調査していけば、比較的簡単にシステムの状態の把握が可能になると思います。
解析の手順
それでは実際に解析の手順を見て行きましょう。
vmstat
まずは vmstat で本当に sys が多いのかを確認します。目安としては cpu の sy のカラムが 20 を超えていたら気に掛ける様にして下さい。それ以下であれば恐らく問題はありません。なお vmstat の一行目の出力はシステムの負荷を正確に反映していない場合がありますので、無視して下さい。
# vmstat 1 kthr memory page disk faults cpu r b w swap free re mf pi po fr de sr s0 s1 -- -- in sy cs us sy id 0 0 0 13641088 12323600 42 20 35 1 1 0 1 -0 1210 0 0 3998 27188 12648 2 2 97 <-- これは無視 0 1 0 12892448 10997300 2 69 57 0 0 0 0 0 5675 0 0 17012 124915 58163 8 7 85 0 1 0 12892296 10997184 0 15 0 0 0 0 0 0 5705 0 0 16958 125244 58293 8 7 85
sy の値が低い場合でも、念のため mpstat の出力も併せて見て頂いた方が良いかもしれません。マルチプロセッサシステムでシングルスレッドのプログラムを実行している場合は vmstat だけでは十分な情報が得られない事があります。
cpu の sy が少ない -> mpstat
次に faults の sy を見ます。この値はシステムコールの回数です。これが多い場合は prstat コマンドでどのプロセスがシステムコールの発生源になっているのか、システムコールでどのくらいの CPU 時間を消費しているのかを観察します。
faults の sy が多い -> prstat -m
faults の sy がそれ程多くない場合、同じく faults の in を見て下さい。この値はインタラプトの回数です。インタラプトが多い場合は intrstat を使用して、インタラプトの発生源等の詳細を確認して下さい。
faults の in が多い -> intrstat
mpstat
vmstat と異なり、mpstat ではプロセッサコア毎の統計情報を見る事が可能です。また、コンテクストスイッチやインタラプト、プロセッサ間クロスコールに付いてもより詳細に見る事が出来ます。
# mpstat 1 ... CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl 0 0 0 1470 1171 141 10099 341 1135 158 0 21185 21 17 0 62 1 32 0 1990 750 0 9594 283 966 109 0 21531 23 17 0 60 2 0 0 1218 6274 5556 8033 202 718 89 0 17645 19 24 0 57 3 0 0 1080 710 0 8221 157 635 115 0 17966 19 14 0 67 4 0 0 832 598 2 2902 25 220 41 0 6161 7 4 0 89 5 26 0 535 650 2 5150 57 317 81 0 11080 11 9 0 80 6 0 0 0 647 14 58 3 5 0 0 117 1 0 0 99 7 0 0 297 617 0 725 8 50 15 0 1404 2 1 0 97 8 0 0 327 649 0 4051 39 197 76 0 8893 9 7 0 84 9 0 0 0 637 0 0 0 0 0 0 0 0 0 0 100 10 0 0 149 622 0 482 1 26 11 0 932 1 1 0 98 11 0 0 1010 598 0 3705 36 155 69 0 7467 7 6 0 87 12 0 0 0 631 0 0 0 0 0 0 0 0 0 0 100 13 0 0 0 643 0 431 1 22 13 0 740 0 0 0 100 14 0 0 570 627 0 3720 31 154 67 0 7503 7 6 0 87 15 0 0 0 637 0 0 0 0 0 0 0 0 0 0 100
まずは sys のカラムをご覧下さい。シングルスレッドのプログラムが CPU 資源を有効に使えていない場合などは、特定の CPU だけ sys が高く、他の CPU では idle 状態になっている場合もありますので注意して見て下さい。mpstat でも sys の値が 20% を下回っている場合は sys は問題無いと判断しても良いと思います。
次に syscl を見て下さい。syscl はシステムコールの回数です。syscl の値が多い場合は prstat コマンドでどのプロセスが sys の発生源かを探して下さい。
syscl が多い -> prstat -m
intr と ithr はインタラプトの回数です。intr の方は clock よりも高い優先順位を持ったインタラプトの回数で、インタラプトが発生した処理の続きでインタラプトハンドラが実行されます。ithr は優先順位が低いインタラプトの回数で、この場合インタラプトの処理は専用のスレッドを生成して引き継がれます。インタラプトが使用する CPU 資源については intrstat コマンドで細かく見る事が出来ます。
intr, ithr が高い -> intrstat
csw と icsw はコンテクストスイッチの回数です。icsw は involuntary なコンテクストスイッチで、強制的に CPU を奪われた回数です。コンテクストスイッチも CPU 資源を消費しますので、特に icsw が高い場合はスレッドやプロセスの数を減らすなど調整してみて下さい。
icsw が多い -> スレッド数、プロセス数を減らす
システムコールもインタラプトもそれ程多くない場合は、それ以外のカーネルサービスで CPU を使っている可能性があります。カーネルサービスの状況は lockstat コマンドで調べる事が出来ます。
syscl, intr, ithr はそれ程高くない -> lockstat -I
prstat -m
prstat はプロセス毎のコンピュータ資源の利用状況を確認するコマンドです。この prstat に -m オプションを付けると、プロセスが発生させている sys の割合が SYS カラムに出力されます。
# prstat -m 1
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP
2816 root 2.9 1.4 0.0 0.0 0.0 82 14 0.2 19K 1K 94K 0 mysqld/42
7061 root 0.2 0.7 0.0 0.0 0.0 0.0 99 0.1 9K 38 28K 0 mysqlbench/33
7064 root 0.0 0.2 0.0 0.0 0.0 0.0 100 0.0 6 0 194 0 prstat/1
6626 root 0.0 0.2 0.0 0.0 0.0 0.0 100 0.0 22 0 146 0 prstat/1
816 noaccess 0.0 0.0 0.0 0.0 0.0 68 32 0.0 19 0 19 0 java/19
Total: 53 processes, 273 lwps, load averages: 2.09, 2.13, 2.16
SYS の高いプロセスを見つけたら、どのシステムコールが sys の直接的な原因になっているか確認してみましょう。プロセスがどんなシステムコールを発生させていて、どのくらい CPU 時間を使用しているかは truss コマンドで調べる事が出来ます。
prstat -m で SYS が高いプロセスを見つけたら -> truss -c
truss -c
truss コマンドは主にプロセスの発生させるシステムコールを追跡するコマンドです。truss に -c オプションを付け、-p でプロセス ID を指定すると、そのプロセスが発生させたシステムコールの種類と回数、システムコールの処理に費やした時間を調べる事が出来ます。
# truss -c -p `pgrep -f mysql`
^C
syscall seconds calls errors
read .394 15835 4613
write .242 6413
time .240 11401
fdsync .161 1605
fcntl .188 9226
lwp_park .089 2529
lwp_unpark .061 2529
yield .004 106
pwrite .059 1605
pollsys .095 3540
-------- ------ ----
sys totals: 1.536 54789 4613
usr time: 1.051
elapsed: 3.290
truss -c は Ctrl-C で停止させるまでプロセスをトレースし続けますので、適当な時間（10 - 30 秒程度）が経過したら Ctrl-C を入力して下さい。トレースをしていた時間は elapsed: に表示されます。
syscall のカラムがシステムコールの名前で seconds のカラムにはそのシステムコールの実行に費やした時間です。sys の原因となっているシステムコールが特定出来ましたら、truss や DTrace を使ってもう少し詳しく調べる事が可能です。
システムコールの引数と返り値を調べたい -> truss システムコールを呼び出している関数を調べたい -> dtrace -n syscall:::
一般的に truss は CPU 負荷の高い処理になりますので、本番環境で使用する際は注意が必要です。テスト環境などに擬似的な負荷を発生させて使用するのがお薦めです。
truss
truss コマンドを -c オプションを付けずに実行すると、システムコールの実行をトレースする事が出来ます。次のコマンドを実行すると、システムコールが発行された順番、システムコールの実行に掛かった時間、システムコールに渡された引数と返り値を表示する事が出来ます。
# truss -vall -E -p `pgrep -f mysql`
2816/74648: 0.0000 time() = 1232696048
2816/74648: 0.0000 time() = 1232696048
2816/74648: 0.0000 write(44, " 0\0\001\001\003\0\0\0 (".., 52) = 52
2816/74640: 0.0000 time() = 1232696048
2816/74648: 0.0000 read(44, 0xA6D0BE48, 4) Err#11 EAGAIN
2816/74640: 0.0000 write(14, "F0 r y I0201\0\0\0 D\0\0".., 645) = 645
2816/74648: 0.0000 fcntl(44, F_SETFL, FWRITE) = 0
2816/74649: 0.0000 lwp_park(0x00000000, 0) = 0
2816/74640: 0.0000 lwp_unpark(74649) = 0
2816/74649: 0.0000 pollsys(0xFFFFFD7FFA37AC80, 0, 0xFFFFFD7FFA37AD10, 0x00000000) = 0
dtrace -n syscall:::
DTrace を使用すると特定のシステムコールについて truss よりも更に詳しく解析する事が出来ます。
システムコールが呼び出された際のスタックダンプを取るには DTrace の ustack() アクションを使用します。以下の例では MySQL のプロセスが lwp_park というシステムコールを呼び出す毎にスタックをダンプさせています。
# dtrace -n 'syscall::lwp_park:entry /execname == "mysqld"/ { ustack(11) }'
dtrace: description 'syscall::lwp_park:entry ' matched 1 probe
CPU ID FUNCTION:NAME
0 68021 lwp_park:entry
libc.so.1`__lwp_park+0x17
libc.so.1`cond_wait_queue+0x59
libc.so.1`_cond_wait+0x57
libc.so.1`cond_wait+0x26
libc.so.1`pthread_cond_wait+0x9
mysqld`os_event_wait_low+0x41
mysqld`sync_array_wait_event+0xda
mysqld`mutex_spin_wait+0x139
mysqld`mutex_enter_func+0x32
mysqld`srv_suspend_mysql_thread+0x1c0
mysqld`row_mysql_handle_errors+0xae
- ustack() アクションについては http://docs.sun.com/app/docs/doc/819-0395/chp-user-4 をご覧下さい。
- Java の場合は jstack() というアクションが用意されています。
intrstat
intrstat はインタラプトの統計情報を出力するコマンドです。どのデバイスがどの CPU 上でどのくらいインタラプト処理を実行しているかを見る事が出来ます。
# intrstat 1
device | cpu0 %tim cpu1 %tim cpu2 %tim cpu3 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 11192 8.5 0 0.0
ahci#0 | 0 0.0 0 0.0 11192 1.4 0 0.0
e1000g#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
pcie_pci#7 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 11192 1.8 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 0 0.0
device | cpu4 %tim cpu5 %tim cpu6 %tim cpu7 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#0 | 0 0.0 0 0.0 10 0.0 0 0.0
ehci#0 | 21 0.1 0 0.0 0 0.0 0 0.0
pcie_pci#7 | 0 0.0 2 0.0 0 0.0 0 0.0
uhci#0 | 21 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 1 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 2 0.0 0 0.0 0 0.0
device | cpu8 %tim cpu9 %tim cpu10 %tim cpu11 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
pcie_pci#7 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 0 0.0
device | cpu12 %tim cpu13 %tim cpu14 %tim cpu15 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
pcie_pci#7 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 0 0.0
mdb -k
mdb を使う事でもう少し詳しくインタラプトを観察する事が出来ます。
# echo "::interrupts -d" | mdb -k IRQ Vector IPL Bus Type CPU Share APIC/INT# Driver Name(s) 3 0xb1 12 ISA Fixed 3 1 0x0/0x3 asy#0 4 0xb0 12 ISA Fixed 3 1 0x0/0x4 asy#1 9 0x81 9 PCI Fixed 1 1 0x0/0x9 acpi_wrapper_isr 16 0x22 1 PCI Fixed 5 2 0x0/0x10 pcie_pci#7, uhci#3 18 0x21 1 PCI Fixed 5 1 0x0/0x12 uhci#2 19 0x40 5 PCI Fixed 2 3 0x0/0x13 ahci#0, uhci#1, aac#0 23 0x20 1 PCI Fixed 4 2 0x0/0x17 uhci#0, ehci#0 48 0x60 6 MSI 6 1 - e1000g#0 49 0x61 6 MSI 6 1 - e1000g#2 50 0x62 6 MSI 6 1 - e1000g#1 51 0x63 6 MSI 6 1 - e1000g#3 160 0xa0 0 IPI ALL 0 - poke_cpu 192 0xc0 13 IPI ALL 1 - xc_serv 208 0xd0 14 IPI ALL 1 - kcpc_hw_overflow_intr 209 0xd1 14 IPI ALL 1 - cbe_fire 210 0xd3 14 IPI ALL 1 - cbe_fire 240 0xe0 15 IPI ALL 1 - xc_serv 241 0xe1 15 IPI ALL 1 - apic_error_intr
kstat
どのレベルのインタラプトが発生しているかを測定するだけであれば kstat を使用する事も出来ます。
# kstat -p 'cpu::intrstat:level*' 1 cpu:0:intrstat:level-1-count 13431448 cpu:0:intrstat:level-1-time 66632929204 cpu:0:intrstat:level-10-count 34384473 cpu:0:intrstat:level-10-time 477870160557 cpu:0:intrstat:level-11-count 20594751 cpu:0:intrstat:level-11-time 3803066006 cpu:0:intrstat:level-12-count 2 cpu:0:intrstat:level-12-time 11658 cpu:0:intrstat:level-13-count 0 cpu:0:intrstat:level-13-time 0 cpu:0:intrstat:level-14-count 34384470 cpu:0:intrstat:level-14-time 83996830975 cpu:0:intrstat:level-15-count 42011399 cpu:0:intrstat:level-15-time 153309580077 cpu:0:intrstat:level-2-count 34384473 cpu:0:intrstat:level-2-time 23093190867 cpu:0:intrstat:level-3-count 160 cpu:0:intrstat:level-3-time 5098702 cpu:0:intrstat:level-4-count 28 cpu:0:intrstat:level-4-time 63455 cpu:0:intrstat:level-5-count 383 cpu:0:intrstat:level-5-time 2486365 cpu:0:intrstat:level-6-count 0 cpu:0:intrstat:level-6-time 0 cpu:0:intrstat:level-7-count 0 cpu:0:intrstat:level-7-time 0 cpu:0:intrstat:level-8-count 0 cpu:0:intrstat:level-8-time 0 cpu:0:intrstat:level-9-count 0 cpu:0:intrstat:level-9-time 0 cpu:1:intrstat:level-1-count 1 ... snip ...
trapstat
SPARC システムではインタラプトを含むトラップの統計情報を trapstat で取得する事が出来ます。
# trapstat 1 vct name | cpu0 cpu1 ------------------------+------------------ 24 cleanwin | 852 643 41 level-1 | 89 5 44 level-4 | 2 0 46 level-6 | 0 28 49 level-9 | 3 3 4a level-10 | 100 0 4d level-13 | 2 1 4e level-14 | 102 6 60 int-vec | 6 33 64 itlb-miss | 4651 4556 68 dtlb-miss | 2994 4140 6c dtlb-prot | 0 1 84 spill-user-32 | 4130 4239 8c spill-user-32-cln | 265 230 98 spill-kern-64 | 1596 993 a4 spill-asuser-32 | 1017 871 ac spill-asuser-32-cln | 1009 449 c4 fill-user-32 | 3976 4134 cc fill-user-32-cln | 2210 1491 d8 fill-kern-64 | 1414 960 108 syscall-32 | 578 364 124 getts | 243 206 126 self-xcall | 3 3 127 gethrtime | 407 348 ... snip ...
lockstat -I
lockstat コマンドはその名の通りロックに関する統計情報を取得するツールですが、カーネルプロファイラの機能も持っています。-I オプションでカーネルのプロファイルを取る事が出来ます。
以下のコマンドを実行すると、カーネル内のどのルーチンに時間を費やしているか、おおよその情報を得る事が出来ます。
# lockstat -kgIW sleep 10 # lockstat -kIW sleep 10
- -k オプションはインストラクションのアドレスが異なっていても同じ関数内であれば一つのエントリにまとめます。
- -W オプションはロックのアドレスが異なっていても同じ関数内であれば一つのエントリにまとめます。
- -I オプションはカーネルプロファイリングを有効にします。
- -g を付けるとスタックトップにある関数だけでなく、スタックフレームにある関数全てを集計対象にします。
その他のコマンド
Solaris に付属しないコマンドや、直接解析をするコマンドではない物も含めて、負荷状況を調査するのに便利なコマンドをご紹介します。
Solaris CAT
Solaris CAT は Solaris Crash Analysis Tool の略で、主にクラッシュダンプを解析するツールですが、稼働中の OS の解析にも使う事が出来ます。最新版の 5.0 を以下の URL からダウンロードする事が出来ます。
combined 版をダウンロードして pkgadd すると /opt/SUNWscat/bin に scat コマンドがインストールされます。
# gunzip SUNWscat5.0-GA-combined.pkg.gz
# pkgadd -d ./SUNWscat5.0-GA-combined.pkg
# PATH=/opt/SUNWscat/bin:${PATH}; export PATH
# which scat
/opt/SUNWscat/bin/scat
scat コマンドを実行すると Solaris CAT のプロンプトが表示されます。このプロンプトに tlist -h -s pctcpu と入力すると、ユーザ空間のスレッドに紐づいているカーネルスレッドについて、凡その CPU 使用率を見る事が出来ます。
# scat > tlist -h -s pctcpu thread pri pctcpu idle PID wchan command 0xffffffff82f77460 60 1.769 -0.78s 3 0xfffffffffbccbe00 fsflush 0xffffffff8ab5db60 59 0.048 -19m49.90s 24581 0xffffffff8d81ccc2 /usr/sbin/in.telnetd 0xffffffff832b07a0 59 0.043 -19m49.96s 140 0 /usr/lib/crypto/kcfd ... snip ...
Solaris CAT には他にも便利な機能が沢山ありますので、是非お試し下さい。
psradm
psradm コマンドは CPU を管理するコマンドです。psradm に -i オプションを渡すと特定の CPU 上でインタラプトを発生させない様にする事が出来ます。特定のプロセッサからインタラプトを排除する事で処理性能が上がる場合があります。
# psradm -i 4-8
psradm コマンドに -f オプションを付けると、特定の CPU にスレッドがスケジューリングされない様にする事が出来ます。これは実質的に CPU 数を変更させたのと一緒です。CPU 数を動的に変更し、sys の割合に変化があるかを見てみる事で状況把握に繋がるケースもありますのでお試し下さい。
# psradm -f 4-8
sys が高い状態を意図的に作り出す
これまで出て来たコマンドをテストする為に、簡単に sys が高い状態を作り出せる方法があると便利です。
# cat /dev/zero > /dev/null
/dev/zero を cat して /dev/null にリダイレクトする事で大量の read(2) と write(2) を発生させる事が出来ます。こちらの記事もご参照下さい。
参考文献
DTrace を使用したカーネルスレッドの追跡方法は加藤さんの blog でも紹介されていますのでご参照下さい。
おわりに
以上、Solaris 上で sys の解析をする手順をご紹介致しました。プログラムの性能には様々な要素が影響してきますので、必ずしも完全に解析出来る物ではありませんが、問題解決の指針を決める際に参考にして頂ければと思います。また、本記事は私の経験則やマニュアルの記載、一部 Solaris の実装を元にして書いておりますが、もし間違い等がございましたらご指摘下さい。
Posted at 03:10午後 1 27, 2009 by Daisuke Homma in Sun | 投稿されたコメント[0]
投稿されたコメント:
Subscribe!