WR blog

about Enterprise IT, Oracle Database, Jazz/Fusion Music, etc…

WR blog RSS Feed
 
 
 
 

Advanced Oracle Troubleshooting Guide - Part 10: インデックスユニークスキャンがマルチブロック読み込み?

 

Advanced Oracle Troubleshooting Guide - Part 10: インデックスユニークスキャンがマルチブロック読み込み?

Oracle(パフォーマンス)の問題のトラブルシューティングを行う際には、通常、問題のセッションが何を(間違って)やっているか、そして、 なぜそれをやっているのかを知りたい。

「何を」という質問には、いくつかのwait interfaceベースの方法を使用して大抵回答できます。ASHやSQL*Traceは、純粋な待機イベント·データに対して多くの詳細を追加してくれます。

私の通常のセッションのトラブルシューティングデータの収集シーケンスは、わずか3ステップで構成されます。

  1. セッションレベルの上位waitと、上位SQLデータを解釈します(ASH、SQL*TraceまたはセッションレベルのV$ビューをサンプリングするカスタムツール)
  2. セッションレベルのパフォーマンスカウンターデータ( V$SESSTAT )を解釈します。
  3. 問題のあるプロセススタックをサンプリングし、実行が最も時間を費やした一番上のスタックのブランチをまとめます。

問題症例の90%において、#1だけで十分です。しかし、複雑でエキゾチックな問題の高度なトラブルシューティングのために、私は定期的に#2に飛び込む必要があります。- V$SESSTATパフォーマンスカウンタ(それは私が例えばスナッパーを書いた理由です)  

#3に飛び込むのは、40から50のトラブルシューティングの例のうちおそらく1つだけです。 - プロセススタックのサンプリング 。しかしながら、プロセススタックのサンプリングは嘘をつかない。セッション/プロセスが何をしているかについて、Oracleのinstrumentation自体が手掛かりを与えないような場合に特に役立ちます。- 顕微鏡のようなものです。それはあなたの問題の一部分について非常に詳細な概要を与えます。全体像ではありません。これが、トラブルシューティングのとき、私が#3から開始しない理由です。(もし、あなたがそうしているなら、それは間違っています。完全にハングしたデータベースを除いては;) )私はいつも#1から開始し、必要なときに#2のみに進む

ところで、Snapperはプロセスの#1と#2の両方のデータを一覧表示します。

ともあれ、私はこの記事を書いている理由は、数日前、ステップ#1が問題の存在を示し、ステップ#2がなぜ それが起こっているかを説明する綺麗な例がある問題についての質問を受けたからです。

古いサーバーに比べると、新しいサーバー上で若干遅く走った実行計画がありました とのみ《古いサーバーでは》1実行ごとに5ブロックだけ読みだしていたのに対して、36ブロックを読み出していました。

select ...
from TABLE_X
where ...
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.07         36          5          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.02       0.09         36          5          0           1
 

上記の「disk」列は、物理I/O経由で読み込まれている36のブロックを示しています。- 一方、唯一の5のバッファがその後に実際にアクセスされていた(論理I/Oは「query」欄に示されている) -

今となっては奇妙なことだ - 論理I/Oは物理的なI/Oを引き起こすものであるため、論理I/O数通常、物理I/Oの数以上でなければならないだから。

より奇妙なことに、実行計画は索引一意スキャンされている:

 
  
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID TABLE_X (cr=5 pr=36 pw=0 time=0 us cost=4 size=26 card=1)
      1   INDEX UNIQUE SCAN TABLE_X_IDX (cr=4 pr=35 pw=0 time=0 us cost=3 size=0 card=1)(object id 51063)
  

・・・しかし、あなたは「blocks read via physical read」を意味する、 "pr="列の中に見てみると、36ブロックのうち35ブロックがINDEX UNIQUE SCAN行ソース(pr=35)で読み込まれたことがわかります。これらのカウンタは累積されますので、pr=36は 親の TABLE ACCESS BY INDEX ROWID 行ソースにおいては、表アクセス·レベルでの物理的な入出力により読み取られた1ブロックだけであることを意味します。では、なぜインデックスアクセスは、35ブロックを読み込むのでしょうか?

それは、インデックスの高さでしょうか?それは不可能です。- インデックスの最大の高さは24レベルです (リーフレベルを含む)。そして、このようなインデックスはとにかくとんでもないだろう :)

waitプロファイルを見てみましょう:

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        4        0.00          0.00
  db file sequential read                         4        0.01          0.04
  db file scattered read                          1        0.03          0.03
  SQL*Net message from client                     2        0.15          0.15


Wow、単一のブロック読み込みを伴って索引ツリーをトラバースすると想定されるインデックス一意スキャンが、4つのシングルブロック読み取りと1つのマルチブロック読み取りを行っていた!

さて、これは待機インタフェースとASHスタイルのデータではこれ以上役立たない状況です。我々は何が起こっているか知っている - 「《本来》すべきでない」マルチブロック読み取りが、ここでは起こっている。なぜ、これが起こっているかは、われわれはまだ知らない。私たちは、ここから推測しなければならない。ここが V$SESSTATの出番です。 - 各々のセッションについて、6​​00以上のパフォーマンスカウンタが用意《maintain》されています。それらの多くがRDBMSカーネルが、どんなオペレーションを(そしてどれだけ)したかに関する貴重な情報を表示します。ですので、私は、クライアントにテストセッションでSnapperを実行してもらえるよう頼みました。これがその出力です(下の出力は、クエリがループ内で何度も実行されたところの、異なるテスト実行からのものであることに注意してください)​​。

 
----------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------------------------
   1612, ORACLE    , STAT, opened cursors cumulative                                 ,          6617,      1.32k,
   1612, ORACLE    , STAT, user calls                                                ,         13234,      2.65k,
   1612, ORACLE    , STAT, pinned cursors current                                    ,            -1,        -.2,
   1612, ORACLE    , STAT, session logical reads                                     ,          5293,      1.06k,
   1612, ORACLE    , STAT, CPU used when call started                                ,             7,        1.4,
   1612, ORACLE    , STAT, CPU used by this session                                  ,             7,        1.4,
   1612, ORACLE    , STAT, DB time                                                   ,           306,       61.2,
   1612, ORACLE    , STAT, user I/O wait time                                        ,           223,       44.6,
   1612, ORACLE    , STAT, non-idle wait time                                        ,           224,       44.8,
   1612, ORACLE    , STAT, non-idle wait count                                       ,          6775,      1.36k,
   1612, ORACLE    , STAT, process last non-idle time                                ,             5,          1,
   1612, ORACLE    , STAT, physical read total IO requests                           ,           158,       31.6,
   1612, ORACLE    , STAT, physical read total multi block requests                  ,            31,        6.2,
   1612, ORACLE    , STAT, physical read total bytes                                 ,       8265728,      1.65M,
   1612, ORACLE    , STAT, cell physical IO interconnect bytes                       ,       8265728,      1.65M,
   1612, ORACLE    , STAT, consistent gets                                           ,          5293,      1.06k,
   1612, ORACLE    , STAT, consistent gets from cache                                ,          5293,      1.06k,
   1612, ORACLE    , STAT, consistent gets - examination                             ,          5293,      1.06k,
   1612, ORACLE    , STAT, physical reads                                            ,          1009,      201.8,
   1612, ORACLE    , STAT, physical reads cache                                      ,          1009,      201.8,
   1612, ORACLE    , STAT, physical read IO requests                                 ,           158,       31.6,
   1612, ORACLE    , STAT, physical read bytes                                       ,       8265728,      1.65M,
   1612, ORACLE    , STAT, free buffer requested                                     ,          1008,      201.6,
   1612, ORACLE    , STAT, physical reads cache prefetch                             ,           851,      170.2,
   1612, ORACLE    , STAT, physical reads prefetch warmup                            ,           851,      170.2,
   1612, ORACLE    , STAT, shared hash latch upgrades - no wait                      ,           188,       37.6,
   1612, ORACLE    , STAT, calls to get snapshot scn: kcmgss                         ,          1319,      263.8,
   1612, ORACLE    , STAT, file io service time                                      ,            25,          5,
   1612, ORACLE    , STAT, file io wait time                                         ,       2219641,    443.93k,
   1612, ORACLE    , STAT, min active SCN optimization applied on CR                 ,             1,         .2,
   1612, ORACLE    , STAT, index fetch by key                                        ,          1292,      258.4,
   1612, ORACLE    , STAT, session cursor cache hits                                 ,          6440,      1.29k,
   1612, ORACLE    , STAT, buffer is not pinned count                                ,          1277,      255.4,
   1612, ORACLE    , STAT, parse time elapsed                                        ,             6,        1.2,
   1612, ORACLE    , STAT, parse count (total)                                       ,          6380,      1.28k,
   1612, ORACLE    , STAT, execute count                                             ,          6378,      1.28k,
   1612, ORACLE    , STAT, bytes sent via SQL*Net to client                          ,       2195633,    439.13k,
   1612, ORACLE    , STAT, bytes received via SQL*Net from client                    ,       2721339,    544.27k,
   1612, ORACLE    , STAT, SQL*Net roundtrips to/from client                         ,          6374,      1.27k,
   1612, ORACLE    , TIME, parse time elapsed                                        ,        114215,    22.84ms,     2.3%, |@         |
   1612, ORACLE    , TIME, PL/SQL execution elapsed time                             ,         67004,     13.4ms,     1.3%, |@         |
   1612, ORACLE    , TIME, DB CPU                                                    ,        630000,      126ms,    12.6%, |@@        |
   1612, ORACLE    , TIME, sql execute elapsed time                                  ,       2595410,   519.08ms,    51.9%, |@@@@@@    |
   1612, ORACLE    , TIME, DB time                                                   ,       3190919,   638.18ms,    63.8%, |@@@@@@@   |
   1612, ORACLE    , WAIT, db file sequential read                                   ,        978601,   195.72ms,    19.6%, |@@        |
   1612, ORACLE    , WAIT, db file scattered read                                    ,       1213550,   242.71ms,    24.3%, |@@@       |
   1612, ORACLE    , WAIT, SQL*Net message to client                                 ,          9212,     1.84ms,      .2%, |          |
   1612, ORACLE    , WAIT, SQL*Net message from client                               ,       1667368,   333.47ms,    33.3%, |@@@@      |
--  End of Stats snap 1, end=2012-03-09 14:47:02, seconds=5
 

メトリック値が表示されない場合は、右にスクロールして上記のハイライトされた行を参照してください…

  • physical read total multi block requests統計は、実際にいくつかのマルチブロックが監視セッションで行わ読み込みがあったことが確認します。
  • physical read total multi block requestsメトリックは、データ·ブロック·プリフェッチがあったことを示します!これは、実際にはシングルブロック読み込みが必要なところで、マルチブロック読み込みが行なわれた理由を説明している。
  • そして、physical reads prefetch warmupメトリックは、くプリフェッチをした理由 を説明しています。 - それは、バッファキャッシュのウォームアップのためだ。再起動または大きなバッファ·キャッシュ·サイズの増加の後、Oracleは可能な限り高速に任意のデータで空のバッファキャッシュを満たすことを決定したところの★。Oracleは、とにかく、ランダムマルチブロック読み込みは、ランダム単一ブロックよりも多くの時間を取らないと仮定する。このため、インデックスアクセスで読みたかったシングルブロックの周辺から、追加のブロックの束を読み出さない★。この読み出し動作は少し遅くなりますが、それらがすでにキャッシュ内にあるとき、複数の将来のシングルブロック読み取りを避けるために役立つかもしれない。これは、インスタンスを再起動するか、大幅にバッファ·キャッシュ·サイズを大きくした場合にのみ物事に影響を与えなければならない。だから、定常状態にある本番システム上であなたがそれを見るべきではありません(and it’s for a good cause anyway)。しかし、テスト·データベースでパフォーマンステストを行い、何かを変更して、インスタンスを再起動《bounce》し、すぐにテストを実行するならば - これは試験結果に影響を与える可能性があります。ところで、この動作は隠しパラメータ_db_cache_pre_warmによって制御されています。私は単に教育目的のため、このパラメータに言及しています。私は、このパラメータを変更することで問題を修正したことがありません :)。だから、サンドボックスハッキングデータベースでのみそれに触れる必要があります。

では、元のトピックに戻りましょう。 - この記事は、この特定のprewarm機能についてはのモノではありませんでした。そうではなくて、V$SESSTATメトリックが、通常の待機インタフェースとTOP-SQLベースのアプローチよりもはるかに多くを、 あなたにどうやって教えてくれるのかについての1つの例です。オラクルからこれらの詳細なメトリックを取得するために、何かのトレースや、undocumentedなイベントを有効にする必要はありません。ちょうどその時にV$SESSIONビューを、単に問い合わせてください。最初に言ったように、より高いレベルのビューが十分役に立たないときでないと、私は微視的なビューにジャンプしません。だから、そのheckなセッションが何をやっているのか、なぜやっているのかを診断しようとするとき、私は3ステップのAdvanced Oracle Troubleshootingメソッドにに従うことをお勧めします。;^)

Profile

渡部亮太 / Watabe Ryota
代官山在住のOracle Database Engineer。 株式会社コーソル所属。講演/講師業もぼちぼち。書籍「プロとしてのOracle運用管理入門」「プロとしてのOracleアーキテクチャ入門」買ってくれるとうれしいなっと。 twitter:wrcsus4

Book



Other Works

Certifications

  • Oracle Master 10g Platinum
  • Oracle Master 11g Gold
  • Oracle Master Silver Oracle PL/SQL Developer
  • Oracle Master Expert 10g RAC
  • Oracle Master Expert Oracle on Linux
  • LPIC level2
  • CCNA
  • 日商簿記3級

Contact

wrcsus4 _at_ gmail _dot_ com

Archives

Recent Posts

Recent Comments

Categories

Tags

Meta