悩ませ過ぎは及ばざるがごとし #3 Tweet
前回の続きだす。(まだGANTZ語が抜けてないw)
前回は状況証拠固めでした。
で、以下のような状況証拠は確認済み。
- 1回目だけ処理時間が異常に長い。
- 実行統計(consistent getsなど)から実行時のアクセスブロック数の差異はない。かつ、ブロック数も少ない。
- 物理読み込みは処理時間には影響していない。
という状況証拠を踏まえ、SQL文の処理フェーズを頭に浮かべて、順序よく考えていくと……
consitents getsの量や処理時間からexecutionフェーズ以降で時間を要しているわけではない……
また、
1回目だけ処理時間が長いが、物理読み込みが影響しているわけではない…
ということは、1回目だけ実行されるといえばハードパース……この部分の処理時間が長いってことですよね!
だんだん近づいてきましたね。というこで、次はパース時間が長いという証拠固めを。
パース時間を比較する方法はいくつかあります…。 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で整形するというおなじみのスタイル。
・1回目の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
・2回目の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です、しかも、3秒程度で結果を返してほしいらしいし…
で、どのようにしたらコストベースオプティマイザを"悩ませずに”済むか、そこが今回のポイント。
思い切って、ルールベースにしちゃおーか?。それはNG。確かにパース時間は短くなるでしょうけど…
解決方法を見つけるには問題のクエリがどんなものか見極める必要がありそうですね〜…。どんな方法があるだろー。
今日はここまで、次回へつづく。
ここまでのあらずじ
| 固定リンク
トラックバック
この記事のトラックバックURL:
http://app.cocolog-nifty.com/t/trackback/106341/52553173
この記事へのトラックバック一覧です: 悩ませ過ぎは及ばざるがごとし #3:
コメント