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 のセキュリティー機能の詳細は、『Solaris 動的トレースガイド』を参照してください。
サポートしているオプションは、次のとおりです。
イベント選択オプションが指定されていない場合、デフォルトは –C です。
すべてのロックイベントを監視します。–A は –CH と同等です。
競合イベントを監視します。
エラーイベントを監視します。
指定されたイベントのみを監視します。event list は、コンマで区切られたイベントまたはイベントの範囲のリストです (例: 1,4-7,35)。引数なしで lockstat を実行すると、すべてのイベントの簡単な説明が表示されます。
保持イベントを監視します。
プロファイル割り込みイベントを監視します。
–I の割り込みレート (秒単位)。プロファイルが (100 Hz で実行される) クロック割り込みと完全に連動して実行されないように、デフォルトは 97 Hz です。
DTrace の実行時オプションまたは D コンパイラオプションを有効化または変更します。オプションのリストについては、dtrace(1M) を参照してください。ブール型のオプションを有効にするときは、その名前を指定します。値を持つオプションを設定するには、オプションの名前と値を等号 (=) で分離します。
基本的な統計情報: ロック、呼び出し元、イベント数。
ヒストグラム: タイミングおよび時間分布ヒストグラム。
スタックトレース: ヒストグラムおよびスタックトレース (最大 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 tcp_rput_data -s 50 -D 10 sleep 1 Adaptive mutex spin: 11 events in 1.023 seconds (11 events/sec)
------------------------------------------------------------------------- Count indv cuml rcnt nsec Lock Caller 9 82% 82% 1.00 2540 0x30000031380 tcp_rput_data+0x2b90 nsec ------ Time Distribution ------ count Stack 256 |@@@@@@@@@@@@@@@@ 5 tcp_rput_data+0x2b90 512 |@@@@@@ 2 putnext+0x78 1024 |@@@ 1 ip_rput+0xec4 2048 | 0 _c_putnext+0x148 4096 | 0 hmeread+0x31c 8192 | 0 hmeintr+0x36c 16384 |@@@ 1 sbus_intr_wrapper+0x30 [...] Count indv cuml rcnt nsec Lock Caller 1 9% 91% 1.00 1036 0x30000055380 freemsg+0x44 nsec ------ Time Distribution ------ count Stack 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 freemsg+0x44 tcp_rput_data+0x2fd0 putnext+0x78 ip_rput+0xec4 _c_putnext+0x148 hmeread+0x31c hmeintr+0x36c sbus_intr_wrapper+0x30 ------------------------------------------------------------------------- [...]使用例 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 特定のモジュールに関するロック競合およびプロファイルデータの収集
この例では、–f オプションを使用しますが、単独の関数を指定せずに sbus モジュールのテキスト空間全体を指定します。ロック競合とプロファイルの両方の統計情報を収集して、競合をモジュールの全体的な負荷と関係付けることができるようにします。
example# modinfo | grep sbus 24 102a8b6f b8b4 59 1 sbus (SBus (sysio) nexus driver)
example# lockstat -kICE -f 0x102a8b6f,0xb8b4 sleep 10 Adaptive mutex spin: 39 events in 10.042 seconds (4 events/sec)
Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------- 15 38% 38% 1.00 206 0x30005160528 sync_stream_buf 7 18% 56% 1.00 14 0x30005160d18 sync_stream_buf 6 15% 72% 1.00 27 0x300060c3118 sync_stream_buf 5 13% 85% 1.00 24 0x300060c3510 sync_stream_buf 2 5% 90% 1.00 29 0x300060c2d20 sync_stream_buf 2 5% 95% 1.00 24 0x30005161cf8 sync_stream_buf 1 3% 97% 1.00 21 0x30005161110 sync_stream_buf 1 3% 100% 1.00 23 0x30005160130 sync_stream_buf [...] Adaptive mutex block: 9 events in 10.042 seconds (1 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------- 4 44% 44% 1.00 156539 0x30005160528 sync_stream_buf 2 22% 67% 1.00 763516 0x30005160d18 sync_stream_buf 1 11% 78% 1.00 462130 0x300060c3510 sync_stream_buf 1 11% 89% 1.00 288749 0x30005161110 sync_stream_buf 1 11% 100% 1.00 1015374 0x30005160130 sync_stream_buf [...] Profiling interrupt: 229 events in 10.042 seconds (23 events/sec) Count indv cuml rcnt nsec Hottest CPU+PIL Caller ------------------------------------------------------------------------- 89 39% 39% 1.00 426 cpu[0]+6 sync_stream_buf 64 28% 67% 1.00 398 cpu[0]+6 sbus_intr_wrapper 23 10% 77% 1.00 324 cpu[0]+6 iommu_dvma_kaddr_load 21 9% 86% 1.00 512 cpu[0]+6 iommu_tlb_flush 14 6% 92% 1.00 342 cpu[0]+6 iommu_dvma_unload 13 6% 98% 1.00 306 cpu[1] iommu_dvma_sync 5 2% 100% 1.00 389 cpu[1] iommu_dma_bindhdl ------------------------------------------------------------------------- [...]使用例 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 ----------------------------------------------------------------------- 1929 40% 40% 0.00 3215 cpu[0] usec_delay+0x78 nsec ------ Time Distribution ------ count Stack 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1872 ata_wait+0x90 8192 | 27 acersb_get_intr_status+0x34 16384 | 29 ata_set_feature+0x124 32768 | 1 ata_disk_start+0x15c ata_hba_start+0xbc ghd_waitq_process_and \ _mutex_hold+0x70 ghd_waitq_process_and \ _mutex_exit+0x4 ghd_transport+0x12c ata_disk_tran_start+0x108 ----------------------------------------------------------------------- [...]
属性についての詳細は、マニュアルページの attributes(5) を参照してください。
|
dtrace(1M), plockstat(1M), attributes(5), lockstat(7D), mutex(9F), rwlock(9F)
『Solaris 動的トレースガイド』
古い (文書化されていない) /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 カーネル実装を反映するため、将来のリリースで変更される場合があります。