悩ませ過ぎは及ばざるがごとし #3 Tweet

前回の続きだす。（まだGANTZ語が抜けてないw)

前回は状況証拠固めでした。

で、以下のような状況証拠は確認済み。

• １回目だけ処理時間が異常に長い。
• 実行統計（consistent getsなど）から実行時のアクセスブロック数の差異はない。かつ、ブロック数も少ない。
• 物理読み込みは処理時間には影響していない。

という状況証拠を踏まえ、SQL文の処理フェーズを頭に浮かべて、順序よく考えていくと……

consitents getsの量や処理時間からexecutionフェーズ以降で時間を要しているわけではない……
また、
１回目だけ処理時間が長いが、物理読み込みが影響しているわけではない…

ということは、１回目だけ実行されるといえばハードパース……この部分の処理時間が長いってことですよね！

だんだん近づいてきましたね。というこで、次はパース時間が長いという証拠固めを。

パース時間を比較する方法はいくつかあります…。　SQL*Plusのset autot trace exp を使って実行計画だけを確認する方法とか、Explain plan文使うとか、SQLトレースを取るとか。
ようするに、パース時間が確認できる方法であればどんな方法でもOKなんです。

今回は結果の比較もしやすい、SQLトレースで証拠固をしてみます。SQLトレースを取得する方法はdbms_monitorパッケージを利用する方法が簡単ですかね。（他にもありますが）

SCOTT> exec dbms_monitor.session_trace_enable(null,null,true,false,'ALL_EXECUTIONS');

PL/SQLプロシージャが正常に完了しました。

SCOTT> SELECT 

・・・中略・・・

5999行が選択されました。

経過: 00:00:48.37

SCOTT> exec dbms_monitor.session_trace_disable(null,null);

PL/SQLプロシージャが正常に完了しました。

こんな感じでセッション単位でSQLトレースを取得してtkprofで整形するというおなじみのスタイル。

・１回目のSQLトレース

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     45.18      45.15          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      401      0.04       0.05          0       1897          0        5999
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      403     45.23      45.21          0       1897          0        5999

・２回目のSQLトレース

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      401      0.04       0.04          0       1897          0        5999
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      403      0.04       0.04          0       1897          0        5999

予想的中！。　パースに時間を要しているのは明らかですね。

最近のコストベースオプティマイザは賢いです。賢いのでいろいろと考えさせすぎると時間がかかります。（将棋でも相手の手数を読み過ぎなんて…ことありますよね。そんな状況に近いです。）。DWH系のクエリならそんなこともあるでしょうけど、今回問題になっているのはOLTPです、しかも、３秒程度で結果を返してほしいらしいし…

で、どのようにしたらコストベースオプティマイザを"悩ませずに”済むか、そこが今回のポイント。

思い切って、ルールベースにしちゃおーか？。それはNG。確かにパース時間は短くなるでしょうけど…

解決方法を見つけるには問題のクエリがどんなものか見極める必要がありそうですね〜…。どんな方法があるだろー。

今日はここまで、次回へつづく。

---

ここまでのあらずじ

・悩ませ過ぎは及ばざるがごとし #1
・悩ませ過ぎは及ばざるがごとし #2