Advanced Oracle Troubleshooting Guide, Part 4 : 長時間パース問題の診断


http://blog.tanelpoder.com/2008/06/03/advanced-oracle-troubleshooting-guide-part-4-diagnosing-a-long-parsing-issue/
の翻訳です。

本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。

注意事項


  • 自動翻訳に手を加えたレベルの翻訳と理解してください
  • 意味をとりやすくするために追加した箇所については、《…》で囲っています。
  • 訳がわからない、または、自信がない箇所は★をつけています。


日本語訳：渡部 亮太 (WR at Csus4 dot net)

履歴


  • 2013-12-06: 初稿up

Advanced Oracle Troubleshooting Guide, Part 4 : 長時間パース問題の診断

2008年6月3日 by

特定のSQLを発行するとセッションがstuckする事象について、Oracleフォーラムに最近、スレッドがあった。ORDEREDヒントを使用していない限り、実行されたSQLは全く戻ってきませんでした。しかし、EXPLAIN PLANコマンド（文を解析するだけで、それを実行しない）さえも、戻ってきませんでした。

classicなSQLトレース+ tkprofのテクニックは《あまり情報を》提供しなかった（さほど時間をを消費しないいくつかの再帰的な問い合わせがあるだけ）

実績のあるV$SESSION_WAITのサンプリングテクニックは何も明らかにしなかった。
セッションが継続的にCPU上にあることを示した。（待ち状態が'WAITED KNOWN TIME'であることは、セッションがCPU上であることを意味している）そして、SEQ《列の値》は増加しなかった（これは、待機状態が時間の経過とともに変化しなかったことをを示す）。

上記の症状を示したため、私はこの問題のトラブルシューティングを行うために十分な準備をした。これはまさに、私のAdvanced Oracle Troubleshooting class でデモするトラブルシューティングのユースケースのまさに1つに思えます。（すてきな組み込み宣伝でしょ？）;)

トレースおよびV$ビューがセッションが何をしているかについての有益な情報を提供していないような場合には、私は通常、サーバプロセスの何回かのスタックトレースを調べる。今回のケースでは、私はスタックの取得を《スレッドの》投稿者に依頼し、結果は次のとおりだった。

21820: oracleXXXXXX (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
00000001021f5f58 kkosbn (ffffffff7ad79910, ff, ffffffff7ad96f58, ffffffff7ad96f58, 10000, ffffffff7ad96f58) + 2d8
00000001021eb278 kkobmp (ffffffff7ad790f0, 10000, ffffffff7ad73e18, 0, 0, ffffffff7ad797a0) + 4d8
00000001021ad348 kkotap (0, 0, 0, ffffffff7ad79910, ffffffff7ad73e18, ffffffff7ad790f0) + 4e8
000000010218fd4c kkojnp (382660a28, 0, ffffffff7ad790f0, 10218f160, 1065327d0, ffffffff7ad797a0) + bac
000000010218e828 kkocnp (106400, 200, ffffffff7ad790f0, 1, 0, 1065327d0) + e8
00000001021757a4 kkooqb (102174, 0, 3, 0, ffffffff7af15d00, ffffffff7ad790f0) + c04
0000000102165ac0 kkoqbc (0, ffffffff7af15d00, 0, 1065327d0, 6, 102165380) + 720
00000001022f3700 apakkoqb (ffffffff7fff6810, ffffffff7af15d00, 3843e26e0, 0, c200080, 0) + 80
00000001022f4110 apaqbd (ffffffff7fff6810, ffffffff7af15d00, 3843e26e0, ffffffff7ad7fd38, 381cbf738, 200000) + 170
00000001022f1014 apadrv (3843e26e0, 106532, ffffffff7af43f28, 106531b28, ffffffff7af15d00, 106532) + 294
0000000102529dc8 opitca (3, 3843e26e0, ffffffff7af43f28, 0, 1065327d0, 106525000) + 9c8
00000001019f1f8c kksFullTypeCheck (ffffffff7fff7b70, 1056d8c28, 106525898, ffeffc00, 1065253d8, 1056d8c18) + c
000000010034c894 rpiswu2 (0, 106525898, 0, ffffffff7fff72a8, 1056d8000, 106525) + 1f4
00000001019f8ca8 kksLoadChild (106400, ffffffff7fff7b70, ffffffff7af43f28, 106525898, ffffffff7fff91c0, 3843e26e0) + 22e8
00000001018f767c kxsGetRuntimeLock (0, 0, 180, 3834b2578, e9e733ed, 106525898) + 5bc
0000000101a18f24 kksfbc (106531, 0, 108, 0, 0, 382d0d758) + 3de4
0000000101a12618 kkspsc0 (1000, fffdffff, 0, 108, 10000000, 0) + 1838
0000000101a13844 kksParseCursor (ffffffff7fffa8b8, 3c305e100, 0, 0, ffffffff7af32260, 3) + e4
0000000102515d3c opiosq0 (1056d8c18, ffffffff7af32260, 1056d8, 20a, 1056d8000, 20b) + 85c
00000001024b1078 kpooprx (ffffffff7fffe07c, ffffffff7fffbec0, 106400, ffffffff7fffabd0, 0, 0) + d8
00000001024ad6d8 kpoal8 (ffffffff7fffbe88, 106528, a4, 8061, 1, 106532860) + 2b8
0000000100346ccc opiodr (1057687c0, 5e, 106525600, 1, ffffffff7af26738, 106528) + 60c
0000000103d74124 ttcpip (34, ffffffff7fffcb50, 1056beb2c, 1056bc310, 0, 106525718) + 504
0000000100341238 opitsk (106532868, 1, 0, 106532860, 105882f78, fffffffd) + 598
0000000100345888 opiino (106400, 106532860, 0, 40002801, 106400, 106532860) + 468
0000000100346ccc opiodr (1065319d8, 3c, 106400, 1065327e0, 106532, 106528) + 60c
000000010033f660 opidrv (106534f60, 0, 3c, 106531c98, 3c, 0) + 380
0000000100339c30 sou2o (ffffffff7ffff2a8, 3c, 4, ffffffff7ffff2d0, 105e0c000, 105e0c) + 50
00000001002fbf5c opimai_real (2, ffffffff7ffff3a8, 104050b4c, 1064cd848, 247cbfc, 14800) + 7c
00000001002fbe18 main (2, 8, 0, ffffffff7ffff3b8, ffffffff7ffff4c8, ffffffff7b500140) + 98
00000001002fbd3c _start (0, 0, 0, 0, 0, 0) + 17c

で、強調した関数（kksParseCursor）はこのプロセスが既に解析し始めていることを示します。
で、他の関数（kksLoadChild）は、ハード解析中であることを示している（ソフト解析は、ライブラリキャッシュに子カーソルをロードする必要がないので）。

さらにいくつか：


  • rpiswu関数は、ハード解析の再帰的処理のための、別々のランタイム実行コンテキスト（RPI = Recursive Program Interface）を初期化するものです

  • 上記のapa*関数も解析アクションを示す

  • kko*関数は、SQL問合せ変換、検証、および様々な他のチェックを行うものである

Oracle 10g以降では、V$SESS_TIME_MODELをサンプリングすることで、解析に費やしたセッションの実行時間を実際に測定できる。これは私のSnapperツールを使ってやっていることである：

SQL> @sn 10 106
 
-- Session Snapper v1.07 by Tanel Poder ( http://www.tanelpoder.com )
 
\---------------------------------------------------------------------------------------------------------------------------------------------
HEAD,     SID, SNAPSHOT START   ,  SECONDS, TYPE, STATISTIC                               ,         DELTA,  DELTA/SEC,     HDELTA, HDELTA/SEC
\---------------------------------------------------------------------------------------------------------------------------------------------
DATA,     106, 20080603 06:31:17,       10, TIME, hard parse elapsed time                 ,      10124018,    1012402,     10.12s,      1.01s
DATA,     106, 20080603 06:31:17,       10, TIME, parse time elapsed                      ,      10124018,    1012402,     10.12s,      1.01s
DATA,     106, 20080603 06:31:17,       10, TIME, DB CPU                                  ,      10113462,    1011346,     10.11s,      1.01s
DATA,     106, 20080603 06:31:17,       10, TIME, DB time                                 ,      10124018,    1012402,     10.12s,      1.01s
DATA,     106, 20080603 06:31:17,       10, WAIT, events in waitclass Other               ,            51,          5,       51us,      5.1us
--  End of snap 1
 
PL/SQL procedure successfully completed.
 

元の投稿者は、STATISTICS_LEVEL = BASICと設定していたので、これらの値はゼロだった。時間モデル統計を収集するためには、STATISTICS_LEVELをTYPICALまたはALLのいずれかに設定する必要がある。

???しかし、スタックトレースを読むことより楽しいです、そうじゃありませんか？;-)