本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。
注意事項
- 自動翻訳に手を加えたレベルの翻訳と理解してください
- 意味をとりやすくするために追加した箇所については、《…》で囲っています。
- 訳がわからない、または、自信がない箇所は★をつけています。
日本語訳:渡部 亮太 (WR at Csus4 dot net)
履歴
- 2013-12-11: 初稿up
Advanced Oracle Troubleshooting Guide, Part 6:os_explainを使用してOracleの実行計画を理解する
Oracleプロセス?スタックへのさらなる冒険の準備をしなさい!
でも先に進む前に、別のスタック?サンプリング?アプローチの安全性についてのこの記事を読んでください。
実行計画において現在実行している箇所がどこかを正確に知りたいと思うような、クエリ《実行》がハングアップし、パフォーマンス悪化することに関連する、non-trivialなOracleトラブル事例に出くわしたことがある。
覚えてほしい。Oracleは、単にサーバー上で、関数内のクラスタ化された命令を実行するだけのプログラムであるので、スタックサンプリングが役に立つ。
だから、この実行計画でSQLを実行しているSolaris SPARCのOracle 10.1データベースから取得した次のスタックトレースを調査していた。
$ cat pstack.txt
\------------------------------------------------------------------------
0000000101eca6e4 kdirfrs (ffffffff78eca5d8, 1, 0, 2, 86521ee00, 0) + 24
0000000102502adc qerixFetchFastFullScan (ffffffff78eca3e0, 10248ebc0, 0, 1, 86521ebf8, fffd) + 33c
0000000102558720 qergiFetch (ffffffff78ecaca8, 10248ebc0, ffffffff7fff5ee8, 10449dba0, 1, 86bb6bb38) + 80
000000010248edd8 qerjoFetch (45, 10248ebc0, ffffffff7fff5ee8, ffffffff78ecad60, 86bb6bc08, 114) + 118
000000010248eeb8 qerjoFetch (7ffe, 10248ebc0, ffffffff7fff5fe8, ffffffff78ecb5e8, 7f399b6f8, 7ffe) + 1f8
00000001025171b8 rwsfcd (8177747a8, 10248e1e0, ffffffff7fff6168, 7fff, f0, 10449dba0) + 78
000000010248e4dc qeruaFetch (745c0ab40, 10248e1e0, ffffffff7fff6168, ffffffff78ecb620, 10449dba8, 8177747a8) + 11c
000000010248d840 qervwFetch (1d, 1d, ffffffff7fff6238, 7fff, 7cfc87c50, 10449d000) + a0
00000001025171b8 rwsfcd (7876e8d18, 10248e1e0, ffffffff7fff63b8, 7fff, c0, 10449dba0) + 78
000000010248e4dc qeruaFetch (817d1e438, 10248e1e0, ffffffff7fff63b8, ffffffff78e7d318, 10449dba8, 7876e8d18) + 11c
000000010248d840 qervwFetch (1d, 1d, ffffffff7fff6488, 7fff, 82355a348, 10449d000) + a0
00000001025171b8 rwsfcd (7454b0408, 10249e4e0, ffffffff7fff6608, 7fff, c0, 10449dba0) + 78
00000001024a4620 qerhjFetch (86b1d64d8, 0, 0, 1, ffffffff78e7df08, 0) + 300
000000010248f99c qerjotFetch (78d8ea1d8, 0, 0, 1, ffffffff78e7e8d0, 10449dba0) + dc
000000010248eeb8 qerjoFetch (1, 10248ebc0, ffffffff7fff6838, ffffffff78e7f2b0, 7d53bb730, 1) + 1f8
000000010248eeb8 qerjoFetch (1, 10248ebc0, ffffffff7fff6938, ffffffff7b9b2f78, 74b306ba0, 7fff) + 1f8
000000010248d840 qervwFetch (5, 5, ffffffff7fff6a08, 7fff, 80b0faa18, 10449d000) + a0
00000001025171b8 rwsfcd (865e988f8, 10249e4e0, ffffffff7fff6b88, 7fff, c0, 10449dba0) + 78
00000001024a4620 qerhjFetch (7a57ae350, 10249e4e0, ffffffff7fff6d88, 1, ffffffff7bb89f00, 0) + 300
00000001025171b8 rwsfcd (823642298, 10249e4e0, ffffffff7fff6d88, 7fff, 6f0, 10449dba0) + 78
00000001024a4620 qerhjFetch (751158588, 102517980, 7511587f0, 1, ffffffff7b9b5090, 0) + 300
000000010251d1f0 qersoFetch (94, 10506adf8, 10449d000, ffffffff7b9b53b8, 799854d60, 7511587f0) + 350
0000000101aa6f24 opifch2 (7, f, 150, 1, 104400, 1050685e8) + a64
0000000101aa6384 opifch (5, 2, ffffffff7fff79f8, 105000, 0, 10434c0a8) + 44
0000000101ad81ec opipls (104000, 10434c, 1, ffffffff7bba3e6a, 0, 140010) + f4c
00000001002d0058 opiodr (6, 10506ae10, 10434cfb0, 10506a, 105000, 104000) + 598
00000001002d4ec0 rpidrus (ffffffff7fff8820, 105067f18, 105068860, ffffffff7bb5f560, 4a8c, 200000) + a0
0000000102f615e4 skgmstack (ffffffff7fff8a48, ffffffff7f87cf8f, ffffffff7fff898f, 1002d4e20, ffffffff7fff8a70, acc01800) + a4
00000001002d504c rpidru (ffffffff7fff9140, 10422b000, 10422a918, 104229598, 410, 82) + ac
00000001002d4808 rpiswu2 (0, 104556000, ffffffff7fff8b88, 2, 104556418, ffffffff7fff92c0) + 1a8
00000001002d61cc rpidrv (a, ffffffff7fff9044, 9, ffffffff7fff90c0, ffffffff7fff9140, 1002d5180) + 62c
0000000102797f90 psddr0 (104400, 86e2fc628, ffffffff7fff92c0, 9, 1050769d8, 1050769d8) + 1f0
0000000102798e04 psdnal (ffffffff7fffa0b8, ffffffff7fffa258, 105000, ffffffff7bc5eb00, 7f7aa86d0, 40) + 184
000000010376d268 pevm_BFTCHC (0, 7f7aa86d0, 50, ffffffff7bb5f560, ffffffff7bc5eb00, 0) + 188
000000010373dff4 pfrinstr_FTCHC (10, 15d0000000000000, ffffffff7bb5f5c8, ffffffff7bb5f560, 4a8c, ffffffff7bb66330) + b4
00000001037362c8 pfrrun_no_tool (ffffffff7bb5f560, 779953684, ffffffff7bb5f5c8, 10457c9d8, 2001, 2001) + 48
00000001037372d0 pfrrun (ffffffff7bb5f5c8, 200000, 0, 200000, ffffffff7bb5f560, 779abb110) + 2f0
0000000103783374 plsql_run (ffffffff7bb55408, 1, 0, ffffdfff, ffffffff7fffa0b8, 0) + 274
0000000103722554 peicnt (ffffffff7fffa0b8, 105068860, 6, ffffffff7fff9f28, 41d8, 1050685e8) + d4
000000010327b784 kkxexe (105000, 104000, 105068, 104296000, 1050685e8, ffffffff7bb5f560) + 284
0000000101ad0228 opiexe (4, ffffffff7bc68ee8, ffffffff7fffab00, 0, 0, ffffffff7bc70480) + 33c8
0000000101a4c0a8 kpoal8 (40008, 1, ffffffff7fffd890, 0, 0, 4) + 648
00000001002d0058 opiodr (14, 10506ae10, 10434ce70, 10506a, 105000, 104000) + 598
0000000102cded94 ttcpip (105071450, 18, ffffffff7fffd890, ffffffff7fffcb88, 104229c98, ffffffff7fffcb84) + 694
00000001002cd3e8 opitsk (1002cf000, 1, 0, ffffffff7fffd9e8, 105071450, 105071458) + 428
0000000101aaf564 opiino (105070000, 1050683c0, 0, 0, f5, 105070290) + 404
00000001002d0058 opiodr (4, 10506ae10, 10434c920, 10000, 105071, 105000) + 598
00000001002cc174 opidrv (0, 4, 10506a, 105071450, 0, 3c) + 354
00000001002c9828 sou2o (ffffffff7fffe6b8, 3c, 4, ffffffff7fffe698, 104aa6000, 104aa6) + 48
00000001002a7b34 main (2, ffffffff7fffe798, ffffffff7fffe7b0, 0, 0, 100000000) + 94
00000001002a7a7c _start (0, 0, 0, 0, 0, 0) + 17c
そんなに元気づけられないよね? ★Not too encouraging, huh?
では、このスタックトレースをos_explainスクリプトを通して実行してみましょう:
$ ./os_explain pstack.txt
SELECT FETCH:
SORT: Fetch
HASH JOIN: Fetch
* HASH JOIN: Fetch
* VIEW: Fetch
NESTED LOOP OUTER: Fetch
NESTED LOOP OUTER: Fetch
NESTED LOOP JOIN: Fetch
HASH JOIN: Fetch
* VIEW: Fetch
UNION-ALL: Fetch
* VIEW: Fetch
UNION-ALL: Fetch
* NESTED LOOP OUTER: Fetch
NESTED LOOP OUTER: Fetch
GRANULE ITERATOR: Fetch
INDEX: FetchFastFullScan
kdirfrs
さて、これははるかに理解しやすいです!
私のスクリプトが行うことは
- 実行計画に関連していないスタックの下の部分を削除する
- 人間がより読みやすくするため、スタックトレースの行の順序を逆にする
- metalink(MOS) note 175982.1で提供されている情報を使用して、Query Execution Rowsource(qer)関数の接頭辞を対応する名前に変換する
簡単に:)
で、どうやってこれを読むべきか?
まず、今までで明らかになっているべきことだが、Oracleにおいて、(SQL実行計画において異なる行として表示される)おのおのの行ソース演算子は、実際にはOracleカーネル内部の単なる関数である。これらは「qer」で始まる行ソース関数です。私の知る限り、QERはQuery Execution Rowsource(クエリ実行行ソース)の略です。
Oracleプロセスがカーソルからデータをフェッチするときはいつでも、opifch2()を呼び出します。which in turn 実行計画におけるルートの行ソース関数を呼び出す★。私の場合、その関数はqersoFetchであり、os_explainスクリプトによって「qerso」の部分がSORTと置換された(上記のメタリンクノートの通り)。qersoFetchの最初の子の関数はqerhjFetchでした。それは、ハッシュ結合の行ソースです。os_explainが、いくつかの行にアスタリスク(*)を前置きしていることに注意してください。
これは、与えられた関数の出力は、フィルタ操作によってフィルタリングされていることを示します(DBMS_XPLANによりexplainされた実行計画の一番下に通常表示される内容と同じフィルター演算です)。
ですから、論理的には、Oracleの機能のツリーとして実行計画をイメージすることができます。
- SELECTクエリについては、OPIフェッチ関数(opifch2)がルートになるでしょう。
- qerhjFetch(ハッシュ結合)とqerjotFetch(ネスト?ループ?ジョイン)のような様々なJOINとUNIONの関数が枝になるでしょう。
- 葉は、常にqertbFetch(表アクセスFULL)またはqerixFetch(索引の一意/ FULL /レンジ?スキャン)のような、ある種のアクセスパス関数になるでしょう。
しかし、物理的には、実行計画は子カーソルのsubheap 6(x$kglcursor.kglobhd6)というメモリ構造にすぎない。そして、その中に行ソース関数のオペコード★の束を持っている。
プランの実行中に、Oracleプロセスは、 "ただ"、それらのオペコードを通じてトラバースし、ルックアップテーブルを用いて、対応する行ソース関数の開始アドレスを検索し、それを呼び出します。その関数は、その処理を実行し(おそらく再帰的に他の行ソース関数を呼び出し)、呼び出し元に戻ります。
多くの行ソース関数は、カスケード接続されるように設計されていることに注意してください。それれは、全体の結果セットとは対照的に《結果セット全体を返すのではなくて》、行の小さなサブセットを返すために必要なだけの仕事をして、一度に少数の行だけを返すことができる。
行がカスケード接続、または、行が利用可能になったときに、親の関数に戻すパイプライン化できるのは非常に良いことです。たとえば、テーブルフェッチは一度に(テーブル全体のではなく)一部の行を取得し、更なる処理のために「上に」返します。また、ネステッドループ結合は、一致《する行が》最初に検出された瞬間から、「上に」一致する行を渡すことができます。最初の行を返す前に、完全なデータセットに対してJOINを実行する必要はありません。
また、このことは、それ《結果セット》を親関数に渡す前に、メモリ内のどこかに、中間結果セット全体を保存する必要がないことを意味します。その代わりに、より多くの行が必要なときはいつでも、実行計画ツリーの枝を再度訪れます《枝に対応する関数を実行します》。そして、os_explainスクリプトは、現在どの実行ブランチが実行されているかを正確に示します 。
補足:今後の記事でスタックトレースを実行計画に合致する方法について詳しく説明する予定です – それは、導入記事としては《扱うべき》マテリアルがあまりにも多い。
だから、カスケード接続された行ソースは、メモリに中間結果セットを保持する必要なく、大規模なデータセットを含む《実行》計画を、「段階的に」実行することができます。一方で、SORTのような、実行計画のいくつかの行ソース演算子は、そのすべての子の行が処理される前に、すべての行を返すことはできません。SORT(および、SORTを使用する集約操作)を使用すると、意味のある結果を返す前に、すべてのソース行を処理する必要があります。残りの行が並び替えの最初として返されていないことを期待して、ソースデータの半分だけを調べて、それを並び替え、行を返し開始することはできません。★SQLカーソル作業領域は、このような操作のために現れる場所です。
他の行ソースはできませんが、SORT、HASHとBITMAP行ソースは、そのためのSQL作業領域を割り当てることができます。次のサンプルクエリの実行計画の統計情報から、簡単に特定できます。
SQL> select /*+ gather_plan_statistics */ owner, count(*) from dba_source group by owner; OWNER COUNT(*) \------------------------------ ---------- WKSYS 8988 HR 34 [...some output snipped...] SYS 129299 WMSYS 704 25 rows selected. SQL> select * from table(dbms_xplan.display_cursor(null,null,'MEMSTATS LAST')); PLAN_TABLE_OUTPUT \---------------------------------------------------------------------------------------------------------------------------------- SQL_ID dcp37kxt02m9f, child number 0 \------------------------------------- select /*+ gather_plan_statistics */ owner, count(*) from dba_source group by owner Plan hash value: 114136443 \---------------------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | OMem | 1Mem | Used-Mem | \---------------------------------------------------------------------------------------------------------------------------- | 1 | HASH GROUP BY | | 1 | 593K| 25 |00:00:18.24 | 821K| 821K| 5213K (0)|
| 2 | VIEW | DBA_SOURCE | 1 | 593K| 595K|00:00:16.84 | | | | | 3 | UNION-ALL | | 1 | | 595K|00:00:15.06 | | | | |* 4 | FILTER | | 1 | | 595K|00:00:10.88 | | | | |* 5 | HASH JOIN | | 1 | 595K| 595K|00:00:08.50 | 884K| 884K| 1316K (0)| |* 6 | HASH JOIN | | 1 | 6527 | 6292 |00:00:00.12 | 870K| 870K| 1179K (0)|
| 7 | TABLE ACCESS FULL | USER$ | 1 | 98 | 98 |00:00:00.01 | | | | |* 8 | HASH JOIN | | 1 | 6527 | 6292 |00:00:00.09 | 909K| 909K| 1181K (0)|
| 9 | INDEX FULL SCAN | I_USER2 | 1 | 98 | 98 |00:00:00.01 | | | | |* 10 | INDEX FAST FULL SCAN | I_OBJ2 | 1 | 6527 | 6292 |00:00:00.04 | | | | | 11 | INDEX FAST FULL SCAN | I_SOURCE1 | 1 | 595K| 595K|00:00:01.56 | | | | | 12 | NESTED LOOPS | | 0 | 1 | 0 |00:00:00.01 | | | | |* 13 | INDEX FULL SCAN | I_USER2 | 0 | 1 | 0 |00:00:00.01 | | | | |* 14 | INDEX RANGE SCAN | I_OBJ4 | 0 | 1 | 0 |00:00:00.01 | | | | | 15 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | | | | | 16 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | | | | | 17 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | | | | |* 18 | INDEX FAST FULL SCAN | I_OBJ2 | 1 | 6 | 0 |00:00:00.01 | | | | |* 19 | FIXED TABLE FIXED INDEX| X$JOXFS (ind:1) | 0 | 1 | 0 |00:00:00.01 | | | | |* 20 | INDEX RANGE SCAN | I_USER2 | 0 | 1 | 0 |00:00:00.01 | | | | | 21 | TABLE ACCESS CLUSTER | USER$ | 0 | 1 | 0 |00:00:00.01 | | | | |* 22 | INDEX UNIQUE SCAN | I_USER# | 0 | 1 | 0 |00:00:00.01 | | | | \----------------------------------------------------------------------------------------------------------------------------
HASH操作がlast Mem列が移入されていることがわかる。それゆで、行ソース関数がそのためのSQLワークエリアを割り当ていた。ネステッドループ結合や、行ソースへのデータアクセスのような他《の処理》は、完全にカスケード接続されるので、SQLワークエリアにメモリがまったく割り当てられなかった。
以下の例に見られるように、os_explainは標準入力(STDIN)からスタックを読み取ることができます。また、-aオプションは、実行計画の関数とその子供たちだけでなく、スタック内のすべての関数を表示するように、os_explainに伝えます。
Command:
SQL> alter session set statistics_level=typical;
Session altered.
SQL> select avg(length(text)) from dba_source where owner = 'SYS';
AVG(LENGTH(TEXT))
\-----------------
125.032127
Plan:
\---------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows | OMem | 1Mem | Used-Mem |
\---------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 | | | |
| 2 | VIEW | DBA_SOURCE | 17972 | | | |
| 3 | UNION-ALL | | | | | |
|* 4 | FILTER | | | | | |
| 5 | NESTED LOOPS | | | | | |
| 6 | NESTED LOOPS | | 18056 | | | |
|* 7 | HASH JOIN | | 198 | 909K| 909K| 1193K (0)|
| 8 | INDEX FULL SCAN | I_USER2 | 98 | | | |
| 9 | NESTED LOOPS | | 198 | | | |
| 10 | TABLE ACCESS BY INDEX ROWID| USER$ | 1 | | | |
|* 11 | INDEX UNIQUE SCAN | I_USER1 | 1 | | | |
|* 12 | INDEX RANGE SCAN | I_OBJ5 | 198 | | | |
|* 13 | INDEX RANGE SCAN | I_SOURCE1 | 93 | | | |
| 14 | TABLE ACCESS BY INDEX ROWID | SOURCE$ | 91 | | | |
| 15 | NESTED LOOPS | | 1 | | | |
|* 16 | INDEX FULL SCAN | I_USER2 | 1 | | | |
|* 17 | INDEX RANGE SCAN | I_OBJ4 | 1 | | | |
| 18 | NESTED LOOPS | | 1 | | | |
| 19 | NESTED LOOPS | | 1 | | | |
| 20 | NESTED LOOPS | | 1 | | | |
| 21 | TABLE ACCESS BY INDEX ROWID | USER$ | 1 | | | |
|* 22 | INDEX UNIQUE SCAN | I_USER1 | 1 | | | |
|* 23 | INDEX RANGE SCAN | I_OBJ5 | 1 | | | |
|* 24 | FIXED TABLE FIXED INDEX | X$JOXFS (ind:1) | 1 | | | |
|* 25 | INDEX RANGE SCAN | I_USER2 | 1 | | | |
\---------------------------------------------------------------------------------------------------
Stack:
$ pstack 23740 | ./os_explain -a
main ssthrdmain opimai_real sou2o opidrv opiodr opiino opitsk ttcpip opiodr kpoal8 SELECT FETCH: GROUP BY SORT: Fetch VIEW: Fetch UNION-ALL: Fetch * FILTER DEFINITION: FetchOutside UNION-ALL: RowProcedure VIEW: RowProcedure qesaAggNonDistSS. evaopn2 evalen lxsCntChar
FILTER行ソース(ここでは、通常の行ソースにおけるフィルタ述語について話しているわけではない)も、物事をより複雑にする可能性がある。FILTER行ソースは、実行計画に独自のロジックや、(相関副問合せを実行するための)ループを導入する可能性がある。
ところで、行ソースレベルの統計収集を有効にして、まったく同じクエリを実行すると何が起こるかを、見てください。
SQL> alter session set statistics_level=all; Session altered. SQL> select avg(length(text)) from dba_source where owner = 'SYS'; AVG(LENGTH(TEXT)) \----------------- 125.032127 $ pstack 23740 | ./os_explain -a main ssthrdmain opimai_real sou2o opidrv opiodr opiino opitsk ttcpip opiodr kpoal8 SELECT FETCH: QUERY EXECUTION STATISTICS: Fetch
GROUP BY SORT: Fetch QUERY EXECUTION STATISTICS: Fetch
VIEW: Fetch QUERY EXECUTION STATISTICS: Fetch
UNION-ALL: Fetch QUERY EXECUTION STATISTICS: Fetch * QUERY EXECUTION STATISTICS: Fetch FILTER DEFINITION: FetchOutside QUERY EXECUTION STATISTICS: Fetch NESTED LOOP JOIN: Fetch QUERY EXECUTION STATISTICS: Fetch QUERY EXECUTION STATISTICS: SnapStats sltrgftime64 gettimeofday
__kernel_vsyscall
すべての値集合ソースは、QUERY EXECUTION STATISTICSラッパーにラップされている。それのタスクは、(_rowsource_statistics_sampfreqパラメータで設定される)内部カウンタがラップするたびに、ツリーにおいて親に「上」に送信された行の数、論理I/O回数、行ソースのタイミング情報をカウントすることである。
これは、Oracle実行計画の内部およびトラブルシューティングするための導入部分にすぎません。うまくいけば、それほど頻繁にこのテクニックは必要ありません。しかし、それは成功し、non-trivialなデータベースの問題において、問題の根本原因を特定するために私を助けてきました。
Oracle 11gでは、リアルタイムSQL監視と呼ばれる優れた新機能がありますので注意してください。それは現在実行しているSQL文の進捗状況を監視することができます。シリアル実行で、CPUやI/O時間の合計が5秒間使われると、そのSQL文に対する監視が開始される。(この時間は_sqlmon_thresholdパラメータによって制御されますが、PXの監視は常に有効になっている)。その後、セッションが費やした時間/行/LIOSを、V$SQL_MONITORおよびV$SQL_PLAN_MONITORから確認できます。SQL実行計画の行レベルでこれらの詳細を見ることができます。別の方法として、きれいにフォーマットされた情報を得るため、DBMS_SQLTUNE.REPORT_SQL_MONITOR関数を使用できます。Greg Rahn がそれについてよいブログエントリを書いている。
しかし、DBMS_SQLTUNEおよびV$SQL_MONITOR / V$SQL_PLAN_MONITORを使用するには、Oracle Diagnostic Pack に加えて Oracle Tuning Packのライセンスを持っている必要があることに注意してください。詳細はOracle 11gのライセンスガイド にあります。
だから、もう1つのリアルタイムモニタリングのための低レベルのアプローチは、まだ11gが主流になった後でも有益であるでしょう。将来の記事で、複数のスタックトレースとDTraceを持ついくつかのクールな機会を集約することで、私は進捗状況を測定する方法、計画の実行プロファイルを取得する方法を示す予定です。