次に、Dプログラの例readtrace.d
を示します。
/* readtrace.d -- Display time spent in read() calls */ syscall::read:entry { self->t = timestamp; /* Initialize a thread-local variable */ } syscall::read:return /self->t != 0/ { printf("%s (pid=%d) spent %d microseconds in read()\n", execname, pid, ((timestamp - self->t)/1000)); /* Divide by 1000 for microseconds */ self->t = 0; /* Reset the variable */ }
例では、readtrace.d
プログラムは、プロセスがread()
システム・コールを起動するたびに、コマンド名、プロセスIDおよびコール継続時間をマイクロ秒で表示します。 変数self->t
はスレッド・ローカルです。これは、システムでのスレッド実行のスコープ内にのみ存在することを意味します。 プログラムでは、プロセスがread()
をコールするときにself->t
のtimestamp
の値が記録され、コールが戻るときにtimestamp
の値からこの値が減算されます。 timestamp
の単位はナノ秒であるため、1000で除算して値をマイクロ秒で取得します。
このプログラムの実行結果は次のとおりです:
#dtrace -q -s readtrace.d
NetworkManager (pid=878) spent 10 microseconds in read() NetworkManager (pid=878) spent 9 microseconds in read() NetworkManager (pid=878) spent 2 microseconds in read() in:imjournal (pid=815) spent 63 microseconds in read() gdbus (pid=878) spent 7 microseconds in read() gdbus (pid=878) spent 66 microseconds in read() gdbus (pid=878) spent 63 microseconds in read() irqbalance (pid=816) spent 56 microseconds in read() irqbalance (pid=816) spent 113 microseconds in read() irqbalance (pid=816) spent 104 microseconds in read() irqbalance (pid=816) spent 91 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 63 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() irqbalance (pid=816) spent 61 microseconds in read() sshd (pid=10230) spent 8 microseconds in read() in:imjournal (pid=815) spent 6 microseconds in read() sshd (pid=10230) spent 7 microseconds in read() in:imjournal (pid=815) spent 5 microseconds in read() sshd (pid=10230) spent 7 microseconds in read() in:imjournal (pid=815) spent 6 microseconds in read() sshd (pid=10230) spent 7 microseconds in read() in:imjournal (pid=815) spent 5 microseconds in read()^C