2009年 9月 28日 月曜日
やっぱり Sun がスキ！
2009年 9月 28日 月曜日
OpenSolaris 2009.06 で Zone を作成する
今回は、OpenSolaris 2009.06 で Solarisコンテナを作成する手順を纏めてみましたので 紹介します。
今まで、「やっぱり Sun がスキ！」ブログでは、Solaris 10 ベースの Solarisコンテナに 関する TIPS をいろいろ紹介して来ましたが、OpenSolaris 2009.06 では Solaris 10 と 少し変わっていますので、Solaris 10 との違いを中心に説明していきます。
ステップ１ zonepath 用のディレクトリを作成する
Zone 作成時に一番重要なプロパティは zonepath ですが、Solaris 10 の ように適当なディレクトリを mkdir で作成して zonepath に設定してはいけません。OpenSolaris 2009.06 では、zonepath に ZFS のデータセット名を指定する 必要があります。例えば、zonepath に /rpool/zones/test-zone と指定したい 場合は、あらかじめ下記の設定が必要になります。
# zfs create rpool/zones # zfs create rpool/zones/test-zone # chmod 700 /rpool/zones/test-zone
ステップ２ Zone の作成を行う
次に zonecfg で Zone名 test-zone の作成を行います。# zonecfg -z test-zone test-zone: No such zone configured Use 'create' to begin configuring a new zone. zonecfg:test-zone> create zonecfg:test-zone> set zonepath=/rpool/zones/test-zone
ここで設定値を確認してみます。
zonecfg:test-zone> info zonename: test-zone zonepath: /rpool/zones/test-zone brand: ipkg autoboot: false bootargs: pool: limitpriv: scheduling-class: ip-type: shared hostid:
info の出力結果で注目する箇所は、Solaris 10 と違いブランド名が native でなく ipkg 形式に なっている事です。従いまして、inherit-pkg-dir のプロパティも無くなっています。
zonecfg の設定を保存した後、zone の状態を確認してみます。
# zoneadm list -cv ID NAME STATUS PATH BRAND IP 0 global running / native shared - test-zone configured /rpool/zones/test-zone ipkg sharedtest-zone のブランドが native でなく ipkg になっています。
ステップ３ Zone のインストールを行う
Zone の作成が完了しましたので、インストールを行います。
# zoneadm -z test-zone install
Publisher: Using opensolaris.org (http://pkg.opensolaris.org/release/).
Image: Preparing at /rpool/zones/test-zone/root.
Sanity Check: Looking for 'entire' incorporation.
Installing: Core System (output follows)
DOWNLOAD PKGS FILES XFER (MB)
Completed 20/20 3021/3021 42.55/42.55
PHASE ACTIONS
Install Phase 5747/5747
Installing: Additional Packages (output follows)
DOWNLOAD PKGS FILES XFER (MB)
Completed 37/37 5598/5598 32.52/32.52
PHASE ACTIONS
Install Phase 7329/7329
Note: Man pages can be obtained by installing SUNWman
Postinstall: Copying SMF seed repository ... done.
Postinstall: Applying workarounds.
Done: Installation completed in 1075.241 seconds.
Next Steps: Boot the zone, then log into the zone console
(zlogin -C) to complete the configuration process
Zone のインストールを実行すると、パッケージのリポジトリからパッケージのダウンロードが開始されます。そして、ログにはインストールにかかった時間が表示されるようになりました。
インストールが完了すれば、後は Solaris 10 と同様に Zone をブートして使用可能になります。
# zoneadm -z test-zone boot # zlogin -C test-zone
おまけ Zone のクローンを作成する
せっかく zonepath が ZFS ベースなので、Solarisコンテナのクローン機能が ZFS のクローンと 連携出来ているか確認してみました。# zoneadm -z test-zone halt # zonecfg -z test-zone export -f /var/tmp/clone-zone.cfgexport したファイル内の zonepath を /rpool/zones/test-zone から /rpool/zones/clone-zone に 変更します。
# zonecfg -z clone-zone -f /var/tmp/clone-zone.cfg # zoneadm -z clone-zone clone test-zone sys-unconfig started 2009年09月27日 01時29分53秒 rm: cannot remove `/rpool/zones/clone-zone/root/etc/vfstab.sys-u': No such file or directory grep: /rpool/zones/clone-zone/root/etc/dumpadm.conf: No such file or directory sys-unconfig completed Sun Sep 27 01:29:53 2009Zone のクローン作成は、即時に作成できましたので ZFS のクローンときちんと連携できているようです。
ZFS の状態を確認してみます。
# zfs list -t snapshot NAME USED AVAIL REFER MOUNTPOINT rpool/ROOT/opensolaris@install 146M - 2.82G - rpool/zones/test-zone/ROOT/zbe@clone-zone_snap 0 - 341M - # zfs get origin | grep clone rpool/zones/clone-zone origin - - rpool/zones/clone-zone/ROOT origin - - rpool/zones/clone-zone/ROOT/zbe origin rpool/zones/test-zone/ROOT/zbe@clone-zone_snap - rpool/zones/test-zone/ROOT/zbe@clone-zone_snap origin -
Zone と ZFS の連携って素敵です！
Posted at 09:51午後 9 28, 2009 by Naoyuki Yamada in Sun | 投稿されたコメント[0]
2009年 9月 18日 金曜日
DTrace を使ってロックの競合を調査する
はじめに
今回は DTrace を使用してロックの競合を調査する初歩的な手順をご紹介したいと思います。DTrace には豊富なプローブが用意されていますので、アイデアさえあれば無限にスクリプトを作成することが可能です。その全てを解説することは難しいですが、DTrace を使ってマルチスレッドプログラムの動きを調べる際の基礎となるスクリプトを幾つかご紹介したいと思います。
plockstat コマンドの実装から
先日ご紹介した plockstat コマンド はその機能の殆どを DTrace を利用して実装しています。OpenSolaris.org にある plockstat コマンドの ソースコード を見てみると、1000 行ほどのコードの内の 300 行ほどが DTrace スクリプトの定義で、残りはヘルパー関数になっています。実は、この plockstat コマンドに含まれている DTrace スクリプトは plockstat コマンドと独立して使用することも可能です。まず始めに、その使い方から見ていきましょう。
mutex ロックの競合を調査する DTrace スクリプト
plockstat コマンドのソースコードから mutex ロックの競合を検知している部分を抜き出して、単独で実行できる様に修正したのが下記のスクリプトです。plockstat$target::: で始まるプローブが並んでいますが、plockstat コマンドに含まれるスクリプトは DTrace の plockstat プロバイダの機能を利用しています。plockstat プロバイダは mutex ロックと reader/writer ロックを監視する為の DTrace のプロバイダです。plockstat コマンドは plockstat プロバイダの機能を全面的に使用しているため、plockstat コマンドは plockstat プロバイダのラッパーと言って良いかもしれません。続いて個々のプローブを見ていきましょう。plockstat$target:::mutex-block はスレッドが mutex ロックでブロックされる直前に呼び出されるプローブです。一方 plockstat$target:::mutex-blocked はブロックから解放された直後に呼び出されますので、mutex-block と mutex-blocked で timestamp の差分を取ると mutex ロックでブロックされていた時間を割り出す事が出来ます。なお、plockstat$target:::mutex-blocked の arg1 が 0 の場合は何らかのエラーで mutex ロックが取得できなかったことを意味するため、ブロックされていた時間には加算されていません。
#!/usr/sbin/dtrace -s
plockstat$target:::mutex-block
{
self->mtxblock[arg0] = timestamp;
}
plockstat$target:::mutex-blocked
/self->mtxblock[arg0] && arg1 != 0/ /* arg1 is not 0 => lock is acquired */
{
@mtx_block[arg0, ustack(5)] =
sum(timestamp - self->mtxblock[arg0]);
@mtx_block_count[arg0, ustack(5)] = count();
self->mtxblock[arg0] = 0;
mtx_block_found = 1;
}
plockstat$target:::mutex-blocked
/self->mtxblock[arg0]/ /* arg1 is 0 => error */
{
self->mtxblock[arg0] = 0;
}
END
/mtx_block_found/
{
trace("Mutex block");
printa(@mtx_block, @mtx_block_count);
}
実際に動かしてみる
このスクリプトを先日の plockstat の記事 で使用したテストプログラムに対して実行してみた結果が以下の出力です。上から、"134614312" が plockstat コマンドの "Lock" のカラムに相当する mutex ロックのアドレス、次のスタックフレームが "Caller" のカラムを作成する為のデータです。"30002403544" は mutex ロックでブロックされていた総時間です。最後の "3" は plockstat コマンドの "Count" のカラムに相当するブロックされた回数です。先ほどの総時間をブロックされた回数で割ると、ブロックされた平均時間となり plockstat コマンドの "nsec" のカラムが求まります (30002403544 nsec / 3 Count = 10000801181 nsec)。きちんと plockstat コマンドに相当する情報が得られている事が分かります。
# ./plockstat_mb.d -c ./mutex_test <-- トレース対象のプログラムは -c オプションで指定します
dtrace: script './plockstat_mb.d' matched 7 probes
done
done
done
dtrace: pid 9964 has exited
CPU ID FUNCTION:NAME
1 2 :END Mutex block
134614312 <-- "Lock"
libc.so.1`mutex_lock_queue+0x24a
libc.so.1`mutex_lock_impl+0x102
libc.so.1`mutex_lock+0x1a
mutex_test`func+0x13 <-- "Caller"
libc.so.1`_thr_setup+0x4e
30002403544 3 <-- "Count"
~~~~~~~~~~~ total time blocked
スレッドの毎に統計情報をまとめるスクリプト
先ほどのスクリプトを少しだけ書き換えて、ブロックされていた時間をスレッド毎に集計するスクリプトを作ってみました。下記のスクリプトを実行すると、プロセスを 10 秒間監視し、ブロックが発生した回数とブロックされていた時間をスレッド単位で出力します。先ほどのスクリプトからの変更点は、@mtx_block, @mtx_block_count 集積体のキーに tid を使用して、スレッド ID 毎に情報を集計しています。また、ブロックされた時間を保持していた self->mtxblock はスレッド毎に一つの値だけを保持すれば良いので、単純なスレッド固有変数にしてあります。tick-1sec は DTrace の profile プロバイダのプローブで、1 秒毎に呼び出されます。ここでは 10 秒間を数えるのに使用しています。
#!/usr/sbin/dtrace -qs
int ntick;
BEGIN
{
ntick = 0;
}
plockstat$target:::mutex-block
{
self->mtxblock = timestamp;
}
plockstat$target:::mutex-blocked
/self->mtxblock && arg1 != 0/ /* arg1 is not 0 => lock is acquired */
{
@mtx_block[tid]= sum(timestamp - self->mtxblock);
@mtx_block_count[tid] = count();
self->mtxblock = 0;
}
plockstat$target:::mutex-blocked
/self->mtxblock/ /* arg1 is 0 => error */
{
self->mtxblock = 0;
}
tick-1sec
{
ntick += 1;
}
tick-1sec
/ntick == 10/
{
trace("Count");
printa(@mtx_block_count);
trace("nsec");
printa(@mtx_block);
exit(0);
}
DTrace スクリプトの実行結果
書き換えたスクリプトを plockstat コマンドの解説で使用した general.c で試してみます。Count 以下がブロックされた回数を表しており、nsec 以下がブロックされた時間を表しています。いずれも測定時間 10 秒辺りの結果です。Count の結果は、左側のカラムがスレッド ID、右側のカラムがブロックされた回数です。スレッド ID が 8 番のスレッドは 10 秒の間に 15197 回ブロックされていた事が分かります。nsec の結果も左のカラムはスレッド ID です。右側のカラムはナノ秒単位でブロックされていた総時間が出力されます。ここではスレッド ID 5 番のスレッドが 10 秒間のうち 5.8 秒間ブロックされていたことが見て取れます。
# ./plockstat_mbt.d -c ./general
Count
8 15197
2 15395
3 15397
7 15418
6 15480
4 15604
9 15633
5 16011
nsec
5 5849251426
6 5891593031
9 5904264724
4 5912264400
3 5953877535
2 5983468423
7 6004800234
8 6067032588
plockstat プロバイダでトレースできないケースへの対応
plockstat プロバイダはその名の通り mutex ロックと reader/writer ロックを監視対象としており、条件変数でブロックされている場合は監視する事が出来ません。マルチスレッドプログラムでは条件変数も良く利用されていますので、mutex ロックや reader/writer ロックと同様に監視できると便利です。
条件変数のテストプログラム
以下のテストプログラムでは、各スレッドは main() 関数の中で res がインクリメントされるまで条件変数でブロックされます。
/*
* cv_test.c : a test program for cv tracing.
* compile : cc cv_test.c -o cv_test
*/
#include <stdio.h>
#include <unistd.h>
#include <atomic.h>
#include <pthread.h>
void *func();
volatile uint_t res = 0;
pthread_mutex_t mp;
pthread_cond_t cv;
int main() {
pthread_t tid1, tid2;
pthread_mutex_init(&mp, NULL);
pthread_cond_init(&cv, NULL);
pthread_create(&tid1, NULL, func, NULL);
pthread_create(&tid2, NULL, func, NULL);
sleep(10);
atomic_inc_uint(&res);
pthread_mutex_lock(&mp);
pthread_cond_broadcast(&cv);
pthread_mutex_unlock(&mp);
pthread_join(tid1, NULL);
pthread_join(tid2, NULL);
pthread_mutex_destroy(&mp);
pthread_cond_destroy(&cv);
exit(0);
}
void *func() {
pthread_mutex_lock(&mp);
while(res == 0) {
pthread_cond_wait(&cv, &mp);
}
puts("done");
pthread_mutex_unlock(&mp);
pthread_exit(0);
}
コンパイル
上記のテストプログラムを cv_test.c という名前で保存し、以下の様にコンパイルして下さい。
# gcc cv_test.c -o cv_test
prstat で調査する
prstat で見てみると LWPID 1 のスレッドがスリープ ("SLP") し、LWPID 2 と 3 のスレッドがロック待ち ("LCK") しているのが分かります。
# ./cv_test&; prstat -mL -p $!
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
10189 root 0.0 0.0 0.0 0.0 0.0 100 0.0 0.0 0 0 0 0 cv_test/3
10189 root 0.0 0.0 0.0 0.0 0.0 100 0.0 0.0 0 0 0 0 cv_test/2
10189 root 0.0 0.0 0.0 0.0 0.0 0.0 100 0.0 0 0 0 0 cv_test/1
plockstat で調査する
cv_test プログラムを plockstat コマンドと共に実行した結果が以下です。prstat コマンドではロック待ちをしていることが明らかに見て取れましたが、plockstat コマンドではロックの競合についての情報は一切出力されていません。
# plockstat -Cv ./cv_test plockstat: tracing enabled for pid 19839 done done plockstat: pid 19839 has exited
条件変数を調査する DTrace スクリプト
plockstat コマンドの代わりに以下の様な DTrace スクリプトを作成すれば条件変数を捕捉することが可能です。DTrace の pid プロバイダを使用して pthread_cond_wait() 関数の出入りを監視しています。同様に pthread_cond_timedwait() や pthread_cond_reltimedwait_np() についてスクリプトを作成すれば、汎用的に条件変数を監視することが可能です。
#!/usr/sbin/dtrace -s
pid$target::pthread_cond_wait:entry
{
self->start = timestamp;
self->addr = arg0;
}
pid$target::pthread_cond_wait:return
/self->start/
{
@time[tid,self->addr] = sum(timestamp - self->start);
@cnt[tid,self->addr] = count();
self->start = 0;
}
END
{
printf("¥n");
printf("¥n");
printf("tid¥tcv address¥ttime(nsec)¥n");
printa("%d¥t%p¥t¥t%@u¥n", @time);
printf("¥n");
printf("tid¥tcv address¥tcount¥n");
printa("%d¥t%p¥t¥t%@u¥n", @cnt);
}
DTrace スクリプトの実行結果
上記スクリプトを cv.d という名前で保存し、実行権限を付けて、以下の様に実行して下さい。結果を見ると、tid 2 のスレッドの time(nsec) が 10000060220 (=> 10 sec)、tid 3 のスレッドの time(nsec) が 10000693754 (=> 10 sec) なので、各スレッドがそれぞれ 10 秒程ずつ待たされている事が分かります。また、tid 2, tid 3 のスレッドの count が 1 なので、両スレッドとも 1 回ずつ pthread_cond_wait() で待たされていたことになります。
# chmod +x ./cv.d # ./cv.d -c ./cv_test <-- トレース対象のプログラムは -c オプションで指定します dtrace: script './cv.d' matched 3 probes done done dtrace: pid 19939 has exited CPU ID FUNCTION:NAME 6 2 :END tid cv address time(nsec) <-- pthread_cond_wait() で待った時間を条件変数とスレッド毎に集計 2 8060fb8 10000060220 3 8060fb8 10000693754 tid cv address count <-- pthread_cond_wait() で待った回数を条件変数とスレッド毎に集計 2 8060fb8 1 3 8060fb8 1
おわりに
以上、DTrace を使用してロックの競合を監視する基本的な方法をご紹介しました。ご覧頂きました通り、plockstat コマンドは DTrace の plockstat プロバイダを全面的に使用して実装されています。また、plockstat コマンドに含まれる DTrace スクリプトは DTrace のスクリプトとして単独でも使用可能であることも見て頂きました。更に、plockstat プロバイダでは捕捉できない条件変数のブロックを DTrace の pid プロバイダを使用したスクリプトで監視する方法もご紹介しました。DTrace にはここで紹介した以外にも proc プロバイダの lwp-create, lwp-start, lwp-exit と言ったプローブや、mutex_owned(), rw_write_held() 等のサブルーチンが備わっており、マルチスレッドプログラムの解析には非常に有用なツールです。是非ご活用下さい。
関連文書
マニュアル
plockstat プロバイダのマニュアル
- http://docs.sun.com/app/docs/doc/819-0395/chp-plockstat
- http://docs.sun.com/app/docs/doc/817-6223/chp-plockstat
『マルチスレッドのプログラミング』
ソースコード
plockstat コマンドのソースコード
- http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/cmd/plockstat/plockstat.c
- 61-351 行目が DTrace のスクリプトになっています
plockstat プロバイダのソースコード
- http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/threads/plockstat.d
- http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/lib/libc/port/threads/synch.c
- "DTRACE_PROBE1(plockstat, mutex__block, mp)" と "DTRACE_PROBE2(plockstat, mutex__blocked, mp, X)" が mutex ロックの競合をトレースしている箇所です
DTrace の解説
Posted at 11:45午前 9 18, 2009 by Daisuke Homma in Sun | 投稿されたコメント[0]
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!