クエリが現在実行段階のどこを実行しているのか分かる方法がないんでしょうか

この前、社内のエンジニアたちと話し合ううちこんな疑問が提起が提起されました。

クエリが現在実行段階のどこを実行しているのか分かる方法がないんでしょうか。

SQL*Traceのような一般的な方法では不可能です。たぶん唯一な方法はオラクルが実行計画によってクエリを実行しながら呼び出す関数(Function)をトレースすることでしょう。オラクルが呼び出す関数をトレースする一番簡単な方法はoradebug short_stackコマンドです。

簡単な例を通じて見ましょう。まず次のように必要なオブジェクトを作ります。

create table t1 as
select level as c1, 'x' as c2
from dual
connect by level <= 1000;

create table t2 as
select level as c1, 'x' as c2
from dual
connect by level <= 1000;

create index t2_n1 on t2(c1);

create or replace function f_wait(p1 number, p2 number)
return number
is
begin
  dbms_lock.sleep(p2);
  return 1;
end;
/

次のようにNested Loops Joinを通じてデータをフェッチするクエリがあります。ただしf_wait(t1.c1, 0.01)を利用して実際のデータをフェッチする時遅延が起こるようにします。

explain plan for
select /*+ ordered use_nl(t2) */ t1.c1, t2.c2, f_wait(t1.c1, 0.01)
from t1, t2
where t1.c1 = t2.c1
;

---------------------------------------------
| Id  | Operation                   | Name  |
---------------------------------------------
|   0 | SELECT STATEMENT            |       |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2    |
|   2 |   NESTED LOOPS              |       |
|   3 |    TABLE ACCESS FULL        | T1    |
|*  4 |    INDEX RANGE SCAN         | T2_N1 |
---------------------------------------------

クエリを実行する途中、実行計画のどんな段階にあるののかトレースしてみましょう。

UKJA@ukja1021> select /*+ ordered use_nl(t2) */ t1.c1, t2.c2, f_wait(t1.c1, 0.01)
  2  from t1, t2
  3  where t1.c1 = t2.c1
  4  ;

        C1 C F_WAIT(T1.C1,0.01)
---------- - ------------------
         1 x                  1
         2 x                  1
...

クエリの特性からたぶん現在テーブルT2からデータをフェッチする段階(id=1)にある確率が高いです。下にoradebug short_stackコマンドの結果があります。

SYS@ukja1021> oradebug short_stack
_ksdxfstk+14<-_ksdxcb+1481<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadSt
art@4+795<-7C80B710<-00000000<-7C80253D<-_skgpwwait+124<-_ksliwat+843<-_kslwaitn
s+24<-_kskthbwt+159<-_kslwait+52<-_psdwat+155<-_pevm_icd_call_common+722<-_pfrin
str_ICAL+120<-_pfrrun_no_tool+56<-_pfrrun+781<-_plsql_run+738<-_peidxr_run+199<-
_peidxexe+52<-_kkxdexe+278<-_kkxmpexe+184<-_kgmexec+295<-_evapls+724<-_evaopn2+4
02<-_kpofcr+1593<-_qertbFetchByRowID+2083<-_rwsfcd+95<-_opifch2+3104<-_opifch+51
<-_opiodr+1099<-_ttcpip+1273<-_opitsk+1017<-_opiino+1087<-_opiodr+1099<-_opidrv+
819<-_sou2o+45<-_opimai_real+112<-_opimai+92<-_OracleThreadStart@4+708<-7C80B710

上のスタックトレース中実行計画と係りのあるのだけ引き出してみれば次のようです。最初の予想とぴったり合います。

opifch2 : Fetch. SELECTに該当
  qertbFetchByRowID : TABLE FETCH BY ROWIDに該当

もう少し正確な観察をために今度はWHERE句にf_wait(t2.c1, 0.01) = 1条件を与えてテーブルT2をアクセスする過程で遅延が起こるようにしてみます。実行計画上でみればIndex Range Scanに該当する４番の段階で遅延が発生することが確認できます。

explain plan for
select /*+ ordered use_nl(t2) */ t1.c1, t2.c2
from t1, t2
where t1.c1 = t2.c1 and f_wait(t2.c1, 0.01) = 1
;

---------------------------------------------
| Id  | Operation                   | Name  |
---------------------------------------------
|   0 | SELECT STATEMENT            |       |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2    |
|   2 |   NESTED LOOPS              |       |
|   3 |    TABLE ACCESS FULL        | T1    |
|*  4 |    INDEX RANGE SCAN         | T2_N1 |
---------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T1"."C1"="T2"."C1")
       filter("F_WAIT"("T2"."C1",0.01)=1)

クエリを実行しながらoradebug short_stackコマンドでトレースします。

UKJA@ukja1021> select /*+ ordered use_nl(t2) */ t1.c1, t2.c2
  2  from t1, t2
  3  where t1.c1 = t2.c1 and f_wait(t2.c1, 0.01) = 1
  4  ;

        C1 C
---------- -
         1 x
         2 x
         3 x
...

結果は次のようです。

SYS@ukja1021> oradebug short_stack
_ksdxfstk+14<-_ksdxcb+1481<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadSt
art@4+795<-7C80B710<-00000000<-7C80253D<-_skgpwwait+124<-_ksliwat+843<-_kslwaitn
s+24<-_kskthbwt+159<-_kslwait+52<-_psdwat+155<-_pevm_icd_call_common+722<-_pfrin
str_ICAL+120<-_pfrrun_no_tool+56<-_pfrrun+781<-_plsql_run+738<-_peidxr_run+199<-
_peidxexe+52<-_kkxdexe+278<-_kkxmpexe+184<-_kgmexec+295<-_evapls+724<-_evaopn2+4
02<-_evareo+110<-_expepr+73<-_expeal+17<-_qerixtFetch+3498<-_qerjoFetch+864<-_qe
rpfFetch+251<-_qertbFetchByRowID+475<-_rwsfcd+95<-_opifch2+3104<-_opifch+51<-_op
iodr+1099<-_ttcpip+1273<-_opitsk+1017<-_opiino+1087<-_opiodr+1099<-_opidrv+819<-
_sou2o+45<-_opimai_real+112<-_opimai+92<-_OracleThreadStart@4+708<-7C80B710

この中で実行計画と関係のある部分だけを引き出せば次のようです。

_opifch2 : Fetch. SELECT
  _qertbFetchByRowID : TABLE FETCH BY ROWID
     _qerpfFetch : Prefetch
        _qerjoFetch : NESTED LOOPS JOIN
           _qerixtFetch : INDEX RANGE SCAN

すなわち、現在４番の段階のIndex Range Scanを実行しているのが分かります。４番段階で遅延が発生するように操作したのがよく動作しました。

もっと長くて複雑なクエリも上と同じ方法でトレースが可能です。もちろん安くてはないんですけど…

クエリの実行時間が長すぎる場合やハング(Hang)が発生するときを想像しましょう。万一SQL*Traceや待機イベント分析のような一般的な方法ではもう以上のトレースが不可能だったら?上の方法はそんな場合使えるたぶん唯一な方法でしょう。