SQL Trace を取得する方法 - DBMS_MONITOR
需要はほんとにあるんだろうかと思って反省会企画第1弾を書いたところ、
sql_traceパラメータの設定
http://d.hatena.ne.jp/nijimass/20080513/1210688832
「DBMS_SYSTEM」「トレース」なんかでの検索痕が結構ありました。
いろいろ見てくれてるひとはいるんですね。
ということで、トレースを取ってみる第２弾です。
今回は前回の最後でちょっと触れた、「DBMS_MONITOR」。
Oracle Database PL/SQLパッケージ・プロシージャおよびタイプ・リファレンス 10g リリース2（10.2）
60 DBMS_MONITOR
http://otndnld.oracle.co.jp/document/products/oracle10g/102/doc_cd/appdev.102/B19245-01/d_monitor.htm
マニュアル見てみると、いろいろなプロシージャがありますね・・・。
ちなみに、パッケージはわかってるけど、プロシージャ名を忘れた！とか、
引数忘れた！というときには、SQL*Plusコマンドの desc[ribe] がオススメです。
desc はTABLEの情報とか見るときに皆さんよく使うと思うのですが、
パッケージに対しても有効ということを知らない人は結構います。
私もそうでした。
特に、Oracle Master Platinum を受験しようと思ってる方は、
ぜひぜひ知っておいてください。知ってると知らないで
合否を分ける可能性すらあるかと。
SQL> describe dbms_monitor PROCEDURE CLIENT_ID_STAT_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- CLIENT_ID VARCHAR2 IN PROCEDURE CLIENT_ID_STAT_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- CLIENT_ID VARCHAR2 IN PROCEDURE CLIENT_ID_TRACE_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- CLIENT_ID VARCHAR2 IN PROCEDURE CLIENT_ID_TRACE_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- CLIENT_ID VARCHAR2 IN WAITS BOOLEAN IN DEFAULT BINDS BOOLEAN IN DEFAULT PROCEDURE DATABASE_TRACE_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- INSTANCE_NAME VARCHAR2 IN DEFAULT PROCEDURE DATABASE_TRACE_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- WAITS BOOLEAN IN DEFAULT BINDS BOOLEAN IN DEFAULT INSTANCE_NAME VARCHAR2 IN DEFAULT PROCEDURE SERV_MOD_ACT_STAT_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SERVICE_NAME VARCHAR2 IN MODULE_NAME VARCHAR2 IN ACTION_NAME VARCHAR2 IN DEFAULT PROCEDURE SERV_MOD_ACT_STAT_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SERVICE_NAME VARCHAR2 IN MODULE_NAME VARCHAR2 IN ACTION_NAME VARCHAR2 IN DEFAULT PROCEDURE SERV_MOD_ACT_TRACE_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SERVICE_NAME VARCHAR2 IN MODULE_NAME VARCHAR2 IN DEFAULT ACTION_NAME VARCHAR2 IN DEFAULT INSTANCE_NAME VARCHAR2 IN DEFAULT PROCEDURE SERV_MOD_ACT_TRACE_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SERVICE_NAME VARCHAR2 IN MODULE_NAME VARCHAR2 IN DEFAULT ACTION_NAME VARCHAR2 IN DEFAULT WAITS BOOLEAN IN DEFAULT BINDS BOOLEAN IN DEFAULT INSTANCE_NAME VARCHAR2 IN DEFAULT PROCEDURE SESSION_TRACE_DISABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SESSION_ID BINARY_INTEGER IN DEFAULT SERIAL_NUM BINARY_INTEGER IN DEFAULT PROCEDURE SESSION_TRACE_ENABLE 引数名 タイプ In/Out Default? ------------------------------ ----------------------- ------ -------- SESSION_ID BINARY_INTEGER IN DEFAULT SERIAL_NUM BINARY_INTEGER IN DEFAULT WAITS BOOLEAN IN DEFAULT BINDS BOOLEAN IN DEFAULT
- DATABASE_TRACE_[ENABLE|DISABLE]
まぁ、案ずるよりなんとかなので、DATABASE_TRACE_ENABLEあたりを実行してみましょうか。
検証環境もあるしね。
ちなみに、これで、データベース全体にたいして、sql_trace が有効になります。
alter system set sql_trace=true;
と同じですね。
SQL> exec dbms_monitor.DATABASE_TRACE_ENABLE(TRUE,FALSE); PL/SQLプロシージャが正常に完了しました。 SQL>
１つ目のTRUEは待機イベントのモニタリングをするかどうか。
event 10046 トレースでいうところの、level 8 です。
２つめはバインド変数。
これは、event 10046 トレースでいうところの、level 4 です。
[oracle@test udump]$ pwd /opt/oracle/app/oracle/admin/orcl1/udump [oracle@test udump]$ ls -rtl | tail -rw-r----- 1 oracle oinstall 1820735 4月 20 20:33 orcl1_ora_5852.trc -rw-r----- 1 oracle oinstall 1821568 4月 20 20:33 orcl1_ora_5857.trc -rw-r----- 1 oracle oinstall 1835561 4月 20 20:37 orcl1_ora_5884.trc -rw-r----- 1 oracle oinstall 651 4月 24 18:08 orcl1_ora_5782.trc -rw-r----- 1 oracle oinstall 708 4月 24 18:08 orcl1_ora_5805.trc -rw-r----- 1 oracle oinstall 1902 4月 24 18:09 orcl1_ora_5806.trc -rw-r----- 1 oracle oinstall 3296 4月 24 19:02 orcl1_ora_6127.trc -rw-r----- 1 oracle oinstall 1302 5月 14 19:34 orcl1_ora_5784.trc -rw-r----- 1 oracle oinstall 1416 5月 14 19:34 orcl1_ora_5807.trc
セッションを張ってみましょうか。
[oracle@test ~]$ sqlplus scott/tiger
SQL*Plus: Release 10.2.0.3.0 - Production on 水 5月 14 19:42:13 2008
Copyright (c) 1982, 2006, Oracle. All Rights Reserved.
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning and Data Mining options
に接続されました。
SQL> select count(*) from emp;
COUNT(*)
----------
7
SQL> exit
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning and Data Mining optionsとの接続が切断されました。
取得できてるかな・・・？
[oracle@test udump]$ ls -rtl | tail -rw-r----- 1 oracle oinstall 1821568 4月 20 20:33 orcl1_ora_5857.trc -rw-r----- 1 oracle oinstall 1835561 4月 20 20:37 orcl1_ora_5884.trc -rw-r----- 1 oracle oinstall 651 4月 24 18:08 orcl1_ora_5782.trc -rw-r----- 1 oracle oinstall 708 4月 24 18:08 orcl1_ora_5805.trc -rw-r----- 1 oracle oinstall 1902 4月 24 18:09 orcl1_ora_5806.trc -rw-r----- 1 oracle oinstall 3296 4月 24 19:02 orcl1_ora_6127.trc -rw-r----- 1 oracle oinstall 1302 5月 14 19:34 orcl1_ora_5784.trc -rw-r----- 1 oracle oinstall 1416 5月 14 19:34 orcl1_ora_5807.trc -rw-r----- 1 oracle oinstall 4457 5月 14 19:39 orcl1_ora_5808.trc -rw-r----- 1 oracle oinstall 313645 5月 14 19:42 orcl1_ora_5894.trc
お。「orcl1_ora_5894.trc」ができてますね。これかな？
[oracle@test udump]$ tkprof orcl1_ora_5894.trc orcl1_ora_5894.txt sys=no
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 19:43:13 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
[oracle@test udump]$ more orcl1_ora_5894.txt
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 19:43:13 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl1_ora_5894.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
emp
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 6 125 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.03 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.04 7 126 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 36
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1 pr=1 pw=0 time=33188 us)
7 INDEX FULL SCAN PK_EMP (cr=1 pr=1 pw=0 time=33075 us)(object id 12276)
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 1 0.03 0.03
SQL*Net message from client 2 1.04 1.04
（中略）
********************************************************************************
Trace file: orcl1_ora_5894.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
8 user SQL statements in trace file.
400 internal SQL statements in trace file.
408 SQL statements in trace file.
49 unique SQL statements in trace file.
3684 lines in trace file.
3 elapsed seconds in trace file.
うん。とれてますね。おｋ。
解除はこれで。
SQL> exec dbms_monitor.DATABASE_TRACE_DISABLE; PL/SQLプロシージャが正常に完了しました。 SQL>
- SESSION_TRACE_[ENABLE|DISABLE]
これは session 単位でとるやつなので、
alter session set sql_trace=true
と同じっぽいですね。
ただ、引数に、「SESSION_ID」「SERIAL_NUM」があるので、
自分だけではなくて、別 session の分もとれるんですかね？
とりあえずやってみますか。
SQL> exec dbms_monitor.SESSION_TRACE_ENABLE();
PL/SQLプロシージャが正常に完了しました。
SQL> select count(*) from scott.emp;
COUNT(*)
----------
7
SQL> exec dbms_monitor.SESSION_TRACE_DISABLE();
PL/SQLプロシージャが正常に完了しました。
とやってみたんですが、どうも取れてないようす・・・。
[oracle@test udump]$ tkprof orcl1_ora_5808.trc orcl1_ora_5808.txt sys=no
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:07:20 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
[oracle@test udump]$ more orcl1_ora_5808.txt
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:07:20 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl1_ora_5808.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
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.02 0.02 0 0 0 0
Execute 6 0.04 0.06 3 66 25 4
Fetch 4 0.00 0.00 0 1 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.07 0.10 3 67 25 7
Misses in library cache during parse: 4
Misses in library cache during execute: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 436.36 457.84
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 1 5 1
Fetch 2 0.00 0.00 0 4 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.01 0 5 5 1
Misses in library cache during parse: 2
Misses in library cache during execute: 2
6 user SQL statements in session.
3 internal SQL statements in session.
9 SQL statements in session.
********************************************************************************
Trace file: orcl1_ora_5808.trc
Trace file compatibility: 10.01.00
Sort options: default
2 sessions in tracefile.
6 user SQL statements in trace file.
3 internal SQL statements in trace file.
9 SQL statements in trace file.
8 unique SQL statements in trace file.
122 lines in trace file.
1601 elapsed seconds in trace file.
ん？ああ、そうかそうか。
SYS でログインしてるのに、 sys=no つけてるじゃん、おれ。
すんません。やりなおし。
[oracle@test udump]$ tkprof orcl1_ora_5808.trc orcl1_ora_5808.txt
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:25:02 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
[oracle@test udump]$ more orcl1_ora_5808.txt
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:25:02 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl1_ora_5808.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
scott.emp
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 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=973 us)
7 INDEX FULL SCAN PK_EMP (cr=1 pr=0 pw=0 time=894 us)(object id 12276)
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
SQL*Net message from client 2 6.34 6.34
********************************************************************************
（中略）
********************************************************************************
Trace file: orcl1_ora_5808.trc
Trace file compatibility: 10.01.00
Sort options: default
2 sessions in tracefile.
6 user SQL statements in trace file.
3 internal SQL statements in trace file.
9 SQL statements in trace file.
8 unique SQL statements in trace file.
122 lines in trace file.
1601 elapsed seconds in trace file.
うん。とれてるね。おｋ！
解除はこれで。
SQL> exec dbms_monitor.SESSION_TRACE_DISABLE(); PL/SQLプロシージャが正常に完了しました。 SQL>
じゃあ、別 session のトレースも取ってみましょうか・・・。
まず、scott で別セッションをはります。
[oracle@test ~]$ sqlplus scott/tiger SQL*Plus: Release 10.2.0.3.0 - Production on 水 5月 14 20:27:16 2008 Copyright (c) 1982, 2006, Oracle. All Rights Reserved. Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production With the Partitioning and Data Mining options に接続されました。 SQL>
で、別のセッションから確認してトレース開始と。
[oracle@test udump]$ sqlplus / as sysdba
SQL*Plus: Release 10.2.0.3.0 - Production on 水 5月 14 20:26:53 2008
Copyright (c) 1982, 2006, Oracle. All Rights Reserved.
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning and Data Mining options
に接続されました。
SQL> select sid,serial# from v$session where username = 'SCOTT';
SID SERIAL#
---------- ----------
148 46
SQL> exec dbms_monitor.session_trace_enable(148,46);
PL/SQLプロシージャが正常に完了しました。
SQL>
scottで何発かSQL実行と。
SQL> select count(*) from dept;
COUNT(*)
----------
4
SQL> select count(*) from emp;
COUNT(*)
----------
7
sysのほうで、トレース解除と。
SQL> exec dbms_monitor.session_trace_disable(148,46); PL/SQLプロシージャが正常に完了しました。 SQL>
取れてるかな・・・？
[oracle@test udump]$ tkprof orcl1_ora_5972.trc orcl1_ora_5972.txt sys=no
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:29:31 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
[oracle@test udump]$ more orcl1_ora_5972.txt
TKPROF: Release 10.2.0.3.0 - Production on 水 5月 14 20:29:31 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl1_ora_5972.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
dept
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.07 0 51 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.02 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.07 0.09 1 52 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 36
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1 pr=1 pw=0 time=20317 us)
4 INDEX FULL SCAN PK_DEPT (cr=1 pr=1 pw=0 time=20266 us)(object id 12232)
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 1 0.01 0.01
SQL*Net message from client 2 2.21 2.21
********************************************************************************
select count(*)
from
emp
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 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1
Misses in library cache during parse: 0
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
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 2 0.07 0.07 0 51 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.02 1 2 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.07 0.09 1 53 0 2
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
db file sequential read 1 0.01 0.01
SQL*Net message from client 3 2.21 2.21
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 13 0.01 0.00 0 0 0 0
Execute 14 0.00 0.00 0 0 0 0
Fetch 22 0.01 0.01 0 51 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 49 0.04 0.03 0 51 0 14
Misses in library cache during parse: 0
2 user SQL statements in session.
14 internal SQL statements in session.
16 SQL statements in session.
********************************************************************************
Trace file: orcl1_ora_5972.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
14 internal SQL statements in trace file.
16 SQL statements in trace file.
14 unique SQL statements in trace file.
191 lines in trace file.
2 elapsed seconds in trace file.
うん。とれとるとれとる。
これがあったら、DBMS_SYSTEM.SET_EV とかいらないっすね。
しかし、DBMS_MONITOR って今までほとんど使ったことなかったけど、
かなりいろいろできそうですね。
「SERV_MOD_ACT_TRACE_ENABLE」とか
「CLIENT_ID_TRACE_ENABLE」とか。
これはまた今度試してみましょう。
では。
