prex(1) カーネルトレース
１．prexカーネルトレース Solaris 8 prex、tnfxtract、およびtnfdumpコマンド
プロセスやスレッドの動き、ディスク入出力の動き等を詳細に調査したい場合、Solaris 8より提供されたprexコマンド【備考1】によって情報を採取し、分析できるようになりました。prexは、TNF（Trace Normal Form)に基づいたカーネルプローブを組み込んだ幾つかのカーネルルーチンのトレース情報を採取します。prexは、所定の条件に基づき、キー"keys"で定義されたセレクタを判別して、トレースデータをバッファに順次書き込みます。フィルタにプロセスIDを使用することも出来ます。トレース終了後、tnfxtractコマンドでそのバッファからトレース情報を抜き出し、tnfdumpコマンドで編集する流れになります。このprexバッファは、採取されるトレース情報量により、どれだけのサイズが最適かは現在のところ調査中です。判明次第お知らせします。当面、システムの実装メモリ、空きメモリ等から判断いただきますようお願いします。図1にカーネルトレース採取の手順を示します。
| No | 手順 | 操作概要 | ||||||||||||||||||
| 1 | 開始 |
|
||||||||||||||||||
| 2 | 情報採取 | トレースを採取したい目的の操作を行います | ||||||||||||||||||
| 3 | 停止 |
|
||||||||||||||||||
| 4 | 情報の抜き出し |
|
||||||||||||||||||
| 5 | 情報の編集 |
|
||||||||||||||||||
| 6 | バッファ解放 |
|
||||||||||||||||||
図１．カーネルトレースの手順
【備考１】prexコマンドについて
デバッグ中のプログラムにプローブを埋め込み、所定の方法でコンパイルすることでprexコマンドを用いてデバッグすることも出来ます。ユーザプログラム(コマンド)のトレーシングは"prex [ -o tracefile ] command ... "と指定して実行します。詳細はprex(1)、tracing(3TNF)、およびTNF_PROBE(3TNF)のマニュアルページをご覧下さい。また、GNUのgccによるプロファイル機能を使用してデバッグや、計測、プロファイリングを行うことも出来ます。 詳細はGNU gccコンパイラのドキュメントと、prof(1)、gprof(1)のマニュアルページをご覧下さい。
【備考２】バッファ割り当てについて
バッファはカーネルのsegkと呼ばれるセグメントに確保されます。この領域はページングの対象外で、メモリにロックされます。prexを実行すると会話モードになります。会話モードに入って最初に実行するコマンドは、次のようになります。単に"buffer
alloc"とすると、384キロバイトのバッファが確保されます。数値の後ろの"m"はメガバイト単位(1,048,576バイト)で確保することを示します。"k"を指定するとキロバイト単位(1,024バイト)で確保されます。バッファサイズの省略時値は393,216バイト(約400キロバイト)、最大長は134,217,728バイト(約134メガバイト)です。それよりも大きな値を指定しても134メガバイトに切り詰められます。
| # prex -k <CR> Type "help" for help ... prex> buffer alloc 4m <CR> Buffer of size 4194304 bytes allocated prex> |
図２．バッファの割り当て bufferファンクション
【備考３】keysの確認
"keys"を設定することが出来ます。省略時は「全部」になっています。このため、プローブを$allでイネーブルすると全部のトレースになります。省略時の設定は次のようになっており、"keys"は/.*/の正規表現のため、全部がマッチすることになります。
| prex> list sets <CR> $all 'keys'=/.*/ prex> |
図３．プローブの正規表現
【備考４】keysに指定できるもの
現在、明確に判明している"keys"は次の通りです。先の$allによって採取、抜き出し(tnfxtract)、編集(tnfdump)した出力の先頭に表示される行です。実際はもっと増えているか、または変わっている可能性もあります。目的のシステムで、$allによって試しに出力されることをお勧めします。
| probe tnf_name: "syscall_end" tnf_string: "keys syscall thread;file ../../sparc/os/syscall.c;line 853;" probe tnf_name: "syscall_start" tnf_string: "keys syscall thread;file ../../sparc/os/syscall.c;line 541;" probe tnf_name: "thread_block" tnf_string: "keys synch;file ../../common/tnf/tnf_res.c;line 290;" probe tnf_name: "thread_state" tnf_string: "keys thread;file ../../common/tnf/tnf_res.c;line 306;" probe tnf_name: "thread_state" tnf_string: "keys thread;file ../../common/tnf/tnf_res.c;line 323;" probe tnf_name: "thread_queue" tnf_string: "keys dispatcher;file ../../common/tnf/tnf_res.c;line 221;" probe tnf_name: "thread_state" tnf_string: "keys thread;file ../../common/tnf/tnf_res.c;line 225;" probe tnf_name: "biodone" tnf_string: "keys io blockio;file ../../common/os/bio.c;line 1201;" probe tnf_name: "pageout" tnf_string: "keys vm pageio io;file ../../common/vm/vm_pvn.c;line 553;" probe tnf_name: "thread_state" tnf_string: "keys thread;file ../../sun4u/os/trap.c;line 337;" probe tnf_name: "address_fault" tnf_string: "keys vm pagefault;file ../../common/vm/vm_as.c;line 1239;" probe tnf_name: "thread_state" tnf_string: "keys thread;file ../../sun4u/os/trap.c;line 1141;" probe tnf_name: "page_unmap" tnf_string: "keys vm pagefault;file ../../common/vm/vm_page.c;line 2683;" probe tnf_name: "thread_exit" tnf_string: "keys thread;file ../../common/tnf/tnf_res.c;line 165;" probe tnf_name: "anon_zero" tnf_string: "keys vm pagefault;file ../../common/vm/vm_anon.c;line 1209;" probe tnf_name: "anon_private" tnf_string: "keys vm pagefault;file ../../common/vm/vm_anon.c;line 1105;" probe tnf_name: "strategy" tnf_string: "keys io blockio;file ../../common/os/driver.c;line 529;" probe tnf_name: "thread_create" tnf_string: "keys thread;file ../../common/tnf/tnf_res.c;line 150;" probe tnf_name: "major_fault" tnf_string: "keys vm pagefault;file ../../common/os/bio.c;line 1270;" probe tnf_name: "pagein" tnf_string: "keys vm pageio io;file ../../common/os/bio.c;line 1297;" ---------------- ---------------- ----- ----- ---------- --- ------------------------- ------------------------ Elapsed (ms) Delta (ms) PID LWPID TID CPU Probe Name Data / Description . . . ---------------- ---------------- ----- ----- ---------- --- ------------------------- ------------------------ ： |
図４．keysの具体例
grepコマンドに指定するように、例えば"io"を指定すると"biodone"、"pageout"、"strategy"、および"pagein"のプローブが対象になります。これらを$allの代わりに、"enable"と"trace"ファンクションに指定します。例えば"thread"(スレッド)をセットする場合は次のようになります。
| prex> enable thread <CR> prex> trace thread <CR> prex> |
図５．threadのセット例
【備考５】編集ファイルサイズについて
$allの場合、とんでもない編集ファイルサイズになりますので、くれぐれもご注意下さい(ORACLEのdbstartとdbshutだけで、約18メガバイト、約16万行でした!!)。
【備考６】バッファの解放
バッファを開放すると、"buffer deallocated"のメッセージが表示されます。segk(カーネルセグメント)からトレースバッファが解放されます。バッファを開放しないでトレースを採取した場合、情報がミックスされます。トレース情報がバッファの最後までいくと先頭から上書きされます。正確な情報を採取したい場合は逐次、割り当て→解放することをお勧めします。
| # prex -k <CR> Type "help" for help ... prex> buffer dealloc <CR> buffer deallocated prex> quit <CR> # |
図６．バッファの解放
２．syscallを選択してトレースする
keysにsyscallを選択してトレースする例を示します。この結果、システムコールの最初と終わり(図4の1行目と2行目のプローブ)の2種類のトレースが採取されます。
| # prex -k <CR> Type "help" for help ... prex> buffer alloc 4m <CR> Buffer of size 4194304 bytes allocated prex> enable syscall <CR> prex> trace syscall <CR> prex> ktrace on <CR> ： →quitしてから、prexコマンドを再起動しても良いです。 prex> ktrace off <CR> prex> quit <CR> # tnfxtract syscall.trc <CR> # tnfdump syscall.trc > syscall.dump <CR> # prex -k <CR> Type "help" for help ... prex> buffer dealloc <CR> buffer deallocated prex> quit <CR> # |
図７．syscallを選択してトレースする例
３．プロセスフィルタリング
常駐しているプロセスに関連するトレースを採取したい場合、pfilterファンクションで目的のプロセスを指定することが出来ます。keysを"thread"(スレッド)としてプロセスフィルタリングを行う例を図11に示します。
| # ps -efl | grep ckpt | grep -v grep <CR> 8 S oracle 592 1 1 41 20 ? 53304 ? 15:48:48 ? 0:13 ora_ckpt_ora900 # prex -k <CR> Type "help" for help ... prex> buffer alloc <CR> Buffer of size 393216 bytes allocated prex> pfilter add 592 <CR> prex> pfilter on <CR> prex> pfilter <CR> Process filtering is on Process filter set is {592} prex> tarce thread <CR> prex> enable thread <CR> prex> ktrace on <CR> ： →quitしてから、prexコマンドを再起動しても良いです。 prex> ktrace off <CR> prex> pfilter off <CR> prex> quit <CR> # tnfxtract /var/tmp/ckpt_thread.trc <CR> # tnfdump /var/tmp/ckpt_thread.trc > /var/tmp/ckpt_thread.dump <CR> # prex -k <CR> Type "help" for help ... prex> buffer dealloc <CR> buffer deallocated prex> quit <CR> # |
図８．プロセスフィルタリングの例
【参考】prex(1)は他に多くの機能を持っています。詳細は関連するマニュアルページtracing(1)、TNF_PROBE(3TNF)、tnfdump(1)、tnfxtrace(1)をご覧下さい。
４．トレース情報の見方
前述の$allによって編集した出力の先頭は、トレース可能なプローブの一覧です。各行は、カーネルルーチン名と、ソースコードの行番号が表示されています。それぞれ、プローブによって採取される情報が異なります。トレース情報は、tnfdumpで出力される編集出力の"Data / Description"項目に表示されます。図4の範囲でどのような情報がトレースされるのかを図9に示します。なお、ソースコード行番号、および"Data / Description"はカーネルレベルやパッチレベルで変更される可能性があります。
| ルーチン名 | TNF名 | keys | 行番号 | 関数名・概要 | Data/Description | 関連ヘッダーファイル |
| bio.c 【備考1】 |
biodone | io blockio |
1201 | biodone ブロック型入出力の完了 |
device: b_edev block: b_lblkno buf: buf構造体アドレス |
buf.h(buf構造体) |
| major_fault | vm pagefault |
1270 | pageio_setup メジャーフォルト |
vnode: p_vnode offset: p_offset |
page.h(page構造体) | |
| pagein | vm pageio io |
1297 | pageio_setup ページイン |
vnode: p_vnode offset: p_offset size: len |
page.h(page構造体) | |
| driver.c 【備考1】 |
strategy | io blockio |
529 | bdev_strategy ディスクストラテジー |
device: b_edev block: b_lblkno size: b_bcount buf: buf構造体アドレス flags: b_flags |
buf.h(buf構造体) |
| tnf_res.c 【備考2】 |
thread_create | thread | 150 | tnf_thread_create スレッドクリエイト |
tid: kthread_t pid: p_pid start_pc: t_startpc |
thread.h(thread構造体) ttoprocによるプロセスID |
| thread_exit | thread | 165 | tnf_thread_exit スレッドエグジット |
ops = t_tnf_tpdp | thread.h(thread構造体) tnf_writer.h(TNFデータ構造体) |
|
| thread_queue | dispatcher | 221 | tnf_thread_queue スレッドキュー |
tid: kthread_t cpuid: cpu_id priority: pri_t queue_length: cpu_disp.disp_nrunnable |
thread.h(thread構造体) cpuvar.h(cpu構造体) types.h(short型) disp.h(disp構造体) |
|
| thread_state | thread | 225 | tnf_thread_queue スレッドキュー |
tid: kthread_t state: LMS_WAIT_CPU (8) |
thread.h(thread構造体) msacct.h(LWPマイクロステート) |
|
| thread_block | synch | 290 | tnf_thread_switch スレッドブロック |
reason: t_wchan stack: pcstack(pcs) |
thread.h(thread構造体) pcstackによるスタックポインタ |
|
| thread_state | thread | 306 | tnf_thread_switch スレッドスイッチ |
state: SLPSTATE | SLPSTATEによるステート | |
| thread_state | thread | 323 | tnf_thread_switch スレッドスイッチ |
state: RUNSTATE | RUNSTATEによるステート | |
| vm_anon.c 【備考3】 |
anon_private | vm pagefault |
1105 | anon_private COWセグメント |
address: addr | caddr_t(ページアドレス) |
| anon_zero | vm pagefault |
1209 | anon_zero ゼロフィルセグメント |
address: addr | caddr_t(ページアドレス) | |
| vm_as.c 【備考3】 |
address_fault | vm pagefault |
1239 | as_fault ページフォルト |
address: addr fault_type: type access: rw |
caddr_t(ページアドレス) seg_enum.h(タイプと型) |
| vm_page.c 【備考3】 |
page_unmap | vm pagefault |
2683 | page_hashout ページの削除 |
vnode: vp offset: p_offset |
vnode.h(vnode構造体) page.h(page構造体) |
| vm_pvn.c 【備考3】 |
pageout | vm pageio io |
553 | pvn_write_done ページ書き込み |
vnode: vp pages_pageout: pgpgout pages_freed: dfree pages_reclaimed: pgrec |
vnode.h(vnode構造体) pageout、free、およびreclaimedのカウント |
| syscall.c 【備考4】 |
syscall_start | syscall thread |
541 | pre_syscall システムコール開始 |
sysnum: t_sysnum | thread.h(system call number) |
| syscall_end | syscall thread |
853 | post_syscall システムコール終了 |
rval1: rval1 rval2: rval2 errno: errno |
rval1、rval2は64ビットの場合の戻り値。 ｅｒｒｎｏ．ｈ |
|
| trap.c 【備考5】 |
thread_state | thread | 337 | trap プロセッサトラップ |
state: mstate | msacct.h |
| thread_state | thread | 1141 | trap ユーザトラップ |
state: LMS_USER (0) | msacct.h |
図９．トレース情報の見方
Copyright (C) 2004 by The Art of Computer Technologies, Corp. All rights reserved.