Advanced Oracle Troubleshooting Guide, Part 5:WaitProfで本当に素早くV$ビューをサンプリング。SQLで!
本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳:渡部 亮太 (WR at Csus4 dot net)
履歴
- 2013-12-06: 初稿up
あなたは、私がダイレクトSGAアクセスについて書く、と思ったに違いない!;)
いいえ!
ダイレクトSGAアクセスは(あなたが、共有メモリデータ構造を知っている限り)優れたトラブルシューティングの可能性を秘めているが、それは一つの大きな欠点を持っています – ほとんどの企業における本番システムではそのようなツールが導入されていない。
私は、時折、 今まさに発生し、すぐに解決する必要がある、緊急のパフォーマンス上の問題を解決するために呼ばれたことがありました。そして、先に述べたように、これらは重要な本番システムであった。インターネットからダウンロードしたバイナリの実行可能ファイルをインストールすることはできない場所です。実際、本番環境へ必要な最小限の影響と変化にとどめて、問題を診断したいだろう。
(そして、それは同様に私のための最初のラウンドのトラブルシューティングツールをSQLトレースを残し!★and that leaves sql tracing out the first round troubleshooting tools for me as well!)
だから、私は自分自身でそのような目的のためのツールセットを開発しました。 Snapperとsw.sqlとすでにブログで紹介しているいくつかのプロセススタックを読むテクニック。
次の行にあるwaitprof.sqlは、(PL/SQLでなくて)普通のSQLで実装された高頻度のV$SESSION_WAITサンプラーです。
Waitprofは基本的にサンプリングセッション待機《イベント》プロファイラです。非常にタイトな《=短い》繰り返しの内でV$SESSION_WAITに対してSELECTを実行し、結果を集約するようなものだ – しかし、普通のSQLですべてこれを行うためのトリックを使用している。それによりPL/SQLベースのループよりもパフォーマンス上の利点を提供している。Waitprofは1つのセッションに対して毎秒最大100万回まで、V$SESSION_WAITをサンプリングできます!
これはもちろん、ハードウェアとOracleのバージョンに依存しますが、通常50-70kHzのサンプリングレートで取得します。
OK、例を見てみたい?;-)
セッション(SID = 142)でlotspios.sqlスクリプトを実行しましょう。名前の通り、多くの物理I/Oを発生させます。
SQL> @lotspios 100
さて、このセッションが時間をかけて何をしているか興味があるとしましょう??(CPU上にあるか、待機しているか、待機しているなら何を待機しているか)。そのために、そのセッションに対してwaitprof.sqlを実行します。構文は以下の通りです:
@waitprof
では、SID 142にwaitprofを実行しましょう。eventのみを収集対象とし、100000のサンプルを取得します。
SQL> @waitprof noprint 142 e 100000
-- WaitProf 1.03 by Tanel Poder ( http://www.tanelpoder.com )
% Total Total Event Distinct Avg time
SID STATE EVENT P1 Time Time ms Events ms/Event
\------- ------- ----------------------------------- -------------------------- ------- ------------ ---------- ----------
142 WAITING db file scattered read 39.75 580.306 721 .805
142 WAITING gc buffer busy 30.90 451.198 485 .930
142 WORKING On CPU / runqueue 17.42 254.347 1786 .142
142 WAITING read by other session 10.35 151.081 313 .483
142 WAITING db file sequential read 1.56 22.834 244 .094
142 WAITING latch: cache buffers chains .02 .234 9 .026
6 rows selected.
Elapsed: 00:00:01.48
%Total Time列から、そのセッションの統計情報をサンプリングしていた時間のほとんど(39.75パーセント)は、 db file scattered readイベントを待機していることがわかります。これはおよそ580ミリ秒を占めています。
Distinct Events列は、そのイベントの明確な発生回数を示していますので、1.48秒のサンプリング期間中に、db file scattered read で721回待機していた。この列は、V$SESSION_WAIT.SEQ番号に基づいていますので、短期間でかなり正確です。そして、Avg time ms/Event列は、1回の《待機》イベントの平均期間を示しています。この例では、db file scattered read は805マイクロ秒を要した。
これはwaitprofの最も簡単な使い方ですが、これは私がそれを書いた理由ではありません。これらの待機の詳細を知ってほしい!
what_to_sampleパラメータには、次の値の任意の組み合わせを受け入れることができます。
- e – サンプルイベント名(これは常に自動的に行われます)
- 1 – サンプルP1値
- 2 – サンプル値P2
- 3 – サンプル値P3
- s – サンプルSEQ#値
だから、すべての待機イベント?パラメータの詳細を取得するには、e1を指定してwaitprof実行できます。
SQL> @waitprof noprint 142 e1 100000
-- WaitProf 1.03 by Tanel Poder ( http://www.tanelpoder.com )
% Total Total Event Distinct Avg time
SID STATE EVENT P1 Time Time ms Events ms/Event
\------- ------- ----------------------------------- -------------------------- ------- ------------ ---------- ----------
142 WAITING db file scattered read file#= 6 49.07 814.496 1057 .771
142 WAITING gc buffer busy file#= 6 23.99 398.151 437 .911
142 WORKING On CPU / runqueue 20.38 338.358 1895 .179
142 WAITING read by other session file#= 6 5.72 94.985 210 .452
142 WAITING db file sequential read file#= 6 .83 13.712 159 .086
142 WAITING latch: cache buffers chains address= 422E843C .01 .083 1 .083
142 WAITING latch: cache buffers chains address= 41F8E900 .00 .066 1 .066
142 WAITING latch: cache buffers chains address= 437FCEC4 .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 4238EE2C .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 42342298 .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 41FBF44C .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 41FB4998 .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 41FACB6C .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 41F7D074 .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 00000006 .00 .017 1 .017
142 WAITING latch: cache buffers chains address= 41FA98F4 .00 .017 1 .017
16 rows selected.
Elapsed: 00:00:01.70
だから、今私は、待機イベントとそのP1の値で、待機プロファイルをブレイクダウンした。バッファ関連のイベントについては、すべてのI/Oがデータファイル6に対して起こったことがわかります。
ラッチ待機については、P1の値は、ラッチアドレスです。それは、V$LATCH_PARENTおよびV$LATCH_CHILDRENを使用して、このアドレスを実際のラッチ名(さらには個々の子ラッチに)変換できます。これは10g以前のデータベースでは特に便利です。
私は、このために、la.sqlスクリプトを書いた:
SQL> @la 422E843C
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SLEEPS WAIT_TIME
\-------- ---------- ------ ---------------------------------------- ---------- ---------- ---------- ---------- ---------- ----------
422E843C 122 1735 cache buffers chains 164637 64387 329 0 6 167
Waitprofは任意の組み合わせでwhat_to_sampleパラメータを使用することができます。
例えば、一度に読み取ったブロック数(P3)でscattered readsをブレークダウンしたい場合は、下のように、パラメータの「3」を使用することができますnoprintオプションを指定した場合、(《必要な》行幅を短くするため)P2、P3、およびSEQ#が表示されないこと、今はprintオプションを使用する必要があることに注意してください:
SQL> @waitprof print 142 e3 100000
-- WaitProf 1.03 by Tanel Poder ( http://www.tanelpoder.com )
% Total Total Event Distinct Avg time
SID STATE EVENT P1 P2 P3 SEQ# Time Time ms Events ms/Event
\------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
142 WORKING On CPU / runqueue 36.03 544.053 1211 .449
142 WAITING gc buffer busy id#= 65537 28.73 433.838 393 1.104
142 WAITING db file scattered read blocks= 16 22.39 338.149 270 1.252
142 WAITING read by other session class#= 1 7.61 114.866 340 .338
142 WAITING db file scattered read blocks= 13 1.16 17.546 20 .877
142 WAITING db file scattered read blocks= 12 1.03 15.568 16 .973
142 WAITING db file scattered read blocks= 14 .49 7.459 7 1.066
142 WAITING db file scattered read blocks= 11 .46 6.976 9 .775
142 WAITING db file scattered read blocks= 10 .36 5.361 7 .766
142 WAITING db file scattered read blocks= 8 .31 4.696 7 .671
142 WAITING db file sequential read blocks= 1 .27 4.077 47 .087
142 WAITING db file scattered read blocks= 9 .27 4.062 6 .677
142 WAITING db file scattered read blocks= 3 .16 2.341 11 .213
142 WAITING db file scattered read blocks= 2 .15 2.235 14 .160
142 WAITING db file scattered read blocks= 15 .15 2.235 2 1.117
142 WAITING db file scattered read blocks= 4 .13 1.933 6 .322
142 WAITING db file scattered read blocks= 6 .12 1.737 5 .347
142 WAITING db file scattered read blocks= 5 .10 1.495 4 .374
142 WAITING db file scattered read blocks= 7 .07 1.027 2 .513
142 WAITING read by other session class#= 65537 .01 .136 9 .015
142 WAITING gc buffer busy id#= 1 .01 .106 7 .015
142 WAITING latch: cache buffers chains tries= 0 .00 .045 2 .023
142 WAITING read by other session class#= 0 .00 .015 1 .015
142 WAITING db file sequential read blocks= 2 .00 .015 1 .015
142 WAITING gc buffer busy id#= 5 .00 .015 1 .015
142 WAITING db file scattered read blocks= 1 .00 .015 1 .015
26 rows selected.
Elapsed: 00:00:01.89
以上のことから、私たちは、I/O操作に関しては、サンプリング中の応答時間のほとんどは16/13/12ブロックの読み取りの際に使われたことがわかります。他の読み取りサイズには、ほとんど時間がかかっていません。
もちろん、WaitprofはP1、P2、P3のすべて列を表示することもできます。これはアクティブなセッションについて、多くの行が表示されることになるかもしれません。
SQL> @waitprof print 142 e123 100000
-- WaitProf 1.03 by Tanel Poder ( http://www.tanelpoder.com )
% Total Total Event Distinct Avg time
SID STATE EVENT P1 P2 P3 SEQ# Time Time ms Events ms/Event
\------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
142 WORKING On CPU / runqueue 21.63 424.007 1970 .215
142 WAITING db file scattered read file#= 1 block#= 43525 blocks= 16 .16 3.175 1 3.175
142 WAITING db file scattered read file#= 1 block#= 43541 blocks= 12 .13 2.587 1 2.587
142 WAITING db file scattered read file#= 1 block#= 43493 blocks= 16 .11 2.234 1 2.234
142 WAITING db file scattered read file#= 1 block#= 44167 blocks= 16 .10 2.019 1 2.019
142 WAITING db file scattered read file#= 1 block#= 55466 blocks= 16 .10 1.901 2 .951
142 WAITING db file scattered read file#= 1 block#= 44041 blocks= 16 .10 1.882 1 1.882
142 WAITING db file scattered read file#= 1 block#= 43877 blocks= 16 .09 1.705 1 1.705
142 WAITING db file scattered read file#= 1 block#= 44067 blocks= 16 .09 1.686 1 1.686
142 WAITING db file scattered read file#= 1 block#= 44103 blocks= 16 .08 1.646 1 1.646
142 WAITING db file scattered read file#= 1 block#= 44135 blocks= 16 .08 1.568 1 1.568
142 WAITING db file scattered read file#= 1 block#= 43597 blocks= 16 .08 1.509 1 1.509
142 WAITING db file scattered read file#= 1 block#= 8696 blocks= 16 .08 1.490 1 1.490
[...lots of lines snipped...]
142 WAITING db file sequential read file#= 1 block#= 35630 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 35634 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 35636 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 35638 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 35640 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 35644 blocks= 1 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 38097 blocks= 16 .00 .020 1 .020
142 WAITING db file sequential read file#= 1 block#= 43562 blocks= 1 .00 .020 1 .020
142 WAITING db file scattered read file#= 1 block#= 35529 blocks= 16 .00 .020 1 .020
1979 rows selected.
CPU使用率がリストの一番上にありますが、合計応答時間の21.63パーセントを占めるだけなので、残り78パーセントのI/O時間が、ここでは「問題」である。その理由は、ほとんどのイベントは、P1、P2、P3の値が違うため別々に出力されている一方で、すべてのCPU時間(《待機と》待機の間の時間)は1つに集約されるためである。《★上記のI/O待機時間が1%未満であるが、単に別々に出力されているだけで、実際は大きいよ。ということを言いたいのか》
時系列順にイベントを表示したい場合は、出力に(待ち状態のシーケンス識別子である)SEQ#を含めることができます。
SQL> @waitprof print 142 e123s 1000
-- WaitProf 1.03 by Tanel Poder ( http://www.tanelpoder.com )
% Total Total Event Distinct Avg time
SID STATE EVENT P1 P2 P3 SEQ# Time Time ms Events ms/Event
\------- ------- ----------------------------------- -------------------------- --------------- --------------- ---------- ------- ------------ ---------- ----------
142 WAITING db file scattered read file#= 6 block#= 43897 blocks= 13 26036 1.80 .360 1 .360
142 WORKING On CPU / runqueue 26036 2.40 .480 1 .480
142 WAITING db file scattered read file#= 6 block#= 44105 blocks= 13 26037 5.30 1.060 1 1.060
142 WORKING On CPU / runqueue 26037 1.40 .280 1 .280
142 WAITING db file scattered read file#= 6 block#= 44314 blocks= 12 26038 5.90 1.180 1 1.180
142 WORKING On CPU / runqueue 26038 1.70 .340 1 .340
142 WORKING On CPU / runqueue 26039 1.80 .360 1 .360
142 WAITING db file scattered read file#= 6 block#= 44534 blocks= 13 26039 6.40 1.280 1 1.280
142 WORKING On CPU / runqueue 26040 1.80 .360 1 .360
142 WAITING db file scattered read file#= 6 block#= 44742 blocks= 13 26040 6.20 1.240 1 1.240
142 WORKING On CPU / runqueue 26041 1.70 .340 1 .340
142 WAITING db file scattered read file#= 6 block#= 44950 blocks= 13 26041 6.00 1.200 1 1.200
142 WAITING db file scattered read file#= 6 block#= 45159 blocks= 12 26042 5.60 1.120 1 1.120
142 WORKING On CPU / runqueue 26042 2.10 .420 1 .420
142 WAITING db file scattered read file#= 6 block#= 45366 blocks= 13 26043 6.00 1.200 1 1.200
142 WORKING On CPU / runqueue 26043 1.70 .340 1 .340
142 WAITING db file scattered read file#= 6 block#= 45574 blocks= 13 26044 5.90 1.180 1 1.180
142 WORKING On CPU / runqueue 26044 1.80 .360 1 .360
142 WAITING db file scattered read file#= 6 block#= 45769 blocks= 13 26045 5.90 1.180 1 1.180
142 WORKING On CPU / runqueue 26045 1.60 .320 1 .320
142 WORKING On CPU / runqueue 26046 1.60 .320 1 .320
142 WAITING db file scattered read file#= 6 block#= 45978 blocks= 12 26046 5.50 1.100 1 1.100
142 WAITING db file scattered read file#= 6 block#= 46185 blocks= 13 26047 6.00 1.200 1 1.200
142 WORKING On CPU / runqueue 26047 1.80 .360 1 .360
142 WAITING db file scattered read file#= 6 block#= 46380 blocks= 13 26048 6.10 1.220 1 1.220
142 WORKING On CPU / runqueue 26048 1.70 .340 1 .340
142 WAITING db file scattered read file#= 6 block#= 46601 blocks= 13 26049 4.30 .860 1 .860
27 rows selected.
ここでは、SEQ# 番号の順に並べた、イベントの詳細な時系列のビューを見ることができる。SEQ#が65535に達した後ゼロに戻る、サンプリング粒度のため潜在的に逃したイベントがある、ようないくつかの落とし穴がある。これについての詳細は今後の記事で。ところで、スクリプトのヘッダから、そこに単一のSQLステートメントを読み取ることによって、スクリプトの使用方法に関する詳細を得ることができます:)
時系列の順序も、全ての待機パラメータも取得できる拡張SQLトレースを有効にすることができるのに、なぜこのようなサンプリングスクリプトを使用するのか尋ねられることがあります。一つの答えは、それがパフォーマンスの問題の初期段階の診断のためにスクリプトを使用する方が便利であるということです。もう1つの答えは時々、変更管理された本番環境においては、トレースを有効にするための変更を加えるために、かなりの時間がかかる可能性があることである。
今後の記事で、私は(very cool)この強力なサンプリング技術を使用方法を紹介します。ヒントはスクリプトがLatchprofと呼ばれているということです;-)
もしあなたが、他のAdvanced Oracle Troubleshootingの記事を読んでいない場合は、次のとおりです。
http://blog.tanelpoder.com/2007/06/18/advanced-oracle-troubleshooting-guide-when-the-wait-interface-is-not-enough-part-1/
http://blog.tanelpoder.com/2007/08/27/advanced-oracle-troubleshooting-guide-part-2-no-magic-is-needed-systematic-approach-will-do/
http://blog.tanelpoder.com/2007/09/06/advanced-oracle-troubleshooting-guide-part-3-more-adventures-in-process-stack/
http://blog.tanelpoder.com/2008/06/03/advanced-oracle-troubleshooting-guide-part-4-diagnosing-a-long-parsing-issue/
ところで、一度だけ、1つのSQL文を実行することで、どうやって私のスクリプトが何百、何千回と同じテーブル(V$SESSION_WAIT)をサンプリングするできるか、誰か説明できますか?;-)