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

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

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

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や待機イベント分析のような一般的な方法ではもう以上のトレースが不可能だったら?上の方法はそんな場合使えるたぶん唯一な方法でしょう。

Process Explorer

この前、Ask ExemにWindows用のオラクルのメモリモニタリングの問題に対する問い合わせがありました。

Oracleのメモリ使用量関連

(Ask Exemは韓国のExemが運営するQ&Aサイトです)

これはオラクルの問題というよりはOSの問題です。オラクルもOSが提供するメモリ管理記法をそのまま使用するアプリに過ぎませんからです。

Windows環境でプロセスをモニタリングする最善のツールははProcess Explorerです。Windowsを使用しながらこのツールを使用していないのは大きい損害だと言えます。

Process Explorerを通じてオラクルをモニタリングする簡単な画面を見てみましょう。

1. ハンドラーモニタリング - ユニックスのlsofコマンドに該当

2. スレッドモニタリング - オラクルのセッションに該当

3. CPU, Memoryなど核心性能指標 - ユニックスのps, topなどに該当

より幅広い性能指標を1つの画面で見ることもできます。

このような機能たちをよく活用すればユニックスに劣らなく精密なプロセスモニタリングが可能です。ただし、Windows用のオラクルはマルチプロセス環境ではなくてマルチスレッド環境ですのでもう少しややこしいといえます。

他のセッションのパラメータを制御しよう

セッションモニタリングをしてみると次のような二つの要求事項ができるはずです。

1. 特定のセッションが特定のパラメータ値を変更した場合(すなわち、システムディフォルト値と違う値を設定した場合)、これを確認できる？
   
2. 特定のセッションの特定のパラメータ値を変えることができる？
   

まず特定のセッションのパラメータ値を確認できる一番確実な方法はoradebug dump errorstackコマンドです。

-- Session #1
UKJA@ukja1021> @me

SADDR           SID    SERIAL# PID        PADDR
-------- ---------- ---------- ---------- --------
34328D4C        140       5489 5924       3424C60C

UKJA@ukja1021> alter session set "_hash_join_enabled" = false;

Session altered.

-- Session #2
SYS@ukja1021> oradebug setospid 5924
Oracle pid: 15, Windows thread id: 5924, image: ORACLE.EXE (SHAD)
SYS@ukja1021> oradebug dump errorstack 3;
Statement processed.
SYS@ukja1021> oradebug tracefile_name
c:\oracle\admin\ukja1021\udump\ukja1021_ora_5924.trc

SYS@ukja1021> ed c:\oracle\admin\ukja1021\udump\ukja1021_ora_5924.trc

....
Dump event group for SESSION
Dump event group for SYSTEM
DYNAMICALLY MODIFIED PARAMETERS:
  _hash_join_enabled       = FALSE   <--- 注目!

Oracle10gからはV$SES_OPTIMIZER_ENVビューを通じて一部のパラメータ値を確認できるがオプティマイザに関したパラメータ値に限るという制約があります。

他のセッションのパラメータ値を変更するのはDBMS_SYSTEMパッケージを通じて可能です。

-- Session #2
SYS@ukja1021> exec dbms_system.set_bool_param_in_session(140,5489,'_hash_join_enabled', true);

PL/SQL procedure successfully completed.

-- Session #1
UKJA@ukja1021> @para hash_join_enabled
UKJA@ukja1021> set echo off
old   9: and i.ksppinm like '%&1%'
new   9: and i.ksppinm like '%hash_join_enabled%'

NAME                           VALUE                IS_DEFAUL SES_MODIFI
------------------------------ -------------------- --------- ----------
SYS_MODIFI
----------
DESCRIPTION
------------------------------------------------------------------------

_hash_join_enabled             TRUE                 TRUE      true
false
enable/disable hash join

DBMS_SYTEM.SET_BOOL_PARAM_IN_SESSIONプロシージャはBoolean(True/False)タイプのパラメータ値を、DBMS_SYSTEM.SET_INT_PARAM_IN_SESSIONプロシージャはIntegerタイプのパラメータ値を変更する機能を提供します。しかし、文字列タイプのパラメータ値を変更する機能は提供されません。たぶん、過去のバージョンでどんな理由のために提供しなかったが、その後機能の追加や変更がなかったと思われます。

OradebugやDBMS_SYSTEMのような文書化がなっていない機能を使用しなければならないのが負担になるかも知れません。こんな機能の使用でオラクルデータベースに問題ができたらサポートの領域を外れるようになると言うのも大きい負担です。でも、トラブルシューチングを少し深く入ってもすぐこんな隠し機能が必要になるのが現実でもあります。