「enqueue と dequeue」の最後の例では、実行可能な xterm プロセスのせいで実行キュー長のバーストが起こったことがわかりました。ここで、この測定結果は仮想デスクトップの変更に起因するものだという仮説を立てることができます。この仮説を検証するには、wakeup プローブを使って、xterm プロセスが何によって呼び起こされているか、またその時期を特定します。次の例を参照してください。
#pragma D option quiet dtrace:::BEGIN { start = timestamp; } sched:::wakeup /stringof(args[1]->pr_fname) == "xterm"/ { @[execname] = lquantize((timestamp - start) / 1000000000, 0, 10); } profile:::tick-1sec /++x == 10/ { exit(0); }
仮説の検証のため、このスクリプトを実行し、5 秒ほど待ったあと、1 度だけ仮想デスクトップを切り替えます。実行可能な xterm プロセスのバーストが、仮想デスクトップを切り替えたせいで発生しているのであれば、次の出力例のように、5 秒経過したところで呼び起こしアクティビティのバーストが確認されるはずです。
# dtrace -s ./xterm.d Xsun value -------------- Distribution ------------ count 4 | 0 5 |@ 1 6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32 7 | 0 |
この出力から、xterm プロセスが仮想デスクトップの切り替えを行なった前後の時間帯に集中していることと、これらの xterm プロセスが X サーバーによって呼び起こされたことがわかります。X サーバーと xterm プロセスのやりとりについて調べたい場合は、X サーバーが wakeup プローブを起動したときのユーザースタックトレースを集積します。
X ウィンドウシステムのようなクライアントサーバーシステムのパフォーマンスについて理解するには、サーバーのサービス提供先であるクライアントについて理解する必要があります。この種の問題に対する答えは、従来のパフォーマンス解析ツールでは得にくいものです。しかし、「サーバーにメッセージを送信したクライアントは、サーバー側の処理が完了するまでスリープする」というモデルがある場合は、wakeup プローブを使って、サーバーがどのクライアントの要求を処理しているのかを特定できます。次の例を参照してください。
self int last; sched:::wakeup /self->last && args[0]->pr_stype == SOBJ_CV/ { @[stringof(args[1]->pr_fname)] = sum(vtimestamp - self->last); self->last = 0; } sched:::wakeup /execname == "Xsun" && self->last == 0/ { self->last = vtimestamp; }
このスクリプトを実行すると、次のような出力が得られます。
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
この出力から、Xsun は、多くの作業を acroread、MozillaFirebird、fvwm2 のために行なっていることがわかります。ただし、fvwm2 の負荷はほかの 2 つほど大きくありません。条件変数同期オブジェクト (SOBJ_CV) からの呼び起こしだけが調べられている点に注目してください。表 25–4 で説明したように、条件変数は同期オブジェクトの一種であり、通常、共有データ領域へのアクセス以外の理由で同期化を行うときに使用されるものです。X サーバーの場合、クライアントは条件変数でスリープして、パイプ内のデータを待機します。
wakeup プローブとともに、追加で sleep プローブを使用すると、どのアプリケーションがどのアプリケーションでブロックされているのか、どのくらいの間ブロックされているのかを調べることができます。次の例を参照してください。
#pragma D option quiet sched:::sleep /!(curlwpsinfo->pr_flag & PR_ISSYS) && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { @[stringof(args[1]->pr_fname), execname] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } END { printa("%s sleeping on %s:\n%@d\n", @); }
このスクリプトをデスクトップシステム上で数秒間実行した場合、出力の末尾部分は次のようになります。
# dtrace -s ./whofor.d ^C ... xterm sleeping on Xsun: value -------------- Distribution ------------ count 131072 | 0 262144 | 12 524288 | 2 1048576 | 0 2097152 | 5 4194304 |@@@ 45 8388608 | 1 16777216 | 9 33554432 |@@@@@ 83 67108864 |@@@@@@@@@@@ 164 134217728 |@@@@@@@@@@ 147 268435456 |@@@@ 56 536870912 |@ 17 1073741824 | 9 2147483648 | 1 4294967296 | 3 8589934592 | 1 17179869184 | 0 fvwm2 sleeping on Xsun: value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@@@@@@@@@@@@@ 67 131072 |@@@@@ 16 262144 |@@ 6 524288 |@ 3 1048576 |@@@@@ 15 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 0 67108864 | 1 134217728 | 0 268435456 | 0 536870912 | 1 1073741824 | 1 2147483648 | 2 4294967296 | 2 8589934592 | 2 17179869184 | 0 34359738368 | 2 68719476736 | 0 syslogd sleeping on syslogd: value -------------- Distribution ------------ count 17179869184 | 0 34359738368 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 68719476736 | 0 MozillaFirebird sleeping on MozillaFirebird: value -------------- Distribution ------------ count 65536 | 0 131072 | 3 262144 |@@ 14 524288 | 0 1048576 |@@@ 18 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 1 67108864 | 3 134217728 |@ 7 268435456 |@@@@@@@@@@ 53 536870912 |@@@@@@@@@@@@@@ 78 1073741824 |@@@@ 25 2147483648 | 0 4294967296 | 0 8589934592 |@ 7 17179869184 | 0 |
MozillaFirebird がブロックする様子と、ブロックする理由について調べたいこともあります。この問いの答えを導き出すには、上のスクリプトを以下の例のように変更します。
#pragma D option quiet sched:::sleep /execname == "MozillaFirebird" && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "MozillaFirebird" && bedtime[args[0]->pr_addr]/ { @[args[1]->pr_pid, args[0]->pr_lwpid, pid, curlwpsinfo->pr_lwpid] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; } END { printa("%d/%d sleeping on %d/%d:\n%@d\n", @); }
このスクリプトを数秒間実行すると、次のような出力が得られます。
# dtrace -s ./firebird.d ^C 100459/1 sleeping on 100459/13: value -------------- Distribution ------------ count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 1048576 | 0 100459/13 sleeping on 100459/1: value -------------- Distribution ------------ count 16777216 | 0 33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 67108864 | 0 100459/1 sleeping on 100459/2: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@ 5 65536 |@ 2 131072 |@@@@@ 6 262144 | 1 524288 |@ 2 1048576 | 0 2097152 |@@ 3 4194304 |@@@@ 5 8388608 |@@@@@@@@ 9 16777216 |@@@@@ 6 33554432 |@@ 3 67108864 | 0 100459/1 sleeping on 100459/5: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@ 12 65536 |@@ 5 131072 |@@@@@@ 15 262144 | 1 524288 | 1 1048576 | 2 2097152 |@ 4 4194304 |@@@@@ 13 8388608 |@@@ 8 16777216 |@@@@@ 13 33554432 |@@ 6 67108864 |@@ 5 134217728 |@ 4 268435456 | 0 536870912 | 1 1073741824 | 0 100459/2 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@@@@@@@@@@ 11 65536 | 0 131072 |@@ 2 262144 | 0 524288 | 0 1048576 |@@@@ 3 2097152 |@ 1 4194304 |@@ 2 8388608 |@@ 2 16777216 |@ 1 33554432 |@@@@@@ 5 67108864 | 0 134217728 | 0 268435456 | 0 536870912 |@ 1 1073741824 |@ 1 2147483648 |@ 1 4294967296 | 0 100459/5 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 | 1 65536 | 2 131072 | 4 262144 | 7 524288 | 1 1048576 | 5 2097152 | 10 4194304 |@@@@@@ 77 8388608 |@@@@@@@@@@@@@@@@@@@@@@@ 270 16777216 |@@@ 43 33554432 |@ 20 67108864 |@ 14 134217728 | 5 268435456 | 2 536870912 | 1 1073741824 | 0 |
sleep プローブと wakeup プローブを使って、ネームサービスキャッシュデーモンなどの door サーバーのパフォーマンスを調べることもできます。次の例を参照してください。
sched:::sleep /curlwpsinfo->pr_stype == SOBJ_SHUTTLE/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "nscd" && bedtime[args[0]->pr_addr]/ { @[stringof(curpsinfo->pr_fname), stringof(args[1]->pr_fname)] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; }
このスクリプトを大規模メールサーバー上で実行した場合、出力の末尾部分は次のようになります。
imapd value -------------- Distribution ------------ count 16384 | 0 32768 | 2 65536 |@@@@@@@@@@@@@@@@@ 57 131072 |@@@@@@@@@@@ 37 262144 | 3 524288 |@@@ 11 1048576 |@@@ 10 2097152 |@@ 9 4194304 | 1 8388608 | 0 mountd value -------------- Distribution ------------ count 65536 | 0 131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 49 262144 |@@@ 6 524288 | 1 1048576 | 0 2097152 | 0 4194304 |@@@@ 7 8388608 |@ 3 16777216 | 0 sendmail value -------------- Distribution ------------ count 16384 | 0 32768 |@ 18 65536 |@@@@@@@@@@@@@@@@@ 205 131072 |@@@@@@@@@@@@@ 154 262144 |@ 23 524288 | 5 1048576 |@@@@ 50 2097152 | 7 4194304 | 5 8388608 | 2 16777216 | 0 automountd value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@ 22 131072 |@@@@@@@@@@@@@@@@@@@@@@@ 51 262144 |@@ 6 524288 | 1 1048576 | 0 2097152 | 2 4194304 | 2 8388608 | 1 16777216 | 1 33554432 | 1 67108864 | 0 134217728 | 0 268435456 | 1 536870912 | 0 |
automountd の異常なデータポイントや、1 ミリ秒超で持続している sendmail のデータポイントについて調べることもできます。上記のスクリプトに述語を追加して、例外的な (異常な) 結果の原因を絞り込むこともできます。