Advanced Oracle Troubleshooting Guide, Part 5:WaitProfで本当に素早くV$ビューをサンプリング。SQLで!

Advanced Oracle Troubleshooting Guide, Part 5:WaitProfで本当に素早くV$ビューをサンプリング。SQLで!

 


http://blog.tanelpoder.com/2008/06/06/advanced-oracle-troubleshooting-guide-part-5-sampling-v-stuff-with-waitprof-really-fast-using-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!)

だから、私は自分自身でそのような目的のためのツールセットを開発しました。 Snappersw.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)をサンプリングするできるか、誰か説明できますか?;-)