SQL Trace を取得する方法 - DBMS_SYSTEM
なんか、DBMS_MONITORのエントリを書いた時点で
これはやらなくて良いような気がしましたが、
いちおう書いとくか。
マニュアル探したけど、DBMS_SYSTEMが見つかりませんでした・・・。
「Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス」に
載ってると思ったのになぁ・・・。
まぁ、とりあえず、お決まりの desc で確認。
Versionは10.2。
SQL> desc dbms_system PROCEDURE DIST_TXN_SYNC 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- INST_NUM NUMBER IN PROCEDURE GET_ENV 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- VAR VARCHAR2 IN VAL VARCHAR2 OUT PROCEDURE KCFRMS PROCEDURE KSDDDT PROCEDURE KSDFLS PROCEDURE KSDIND 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- LVL BINARY_INTEGER IN PROCEDURE KSDWRT 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- DEST BINARY_INTEGER IN TST VARCHAR2 IN PROCEDURE READ_EV 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- IEV BINARY_INTEGER IN OEV BINARY_INTEGER OUT PROCEDURE SET_BOOL_PARAM_IN_SESSION 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SID NUMBER IN SERIAL# NUMBER IN PARNAM VARCHAR2 IN BVAL BOOLEAN IN PROCEDURE SET_EV 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SI BINARY_INTEGER IN SE BINARY_INTEGER IN EV BINARY_INTEGER IN LE BINARY_INTEGER IN NM VARCHAR2 IN PROCEDURE SET_INT_PARAM_IN_SESSION 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SID NUMBER IN SERIAL# NUMBER IN PARNAM VARCHAR2 IN INTVAL BINARY_INTEGER IN PROCEDURE SET_SQL_TRACE_IN_SESSION 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SID NUMBER IN SERIAL# NUMBER IN SQL_TRACE BOOLEAN IN PROCEDURE WAIT_FOR_EVENT 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- EVENT VARCHAR2 IN EXTENDED_ID BINARY_INTEGER IN TIMEOUT BINARY_INTEGER IN
「SET_SQL_TRACE_IN_SESSION」がそのものずばりなのですが、説明は省きます。
スーパーセット的に使用可能な「SET_EV」があるので・・・。
っつーわけで、今回はDBMS_SYSTEM.SET_EVの説明をしていきます。
DBMS_SYSTEM.SET_EV のパラメータ
DBMS_SYSTEM.SET_EVは
特定のセッションに対して、イベントを設定できるプロシージャです。
ここに、10046(SQLトレース)や10053(CBOのトレース)といったイベントを設定すれば
よいわけで、「SET_SQL_TRACE_IN_SESSION」のスーパーセットと書いたのは、
このためです。
PROCEDURE SET_EV 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SI BINARY_INTEGER IN SE BINARY_INTEGER IN EV BINARY_INTEGER IN LE BINARY_INTEGER IN NM VARCHAR2 IN
パラメータに設定すべき内容は下記のようになっているようです。
SI -> sid
SE -> serial#
EV -> Event Number(10046とか10053とか)
LE -> Event Level
NM -> Event Name
DBMS_SYSTEM.SET_EV を使ってSQLトレースを取得する。
例によって案ずるより何とかということで実行。
SQL> select sid,serial# from v$session where username='SCOTT';
SID SERIAL#
---------- ----------
152 8
SQL> exec DBMS_SYSTEM.SET_EV(152,8,10046,8,'');
PL/SQLプロシージャが正常に完了しました。
今回も Level 8 で取得してます。
何度か書いてますが、
Level 1 -> SQLトレースだけ
Level 4 -> SQLトレースとバインド変数
Level 8 -> SQLトレースと待機イベント
Level 12 -> SQLトレースとバインド変数と待機イベント
となってますので、ご参考に・・・。
SQL> select count(*) from SALGRADE;
COUNT(*)
----------
5
解除はLevelを0にすることで行ないます。
SQL> exec DBMS_SYSTEM.SET_EV(152,8,10046,0,''); PL/SQLプロシージャが正常に完了しました。
確認・・・。
[oracle@test udump]$ tkprof orcl1_ora_5872.trc orcl1_ora_5872.txt sys=no
TKPROF: Release 10.2.0.3.0 - Production on 火 5月 20 19:29:53 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
[oracle@test udump]$ more orcl1_ora_5872.txt
TKPROF: Release 10.2.0.3.0 - Production on 火 5月 20 19:29:53 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl1_ora_5872.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
select count(*)
from
SALGRADE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.03 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.04 2 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.07 2 3 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 36
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file sequential read 2 0.01 0.01
SQL*Net message from client 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.03 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.04 2 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.07 2 3 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.01 0.01
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 11 0.03 0.02 0 0 0 0
Execute 81 0.11 0.13 0 0 0 0
Fetch 84 0.07 0.16 12 238 0 487
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 176 0.23 0.32 12 238 0 487
Misses in library cache during parse: 11
Misses in library cache during execute: 11
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 12 0.02 0.11
1 user SQL statements in session.
81 internal SQL statements in session.
82 SQL statements in session.
********************************************************************************
Trace file: orcl1_ora_5872.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
1 user SQL statements in trace file.
81 internal SQL statements in trace file.
82 SQL statements in trace file.
12 unique SQL statements in trace file.
748 lines in trace file.
0 elapsed seconds in trace file.
取れました。
おｋ。
DBMS_SYSTEM.SET_EV を使ってCBOのトレースを取得する。
SQL> exec DBMS_SYSTEM.SET_EV(152,8,10053,1,''); PL/SQLプロシージャが正常に完了しました。
SQL> select count(*) from emp;
COUNT(*)
----------
7
SQL> exec DBMS_SYSTEM.SET_EV(152,8,10053,0,''); PL/SQLプロシージャが正常に完了しました。
やりかたは10046と同じです。
あんまり自分で読む機会はないので、中身は省略しますね。
サポートに送りつける用途が多いので・・・。
DBMS_SYSTEM.SET_EV を使ってerrorstackとかを取ってみる。
ちょっと話がそれますが、
ORA-4031 とかが発生した場合に errorstack をとりたい！
とかいう場合は、通常このように設定しますが、
alter session set events '4031 trace name errorstack level 3';
これだと、実行セッションでしか有効にならないわけで、
別セッションに対して有効にするために、
DBMS_SYSTEM.SET_EV を使ってやると、こうなるわけですね。
# system単位で設定するほうが早いですけどね。
SQL> exec DBMS_SYSTEM.SET_EV(&sid ,&serial# ,4031 ,3 ,'ERRORSTACK');
4031は起こしにくいので、942が発生したらでerrorstack取るようにしてみます。
SQL> select sid,serial# from v$session where username='SCOTT';
SID SERIAL#
---------- ----------
152 10
SQL> exec DBMS_SYSTEM.SET_EV(152,10,942,3,'ERRORSTACK');
PL/SQLプロシージャが正常に完了しました。
で、ORA-942 を発生させると・・・。
SQL> select count(*) from yakiniku_tabetai;
select count(*) from yakiniku_tabetai
*
行1でエラーが発生しました。:
ORA-00942: 表またはビューが存在しません。
ここでは当然わからないんですが、
SQLを実行してから、ORA-942 が出るまでに、
「お、なんかログとってるな・・・。」的な
いつもとは違うレスポンス感、ひっかかり感があります。
で、ファイルを確認。
[oracle@test udump]$ ls -rtl | tail
-rw-r----- 1 oracle oinstall 2653 5月 14 20:24 orcl1_ora_5932.trc
-rw-r--r-- 1 oracle oinstall 12424 5月 14 20:25 orcl1_ora_5808.txt
-rw-r--r-- 1 oracle oinstall 5639 5月 14 20:29 orcl1_ora_5972.txt
-rw-r----- 1 oracle oinstall 15804 5月 14 20:30 orcl1_ora_5972.trc
-rw-r----- 1 oracle oinstall 2761 5月 14 20:35 orcl1_ora_5982.trc
-rw-r----- 1 oracle oinstall 651 5月 20 18:55 orcl1_ora_5770.trc
-rw-r----- 1 oracle oinstall 708 5月 20 18:55 orcl1_ora_5793.trc
-rw-r--r-- 1 oracle oinstall 26410 5月 20 19:34 orcl1_ora_5872.txt
-rw-r----- 1 oracle oinstall 130670 5月 20 19:37 orcl1_ora_5872.trc
-rw-r----- 1 oracle oinstall 1851463 5月 20 19:38 orcl1_ora_5953.trc
[oracle@test udump]$ more orcl1_ora_5953.trc
/opt/oracle/app/oracle/admin/orcl1/udump/orcl1_ora_5953.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning and Data Mining options
ORACLE_HOME = /opt/oracle/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: test
Release: 2.6.9-67.0.0.0.1.EL
Version: #1 Sun Nov 18 00:16:01 EST 2007
Machine: i686
Instance name: orcl1
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 5953, image: oracle@test (TNS V1-V3)
*** ACTION NAME:() 2008-05-20 19:38:03.291
*** MODULE NAME:(SQL*Plus) 2008-05-20 19:38:03.291
*** SERVICE NAME:(SYS$USERS) 2008-05-20 19:38:03.291
*** SESSION ID:(152.10) 2008-05-20 19:38:03.291
*** 2008-05-20 19:38:03.291
ksedmp: internal or fatal error
ORA-00942: 表またはビューが存在しません。
Current SQL statement for this session:
select count(*) from yakiniku_tabetai
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst()+27 call ksedst1() 0 ? 1 ?
ksedmp()+557 call ksedst() 0 ? 0 ? 0 ? C7C88D8 ?
2F1EF2F8 ? C806D00 ?
ksddoa()+932 call 00000000 3 ? 0 ? 0 ? 0 ? 0 ? 0 ?
ksdpcg()+476 call ksddoa() C89CB1C ? C88752C ?
ksdpec()+208 call ksdpcg() 3AE ? BFFF4200 ? 1 ?
とれてますね。
内容は・・・。まぁ、がんばってください・・・。
というわけで、今日はここまで。
さて、次は何をやるかな・・・。
なんか知りたいことがあれば、コメントでもメールでもお待ちしております。
スキルレベル的にできないかもしれないけど。
では。
