lockstat - カーネルロックおよびプロファイル統計情報の報告
lockstat [-ACEHI] [-e event_list] [-i rate]
[-b | -t | -h | -s depth] [-n nrecords]
[-l lock [, size]] [-d duration]
[-f function [, size]] [-T] [-ckgwWRpP] [-D count]
[-o filename] [-x opt [=val]] command [args]
lockstat ユーティリティーは、カーネルのロックとプロファイルの統計情報を収集して表示します。lockstat では、監視するイベント (たとえば、適応型相互排他ロックでのスピン、書き込み待機による読み取り書き込みロックへの読み取りアクセスのブロックなど)、イベントごとに収集するデータ量、およびデータの表示方法を指定できます。デフォルトでは、lockstat はすべてのロック競合イベントをモニターし、それらのイベント関する頻度とタイミングのデータを収集して、もっとも一般的なイベントが最初に表示されるように頻度の高い順にデータを表示します。
lockstat は、指定されたコマンドが完了するまでデータを収集します。たとえば、決まった時間間隔の統計情報を収集するには、次のようにコマンドとして sleep(1) を使用します。
example# lockstat sleep 5
–I オプションを指定すると、lockstat はプロセッサ単位で高レベルの定期割り込みソースを設定し、プロファイルデータを収集します。この割り込みハンドラは、呼び出し元が割り込まれた PC (プログラムカウンタ) である lockstat イベントを生成するだけです。プロファイルイベントはほかの lockstat イベントとほぼ同じなので、lockstat の通常のオプションがすべて適用可能です。
lockstat は、DTrace を利用して実行中のカーネルのテキストを変更し、対象となるイベントを傍受します。これにより、すべてのシステムアクティビティーに対してわずかながら測れるほどのパフォーマンスオーバーヘッドが発生するため、lockstat へのアクセスはデフォルトでスーパーユーザーに限定されています。システム管理者は、ほかのユーザーに追加の DTrace 特権を付与することで、lockstat の使用を許可できます。DTrace のセキュリティー機能の詳細は、Oracle Solaris 11.4 DTrace (Dynamic Tracing) Guideを参照してください。
サポートしているオプションは、次のとおりです。
イベント選択オプションが指定されていない場合、デフォルトは –C です。
すべてのロックイベントを監視します。–A は –CH と同等です。
競合イベントを監視します。
エラーイベントを監視します。
指定されたイベントのみを監視します。event list は、コンマで区切られたイベントまたはイベントの範囲のリストです (例: 1,4-7,35)。引数なしで lockstat を実行すると、すべてのイベントの簡単な説明が表示されます。
保持イベントを監視します。
プロファイル割り込みイベントを監視します。
–I の割り込みレート (秒単位)。プロファイルが (100 Hz で実行される) クロック割り込みと完全に連動して実行されないように、デフォルトは 97 Hz です。
DTrace の実行時オプションまたは D コンパイラオプションを有効化または変更します。オプションのリストについては、dtrace(8) を参照してください。ブール型のオプションを有効にするときは、その名前を指定します。値を持つオプションを設定するには、オプションの名前と値を等号 (=) で分離します。
基本的な統計情報: ロック、呼び出し元、イベント数。
ヒストグラム: タイミングおよび時間分布ヒストグラム。
スタックトレース: ヒストグラムおよびスタックトレース (最大 depth フレームまで)。
タイミング: すべてのイベントの基本データおよびタイミング (デフォルト)。
duration より長いイベントのみを監視します。
シンボリック名または 16 進アドレスとして指定できる func によって生成されたイベントのみを監視します。size のデフォルトは、ELF シンボルが利用可能な場合はそのサイズ、利用可能でない場合は 1 です。
シンボリック名または 16 進アドレスとして指定できる lock のみを監視します。size のデフォルトは、ELF シンボルが利用可能な場合はそのサイズ、利用可能でない場合は 1 です。
データレコードの最大数。
イベントを (サンプリングではなく) トレースします (デフォルトではオフ)。
ロック配列 (たとえば、pse_mutex[]) のロックデータを 1 つにまとめます。
各タイプの上位 count 個のイベントのみを表示します。
関数によって生成されたイベントの総数を表示します。たとえば、foo() がループ内で bar() を呼び出す場合、bar() によって実行された処理は (foo() 自体によって実行された処理とともに) foo() によって生成された処理としてカウントされます。–g オプションを使用すると、各関数が現れるスタックフレームの総数がカウントされます。これは、2 つのことを意味します: (1) スタックトレースの深さが十分でない場合、–g によって報告されるデータは正しくない可能性があります。(2) 再帰的に呼び出される関数では、100% を超えるアクティビティーが表示される可能性があります。(1) を考慮して、–g を使用する場合のデフォルトのデータ収集モードは –s 50 です。
関数内の PC を 1 つにまとめます。
出力を filename に送ります。
(数 * 時間) の積でデータをソートします。
解析可能な出力形式。
数ではなくレート (1 秒あたりのイベント数) を表示します。
任意の対象: イベントをロックではなく呼び出し元でのみ区別します。
任意の場所: イベントを呼び出し元ではなくロックでのみ区別します。
各種のデータ列に対して次のヘッダーが表示されます。
このイベントが発生した回数。–R が指定された場合はレート (1 秒あたりの回数)。
この特定のイベントで表されるすべてのイベントの割合。
この関数によって生成されたすべてのイベントの割合。
累積率 (現在までの個別の合計)。
平均参照数。これは、排他ロック (相互排他ロック、スピンロック、書き込みとして保持されている読み取り書き込みロック) では常に 1 になりますが、共有ロック (読み取りとして保持されている読み取り書き込みロック) では 1 より大きくなることがあります。
イベントのナノ秒単位の平均期間 (イベントに適する場合)。プロファイルイベントの場合、期間は割り込みの待機時間を意味します。
可能な場合にシンボルで表示される、ロックのアドレス。
CPU とプロセッサ割り込みレベル (PIL)。たとえば、PIL 6 の最中に CPU 4 が割り込まれた場合、これは cpu[4]+6 として報告されます。
可能な場合にシンボルで表示される、呼び出し元のアドレス。
example# lockstat sleep 5 Adaptive mutex spin: 2210 events in 5.055 seconds (437 events/sec)
Count indv cuml rcnt nsec Lock Caller
------------------------------------------------------------------------
269 12% 12% 1.00 2160 service_queue background+0xdc
249 11% 23% 1.00 86 service_queue qenable_locked+0x64
228 10% 34% 1.00 131 service_queue background+0x15c
68 3% 37% 1.00 79 0x30000024070 untimeout+0x1c
59 3% 40% 1.00 384 0x300066fa8e0 background+0xb0
43 2% 41% 1.00 30 rqcred_lock svc_getreq+0x3c
42 2% 43% 1.00 341 0x30006834eb8 background+0xb0
41 2% 45% 1.00 135 0x30000021058 untimeout+0x1c
40 2% 47% 1.00 39 rqcred_lock svc_getreq+0x260
37 2% 49% 1.00 2372 0x300068e83d0 hmestart+0x1c4
36 2% 50% 1.00 77 0x30000021058 timeout_common+0x4
36 2% 52% 1.00 354 0x300066fa120 background+0xb0
32 1% 53% 1.00 97 0x30000024070 timeout_common+0x4
31 1% 55% 1.00 2923 0x300069883d0 hmestart+0x1c4
29 1% 56% 1.00 366 0x300066fb290 background+0xb0
28 1% 57% 1.00 117 0x3000001e040 untimeout+0x1c
25 1% 59% 1.00 93 0x3000001e040 timeout_common+0x4
22 1% 60% 1.00 25 0x30005161110 sync_stream_buf+0xdc
21 1% 60% 1.00 291 0x30006834eb8 putq+0xa4
19 1% 61% 1.00 43 0x3000515dcb0 mdf_alloc+0xc
18 1% 62% 1.00 456 0x30006834eb8 qenable+0x8
18 1% 63% 1.00 61 service_queue queuerun+0x168
17 1% 64% 1.00 268 0x30005418ee8 vmem_free+0x3c
[...]
R/W reader blocked by writer: 76 events in 5.055 seconds (15 events/sec)
Count indv cuml rcnt nsec Lock Caller
------------------------------------------------------------------------
23 30% 30% 1.00 22590137 0x300098ba358 ufs_dirlook+0xd0
17 22% 53% 1.00 5820995 0x3000ad815e8 find_bp+0x10
13 17% 70% 1.00 2639918 0x300098ba360 ufs_iget+0x198
4 5% 75% 1.00 3193015 0x300098ba360 ufs_getattr+0x54
3 4% 79% 1.00 7953418 0x3000ad817c0 find_bp+0x10
3 4% 83% 1.00 935211 0x3000ad815e8 find_read_lof+0x14
2 3% 86% 1.00 16357310 0x300073a4720 find_bp+0x10
2 3% 88% 1.00 2072433 0x300073a4720 find_read_lof+0x14
2 3% 91% 1.00 1606153 0x300073a4370 find_bp+0x10
1 1% 92% 1.00 2656909 0x300107e7400 ufs_iget+0x198
[...]
使用例 2 保持回数の測定
example# lockstat -H -D 10 sleep 1 Adaptive mutex spin: 513 events
Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------- 480 5% 5% 1.00 1136 0x300007718e8 putnext+0x40 286 3% 9% 1.00 666 0x3000077b430 getf+0xd8 271 3% 12% 1.00 537 0x3000077b430 msgio32+0x2fc 270 3% 15% 1.00 3670 0x300007718e8 strgetmsg+0x3d4 270 3% 18% 1.00 1016 0x300007c38b0 getq_noenab+0x200 264 3% 20% 1.00 1649 0x300007718e8 strgetmsg+0xa70 216 2% 23% 1.00 6251 tcp_mi_lock tcp_snmp_get+0xfc 206 2% 25% 1.00 602 thread_free_lock clock+0x250 138 2% 27% 1.00 485 0x300007c3998 putnext+0xb8 138 2% 28% 1.00 3706 0x300007718e8 strrput+0x5b8 ------------------------------------------------------------------------- [...]使用例 3 特定の関数を含むスタックトレースの保持回数の測定
example# lockstat -H -f so_recvmsg -s 50 -D 10 sleep 10 Adaptive mutex hold: 171792 events in 10.089 seconds (17028 events/sec)
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Lock Caller
48140 28% 28% 0.00 1109 0x184004c76ade8 so_recvmsg+0x8a0
nsec ------ Time Distribution ------ count Stack
1024 | 991 socket_recvmsg+0x28
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 47120 socket_vop_read+0x20
4096 | 28 fop_read+0xe8
8192 | 0 read+0x2d0
16384 | 0 syscall_trap+0x238
32768 | 0
65536 | 0
131072 | 1
[...]
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Lock Caller
37756 22% 100% 0.00 1076 0x18400555603e0 so_recvmsg+0x2bc
nsec ------ Time Distribution ------ count Stack
1024 |@@@@@ 7519 socket_recvmsg+0x28
2048 |@@@@@@@@@@@@@@@@@@@@@@@ 30193 socket_vop_read+0x20
4096 | 41 fop_read+0xe8
8192 | 3 read+0x2d0
syscall_trap+0x238
[...]
使用例 4 基本的なカーネルプロファイル
基本的なプロファイルでは、プロファイル割り込みによって foo()+0x4c と foo()+0x78 のどちらがサンプリングされたかを気にする必要はなく、foo() のどこかがサンプリングされていればよいため、–k を使用します。特定の CPU や割り込みレベルではなくシステム全体を測定するので、CPU と PIL は基本的なプロファイルに関係ありません。したがって、–W を使用します。
example# lockstat -kIW -D 20 ./polltest Profiling interrupt: 82 events in 0.424 seconds (194 events/sec)
Count indv cuml rcnt nsec Hottest CPU+PIL Caller
-----------------------------------------------------------------------
8 10% 10% 1.00 698 cpu[1] utl0
6 7% 17% 1.00 299 cpu[0] read
5 6% 23% 1.00 124 cpu[1] getf
4 5% 28% 1.00 327 cpu[0] fifo_read
4 5% 33% 1.00 112 cpu[1] poll
4 5% 38% 1.00 212 cpu[1] uiomove
4 5% 43% 1.00 361 cpu[1] mutex_tryenter
3 4% 46% 1.00 682 cpu[0] write
3 4% 50% 1.00 89 cpu[0] pcache_poll
3 4% 54% 1.00 118 cpu[1] set_active_fd
3 4% 57% 1.00 105 cpu[0] syscall_trap32
3 4% 61% 1.00 640 cpu[1] (usermode)
2 2% 63% 1.00 127 cpu[1] fifo_poll
2 2% 66% 1.00 300 cpu[1] fifo_write
2 2% 68% 1.00 669 cpu[0] releasef
2 2% 71% 1.00 112 cpu[1] bt_getlowbit
2 2% 73% 1.00 247 cpu[1] splx
2 2% 76% 1.00 503 cpu[0] mutex_enter
2 2% 78% 1.00 467 cpu[0]+10 disp_lock_enter
2 2% 80% 1.00 139 cpu[1] default_copyin
-----------------------------------------------------------------------
[...]
使用例 5 生成される負荷のプロファイル
上の例では、サンプルの 5% が poll() に含まれていました。これにより、poll() 自体の内部で費やした時間はわかりますが、poll() によってどの程度の処理が生成されたか、つまり、poll() によって呼び出された関数内で費やした時間はわかりません。それを判定するには、–g オプションを使用します。次の例は、polltest が poll() 自体で費やした時間は 5% だけだが、poll() によって引き起こされた処理は負荷の 34% を占めることを示しています。
プロファイル割り込みを生成する関数 (lockstat_intr() や cyclic_fire() など) はどのスタックトレースにも表示されるため、負荷の 100% を生成していると見なされます。これは重要なことを示してます。生成される負荷の割合は互いに独立していないため、合計しても 100% にはなりません。すべてのスタックトレースの 72% に foo() と bar() の両方が含まれている場合、foo() と bar() の両方が 72% の負荷を生成することになります。
example# lockstat -kgIW -D 20 ./polltest Profiling interrupt: 80 events in 0.412 seconds (194 events/sec)
Count genr cuml rcnt nsec Hottest CPU+PIL Caller
-------------------------------------------------------------------------
80 100% ---- 1.00 310 cpu[1] lockstat_intr
80 100% ---- 1.00 310 cpu[1] cyclic_fire
80 100% ---- 1.00 310 cpu[1] cbe_level14
80 100% ---- 1.00 310 cpu[1] current_thread
27 34% ---- 1.00 176 cpu[1] poll
20 25% ---- 1.00 221 cpu[0] write
19 24% ---- 1.00 249 cpu[1] read
17 21% ---- 1.00 232 cpu[0] write32
17 21% ---- 1.00 207 cpu[1] pcache_poll
14 18% ---- 1.00 319 cpu[0] fifo_write
13 16% ---- 1.00 214 cpu[1] read32
10 12% ---- 1.00 208 cpu[1] fifo_read
10 12% ---- 1.00 787 cpu[1] utl0
9 11% ---- 1.00 178 cpu[0] pcacheset_resolve
9 11% ---- 1.00 262 cpu[0] uiomove
7 9% ---- 1.00 506 cpu[1] (usermode)
5 6% ---- 1.00 195 cpu[1] fifo_poll
5 6% ---- 1.00 136 cpu[1] syscall_trap32
4 5% ---- 1.00 139 cpu[0] releasef
3 4% ---- 1.00 277 cpu[1] polllock
-------------------------------------------------------------------------
[...]
使用例 6 特定のモジュールに関するロック競合およびプロファイルデータの収集
In this example we use the –f option not to specify a single function, but rather to specify the entire text space of the procfs module.ロック競合とプロファイルの両方の統計情報を収集して、競合をモジュールの全体的な負荷と関係付けることができるようにします。
example# modinfo | grep procfs # modinfo | grep procfs 9 10b0a698 1b068 5 1 procfs (filesystem for proc)
example# lockstat -kICE -f 0x10b0a698,0x1b068 sleep 10 Adaptive mutex spin: 16 events in 10.042 seconds (2 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
15 94% 94% 0.00 2158 pr_pidlock pr_p_lock_i
1 6% 100% 0.00 3060 pr_pidlock prinactive
-------------------------------------------------------------------------------
Profiling interrupt: 4 events in 10.033 seconds (0 events/sec)
Count indv cuml rcnt nsec CPU+PIL Caller
-------------------------------------------------------------------------------
1 25% 25% 0.00 588 cpu[108]+11 prchoose
1 25% 50% 0.00 492 cpu[108] prchoose
1 25% 75% 0.00 225 cpu[50]+11 prchoose
1 25% 100% 0.00 1785 cpu[50] prchoose
-------------------------------------------------------------------------------
使用例 7 CPU の平均 PIL (プロセッサ割り込みレベル) の判定
example# lockstat -Iw -l cpu[3] ./testprog
Profiling interrupt: 14791 events in 152.463 seconds (97 events/sec)
Count indv cuml rcnt nsec CPU+PIL Hottest Caller
-----------------------------------------------------------------------
13641 92% 92% 1.00 253 cpu[3] (usermode)
579 4% 96% 1.00 325 cpu[3]+6 ip_ocsum+0xe8
375 3% 99% 1.00 411 cpu[3]+10 splx
154 1% 100% 1.00 527 cpu[3]+4 fas_intr_svc+0x80
41 0% 100% 1.00 293 cpu[3]+13 send_mondo+0x18
1 0% 100% 1.00 266 cpu[3]+12 zsa_rxint+0x400
-----------------------------------------------------------------------
[...]
使用例 8 システムをビジー状態にしているサブシステムの特定
example# lockstat -s 10 -I sleep 20
Profiling interrupt: 4863 events in 47.375 seconds (103 events/sec)
Count indv cuml rcnt nsec CPU+PIL Caller
787 8% 8% 0.00 1953 cpu[112] default_mutex_lock_delay+0x6c
nsec ------ Time Distribution ------ count Stack
512 |@ 31 default_mutex_lock_delay+0x64
1024 |@@@@@@@@@@@@@@@@@ 460 lock_set_spl_spin+0xcc
2048 |@@@@@@@@@@ 277 turnstile_lookup+0x48
4096 | 19 rw_enter_sleep+0xcc
sdev_access+0x10
sdev_lookup+0x20
fop_lookup+0x15c
lookuppnvp+0x49c
lookuppnatcred+0x110
-----------------------------------------------------------------------
[...]
属性についての詳細は、マニュアルページの attributes(7) を参照してください。
|
lockstat(4D), attributes(7), dtrace(8), plockstat(8), mutex(9F), rwlock(9F)
Oracle Solaris 11.4 DTrace (Dynamic Tracing) Guide
古い (文書化されていない) /usr/bin/kgmon および /dev/profile は、lockstat –I で提供されるプロファイルサポートによって置き換えられます。
末尾呼び出しの削除は、呼び出し側に影響する可能性があります。たとえば、foo()+0x50 が bar() を呼び出し、bar() が最後に実行する処理が mutex_exit() の呼び出しである場合、コンパイラは bar() が foo()+0x58 という戻りアドレスで mutex_exit() に分岐するように設定する可能性があります。したがって、bar() 内の mutex_exit() は foo()+0x58 で発生したかのように表示されます。
コンパイラは関数呼び出しの間にローカルストレージの戻りアドレスレジスタを自由に使用できるため、割り込みが発生するスタックフレーム内の PC は不正である可能性があります。
–I オプションと –s オプションを同時に使用すると、割り込みハンドラがその PC からの関数呼び出しではなく非同期で実行を開始するため、割り込まれた PC は通常スタックのどこにも表示されません。
lockstat テクノロジーは現状のまま提供されます。lockstat の出力形式と出力内容は、最新の Solaris カーネル実装を反映するため、将来のリリースで変更される場合があります。