2009年 9月 17日 木曜日
やっぱり Sun がスキ！
2009年 9月 17日 木曜日
plockstat コマンドでロックの競合を調べる
はじめに
今回は Solaris の plockstat(1M) コマンドを使ってユーザプロセスのロックの競合を解析する方法をご紹介したいと思います。大規模 SMP マシンや CMT マシンで長く運用されて来た歴史柄、Solaris は CPU スケーラビリティに非常に気を使っている OS です。カーネルサービスがスケールするだけでなく、ユーザプロセスの処理の並列度が十分に上がらない場合の分析ツールも揃っています。今回紹介する plockstat もそういったツールの一つで、プロセス内のロックを解析する為のコマンドです。plockstat コマンドを使うことで、プロセス内のロックの取得と競合の回数や原因を調査する事が可能です。
plockstat の 'p' はプロセスの 'p' なので私は「ぴーろっくすたっと」と読んでいますが、'p' が付かない lockstat というコマンドもあり、こちらはカーネル内のロックを観測するコマンドです。どちらもベンチマークやトラブルシューティングでは非常に良く使用するコマンドですので、是非ご活用頂ければと思います。
plockstat コマンドについて
plockstat コマンドを使用すると、プロセス内のロックの『取得』と『競合』の発生を監視できます。ロックの取得では、1) 取得されたロックのアドレス、2) プログラムのどの部分からロックが取得されたか、3) そのロックが取得された回数、4) そのロックが解放されるまでの平均時間、を見る事が出来ます。一方ロックの競合は、1) 競合が発生しているロックのアドレス、2) プログラムのどの部分がロックの競合を発生させているか、3) そのロックで何回競合が発生したか、4) そのロックでブロックされていた平均時間、を見る事が出来ます。特にロックの競合（あるスレッドが保持しているロックを別のスレッドが取得しようとすること）はプログラムの実行性能に直結する、とても重要な要素です。その為、今回の記事ではロックの競合に重点を置いて見て行きたいと思います。
なお、plockstat コマンドで観察できるロックの種類は mutex ロックと reader/writer ロックです。ロックの競合は『コンテンション』と呼ばれる場合もあります。ロックの競合が発生して待たされている状態を『ロック待ち』と呼んだり、『（スレッドがロックで）ブロックされている』と表現する事があります。
plockstat コマンドの使い方
plockstat コマンドを使用する前に
plockstat はプロセス内のロックを観察するコマンドです。plockstat コマンドを使用する前にどのプロセスでロックの競合が発生しているかを確認しておく必要があります。ロックの競合が発生しているプロセスは prstat(1M) コマンドで探す事が出来ます。prstat コマンドには "-mL 1" オプションを付けて実行して下さい。"-m" オプションがロック待ちを検出する為のオプションです。prstat コマンドの出力の "LCK" のカラムがロックの競合で待たされている時間で、単位は % です。スレッド数やアプリケーションの実装にもよりますが、この値が定常的に高い値を示していたらロックの競合を気にした方が良いかもしれません。LCK が高くなっているプロセスを見つけたら、プロセス名とプロセス ID を調べてください。LCK の値が高くなっている行の "PROCESS" が該当プロセスのプロセス名、"PID" がプロセス ID、"LWPID" がスレッド ID です。
以下は prstat コマンドを実行した例です。ここでは "general" というプロセスのスレッド ID 2 番から 9 番のスレッドで約 50% のロック待ちが発生しています。
# prstat -mL 1
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
20904 root 48 4.0 0.0 0.0 0.0 47 0.0 1.1 3K 6 7K 0 general/6
20904 root 45 3.8 0.0 0.0 0.0 50 0.0 1.1 3K 20 7K 0 general/5
20904 root 45 3.9 0.0 0.0 0.0 50 0.0 1.2 3K 28 7K 0 general/3
20904 root 45 3.8 0.0 0.0 0.0 50 0.0 1.2 3K 32 7K 0 general/7
20904 root 45 3.8 0.0 0.0 0.0 51 0.0 1.2 3K 18 7K 0 general/2
20904 root 44 3.8 0.0 0.0 0.0 51 0.0 1.2 3K 12 6K 0 general/8
20904 root 44 3.7 0.0 0.0 0.0 51 0.0 1.2 3K 11 7K 0 general/4
20904 root 44 3.8 0.0 0.0 0.0 51 0.0 1.2 3K 12 7K 0 general/9
20903 root 0.1 0.2 0.0 0.0 0.0 0.0 100 0.0 52 0 365 0 prstat/1
prstat コマンドを実行しても "LCK" が出ていない場合はプロセスのロックの競合は問題ない可能性があります。他に問題が無いか検討してみてください。例えばカーネル内のロックが問題である場合は lockstat コマンドを試してみて下さい。また、"LCK" が出ていてもロックが最優先の課題では無い場合もあります。例えば vmstat コマンドで CPU の id が 0 の場合はたとえロックの競合を解消できたとしてもこれ以上は性能が上がらないかもしれません。その場合は CPU を追加する等の処置が必要です。どんな症状の時にロックが問題であるかの判別手順は、別の機会に改めてご紹介したいと思います。
一般的な使い方
plockstat コマンドの基本的な使い方は "plockstat -Cve 5 -x bufsize=10k -x aggsize=2m -p <PID>" です。-C オプションはロックの競合の発生を調べる為の基本オプションです。-v オプションは verbose オプションで、トレースの開始を出力する為に付けています。-e <SEC> で plockstat コマンドを実行する時間を指定します。"-e 5" と指定すると 5 秒間計測します。計測が終わると plockstat コマンドは終了しますが、測定対象のプロセスはそのまま稼働を続けます。-e オプションを付け無い場合は、プログラムが終了するまでトレースを続けます。-x bufsize=<SIZE> -x aggsize=<SIZE> でコマンドの内部バッファを増やしています。このオプションが無くても問題の無いことが多いですが、取得する統計情報の量が大き過ぎて溢れてしまうことを予防する為に付けています。-p <PID> で解析対象のプロセスを指定します。<PID> には解析したいプロセスのプロセス ID を指定します。
# plockstat -Cve 5 -x bufsize=10k -x aggsize=2m -p <PID> ... -C は競合を調査 ... -v は冗長出力 ... -e <SEC> は plockstat コマンドの実行時間 ... -x bufsize=<SIZE> -x aggsize=<SIZE> は内部バッファの拡大 ... -p <PID> は調査対象のプロセスを指定
ロック発生時のスタックフレームを記録する
plockstat コマンドではロックが発生した際のスタックフレームを記録する事も出来ます。ロックに至るまでの関数コールの履歴を見ることで、ロックの発生原因を詳細に特定することが可能になります。スタックフレームの保存には -s <DEPTH> オプションを付けます。
plockstat -Cvs 5 -p <PID> ... -s <DEPTH> で保存するスタックの深さを指定
出力行数を制限したい場合は
出力行数が多すぎてログが見にくい場合は -n オプションを付けてください。
# plockstat -Cve 5 -n 10 -p <PID> ... -n オプションで出力する行数を制限
プログラム実行時に plockstat コマンドを使用する
plockstat コマンドの引数にプログラムを指定する事も出来ます。実行時間が短いプログラムや、プログラム開始時のロックを観測したい場合に便利です。<COMMAND> には調査したいコマンドを指定します。
# plockstat -Cv -x bufsize=10k -x aggsize=2m <COMMAND> ... コマンドの最後にプログラム名を指定すると、そのプログラムを実行
ロックの取得を観測する
ロックの競合ではなくロックの取得を監視したい場合は -H オプションを付けます。ロックの取得は競合に比べて発生頻度が高いため、plockstat コマンドの実行負荷が高くなる事があり、それがプログラムの実行に影響を与えてしまう事があります。注意して使用してください。
# plockstat -Hve 5 -p <PID> ... -H オプションでロックの『取得』を観測
全ての情報を一度に取得したい場合は…
ロックの競合と取得の両方を監視したい場合は -A オプションを付けます。-A オプションは -H オプション以上に実行負荷が高いので注意して使用してください。
# plockstat -Ave 5 -p <PID> ... -A オプションでロックの『取得』と『競合』の両方を観測
plockstat コマンドの使用例 その1
実際に plockstat コマンドを使用する例をテスト用のプログラムを使ってご覧頂きます。
mutex ロックのテストプログラム
以下のテストプログラムでは main() 関数を実行しているスレッドが mutex ロックを保持した状態で 10 秒間休眠し、それ以外のスレッドはその間ブロックされます。これが競合が発生している状態です。ロックの競合は main() のスレッドが停止している間 10 秒ほど続きます。main() のスレッドが mutex ロックを解放すると、ロックの競合は解消され、その他のスレッドがロックを取得します。各スレッドは "done" というメッセージを出力してプログラムは終了します。mutex を保持しながら sleep() したり、エラー処理を省いたりしておりますが、plockstat コマンドのテスト用に分かり易さを優先しました。ご了承下さい。
/*
* mutex_test.c : a test program for plockstat.
* compile : # cc mutex_test.c -o mutex_test
*/
#include <stdio.h>
#include <unistd.h>
#include <pthread.h>
void *func();
pthread_mutex_t mp;
int main() {
pthread_t tid1, tid2, tid3;
pthread_mutex_init(&mp, NULL);
pthread_mutex_lock(&mp);
pthread_create(&tid1, NULL, func, NULL);
pthread_create(&tid2, NULL, func, NULL);
pthread_create(&tid3, NULL, func, NULL);
sleep(10); /* you should not do this. */
pthread_mutex_unlock(&mp);
pthread_join(tid1, NULL);
pthread_join(tid2, NULL);
pthread_join(tid3, NULL);
pthread_mutex_destroy(&mp);
exit(0);
}
void *func() {
pthread_mutex_lock(&mp);
puts("done");
pthread_mutex_unlock(&mp);
pthread_exit(0);
}
コンパイル
上記のテストプログラムを mutex_test.c というファイル名で保存し、以下の様にコンパイルして下さい。
# gcc mutex_test.c -o mutex_test
plockstat コマンドの実行
次の様に plockstat コマンドにテストプログラムを渡してください。
# plockstat -Cv ./mutex_test
実行結果とその見方
plockstat コマンドの実行結果は以下の様になります。一番最後の行が一番重要な行です。左から、ロックの競合が発生した回数 (Count)、競合が発生した時間の平均 (nsec)、競合したロックの名前またはアドレス (Lock)、ロックの競合が発生した関数 (Caller) を示しています。下記の例では mutex_test の実行中にロックの競合は 3 回発生しています。競合が発生してから解消されるまでの時間は平均 10 秒 (10000255945 nsec) で、競合が発生したロックは mutex_test プログラムの "mp" という変数、競合を発生させた関数は mutex_test プログラムの func() です。最後の +0x13 は func() 関数のエントリポイントから mutex_lock() までのオフセットです。以上、プログラムに記述した通りの出力が出ている事が分かります。
# plockstat -Cv ./mutex_test
plockstat: tracing enabled for pid 19830 <-- 冗長出力オプションによる出力
done <-- mutex_test プログラムによる出力
done <-- mutex_test プログラムによる出力
done <-- mutex_test プログラムによる出力
plockstat: pid 19830 has exited
Mutex block
Count nsec Lock Caller
-------------------------------------------------------------------------------
3 10000255945 mutex_test`mp mutex_test`func+0x13
plockstat コマンドの使用例 その2
次にプログラムの並列度に関する古典的な問題のひとつである、メモリ割り当ての並列実行について見てみたいと思います。これはヒープコンテンションとも呼ばれている問題で、Solaris では後述の mtmalloc ライブラリによって既に解決されています。
テストプログラム
メモリ割り当てのテストに使用するプログラムは OpenSolaris の配布物から流用します。general.c はマルチスレッドプログラムで並列に malloc() を呼び出すマイクロベンチマークです。まずは以下の様にコンパイルしてください。
# mkdir /var/tmp/malloc # cd /var/tmp/malloc # wget http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libmtmalloc/tests/general.c # gcc general.c -o general
prstat コマンドで調査する
まずは general プログラムの挙動を調べる為に prstat コマンドを使用します。prstat コマンドの -p オプションにプロセス ID を渡すと、そのプロセスだけの統計情報を見る事が出来ます。ここでは general プログラムのプロセス ID を渡しています。general プログラムは 8 つのスレッドを新たに作成し、それぞれのスレッドが 50% 前後の時間をロック待ちに費やしている事が分かります。
# ./general&; prstat -mLp $! 1
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
9838 root 48 4.1 0.0 0.0 0.0 47 0.0 1.1 3K 13 7K 0 general/9
9838 root 46 3.9 0.0 0.0 0.0 49 0.0 1.1 3K 3 7K 0 general/7
9838 root 45 3.9 0.0 0.0 0.0 50 0.0 1.2 3K 17 7K 0 general/2
9838 root 45 3.9 0.0 0.0 0.0 50 0.0 1.2 3K 9 7K 0 general/8
9838 root 45 3.9 0.0 0.0 0.0 50 0.0 1.2 3K 8 7K 0 general/6
9838 root 45 3.8 0.0 0.0 0.0 50 0.0 1.1 3K 6 7K 0 general/4
9838 root 43 3.7 0.0 0.0 0.0 52 0.0 1.2 3K 6 7K 0 general/5
9838 root 42 3.7 0.0 0.0 0.0 54 0.0 1.2 3K 9 6K 0 general/3
9838 root 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 general/1
なお、このプログラムを実行したマシンの CPU 数は 8 つで、general プログラム実行中も CPU リソースに空き (CPU の空き = vmstat コマンドの id) がある状態です。
# psrinfo 0 on-line since 09/03/2009 17:11:43 1 on-line since 09/03/2009 17:11:54 2 on-line since 09/03/2009 17:11:54 3 on-line since 09/03/2009 17:11:56 4 on-line since 09/08/2009 11:20:06 5 on-line since 09/08/2009 11:20:06 6 on-line since 09/08/2009 11:20:06 7 on-line since 09/08/2009 11:20:06 # vmstat 1 kthr memory page disk faults cpu r b w swap free re mf pi po fr de sr s0 s1 s2 s3 in sy cs us sy id 0 0 0 32014452 31721476 7 53 0 1 1 0 1 -0 0 -0 -0 468 568 577 0 0 100 0 0 0 31950536 31614640 20 6030 0 0 0 0 0 0 0 0 0 671 56769 51060 45 5 50 0 0 0 31926584 31590736 0 5955 0 0 0 0 0 0 0 0 0 561 56962 51203 45 5 50 0 0 0 31902764 31566916 0 5977 0 0 0 0 0 0 0 0 0 550 57824 52201 45 5 50 0 0 0 31878908 31543060 0 5943 0 0 0 0 0 0 0 0 0 606 57476 51873 45 5 50
plockstat コマンドで調査する
次に、prstat コマンドで見られたロック待ちの原因を plockstat コマンドで調べてみます。plockstat コマンドの出力から Lock のカラムを見てみると libc.so.1 の libc_malloc_lock で競合が発生している事が分かります。中段に "Mutex block" と書かれている様に、これは mutex ロックの競合です。また、 nsec と Count のカラムを見ると、平均 0.001 秒 (1033533 nsec) のロック待ちが約 6 千回発生していることが分かります。これはプロセス全体で 60 秒 (57903 count * 1033533 nsec = 59844661299 nsec => 60 sec) ほど待たされている計算になります。plockstat コマンドで測定していたのは 10 秒間ですが、スレッドが 9 つありますので、このプロセスの論理的な演算可能時間は 90 秒間です（CPU 数や他のプログラムの処理のことを考えると実質的な演算可能時間はもう少し少なくなります）。この演算可能な 90 秒のうち 60 秒は mutex のロックで待たされていると言うことになります。このプログラムはかなりの時間をロック待ちに費やしていると言って良いでしょう。
# plockstat -Cve 10 ./general
plockstat: tracing enabled for pid 9849
0
Mutex block
Count nsec Lock Caller
-------------------------------------------------------------------------------
57903 1033533 libc.so.1`libc_malloc_lock general`be_thread+0x70
スタックフレームを観察する
ロックの原因をもう少し特定するため、plockstat コマンドに -s オプションも付けてスタックフレームを見てみます。右下の "Stack" のカラムを見ると、general の be_thread() 関数のオフセット 0x70 から libc.so.1 の malloc() 関数が呼び出されており、malloc() から mutex_lock() が呼び出されている事が分かります。このロック待ちは malloc() 関数が原因であることが分かります。これがヒープコンテンションが発生している状態です。
# plockstat -Cve 10 -s 5 ./general
plockstat: tracing enabled for pid 9862
0
Mutex block
-------------------------------------------------------------------------------
Count nsec Lock Caller
60065 1434766 libc.so.1`libc_malloc_lock general`be_thread+0x70
nsec ---- Time Distribution --- count Stack
2048 | | 836 libc.so.1`mutex_lock_impl+0x102
4096 |@@@ | 9909 libc.so.1`mutex_lock+0x1a
8192 | | 2316 libc.so.1`malloc+0x29 <-- これ
16384 |@@ | 7215 general`be_thread+0x70
32768 |@@@@@@ | 16034
65536 | | 1837
131072 | | 1223
262144 |@ | 2702
524288 |@ | 4505
1048576 |@ | 3721
2097152 | | 2269
4194304 | | 2193
8388608 |@ | 3411
16777216 | | 1671
33554432 | | 219
67108864 | | 4
mtmalloc ライブラリ
このヒープコンテンションへの対策として、Solaris にはマルチスレッドプログラム用の mtmalloc ライブラリが用意されており、既に様々なアプリケーションで使用されています。mtmalloc の使用方法は、コンパイル時にライブラリをリンクするか、プログラム実行時に LD_PRELOAD で読み込みます。これにより malloc() 関数がマルチスレッドに最適化された malloc() に置き換わります。
mtmalloc を使用して計測
先ほどの general プログラムで mtmalloc を使用してみた所、mutex でブロックされる回数が大幅に減少しました。ロック待ちをしていた時間は、34 count * 1401746 nsec + 1 count * 15222 nsec = 47674586 => 0.047 秒です。また、Caller のカラムを見ると、先ほどあった libc の malloc() のロックが消えている事が分かります。
# LD_PRELOAD_32=/usr/lib/libmtmalloc.so.1 plockstat -Cv ./general
plockstat: tracing enabled for pid 20828
plockstat: pid 20828 has exited
Mutex block
Count nsec Lock Caller
-------------------------------------------------------------------------------
34 1401746 libc.so.1`__sbrk_lock libmtmalloc.so.1`morecore+0x81
1 15222 0xfefa2138 libmtmalloc.so.1`setup_caches+0x21
mtmalloc で処理性能が大幅にアップ
mtmalloc を使ったテストでは、元の libc の malloc() をした場合と比べるとプログラムの実行時間も大幅に減少しています。ptime コマンドで計測した所、だいたい 1/10 程度の時間で処理が終了している事が分かります。plockstat コマンドで入手した情報を元にロックの競合を解消することでアプリケーションの高速化を行う事が出来ました。
# ptime ./general real 27.474 <-- libc の malloc() を使用した場合の処理時間 user 1:19.758 sys 4.740 # LD_PRELOAD_32=/usr/lib/libmtmalloc.so.1 ptime ./general real 3.195 <-- mtmalloc を使用した場合の処理時間 user 24.022 sys 1.019
おわりに
以上、plockstat コマンドを使用してロックの競合を解析する手順をご紹介しました。plockstat コマンドに prstat コマンドや vmstat コマンドを組み合わせて使うことで、ロックの競合の原因やそのロックの競合がプログラム全体の処理性能にどれだけ影響を与えているかを調べることが出来ます。また、テストプログラムや malloc() の実験を通して、plockstat コマンドの実際の使い方と競合が発生していた場合の対処方法の一例をご覧頂きました。メニーコア時代への対策として、今回ご紹介した手順を是非ご活用下さい。
なお、今回ご紹介した plockstat コマンドは DTrace の仕組みがあれば実装可能です。実際、Mac OS X にも plockstat コマンドがバンドルされています。FreeBSD でも使えるかもしれません。plockstat コマンドはとても便利なツールですし、こうしてプログラムが動いている舞台裏を覗いてみるのはコーディングやサーバ運用の役に立ちます。Solaris 以外の環境でも是非お試し下さい。 次回の記事 では更に進んで、plockstat コマンドの実装と DTrace を使ってロックを解析する方法に付いて書いてみたいと思います。
参考文献
mtmalloc ライブラリのソースコード
malloc() の並列実行ベンチマーク
Posted at 11:15午前 9 17, 2009 by Daisuke Homma in Sun | 投稿されたコメント[0]
Subscribe!