SQL_TRACE作为SQL优化的工具的特点是：她可以对整个当前session或者其他特定的session做全面的跟踪，以便发现session中出现的异常现象，第一时间处理之。
当然，针对一条SQL的跟踪同样有效，类似Explain Plan和AUTOTRACE。
这里演示一下对当前session进行跟踪的情况。
1.开启sql_trace
sec@ora10g> alter session set sql_trace = true;
Session altered.
2.执行待跟踪的SQL语句
sec@ora10g> select count(*) from t;
COUNT(*)
----------
3000001
3.关闭sql_trace，停止跟踪
sec@ora10g> alter session set sql_trace = false;
Session altered.
4.确认一下当前执行的sqlplus的spid，以便下一步骤确定生成的trace文件
sec@ora10g> select spid from V$session s,v$process p,v$mystat m where s.paddr = p.addr and s.sid = m.sid and m.statistic# = 0;
SPID
------------
28863
5.进入到用户转储区udump目录，sql_trace生成的trace文件就在这个文件夹中生成
ora10g@secDB /home/oracle$ cd $ORACLE_BASE/admin/$ORACLE_SID/udump
6.使用第4步骤得到的spid得到对应的trace文件
$ ls -l | grep 28863
-rw-r----- 1 oracle oinstall 2.4K Sep 26 16:12 ora10g_ora_28863.trc
7.查看一下原汁原味的trace文件，细心查找一下上面我们运行过的三个SQL语句。有点乱，这时tkprof工具就派上用场了
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.trc
/oracle/app/oracle/admin/ora10g/udump/ora10g_ora_28863.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining Scoring Engine options
ORACLE_HOME = /oracle/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: asdlabdb01
Release: 2.6.18-128.el5
Version: #1 SMP Wed Dec 17 11:41:38 EST 2008
Machine: x86_64
Instance name: ora10g
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 28863, image: oracle@asdlabdb01 (TNS V1-V3)
*** 2009-09-26 16:12:16.005
*** ACTION NAME:() 2009-09-26 16:12:16.005
*** MODULE NAME:(SQL*Plus) 2009-09-26 16:12:16.005
*** SERVICE NAME:(SYS$USERS) 2009-09-26 16:12:16.005
*** SESSION ID:(525.2176) 2009-09-26 16:12:16.005
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563218755381 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563218755376
EXEC #3:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563218755807
=====================
PARSING IN CURSOR #2 len=22 dep=0 uid=30 ct=3 lid=30 tim=1224563222976558 hv=2763161912 ad='ccd964b0'
select count(*) from t
END OF STMT
PARSE #2:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976554
EXEC #2:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976654
FETCH #2:c=540917,e=527837,p=0,cr=37988,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223504525
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563223504782
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563223505075 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563223505071
EXEC #3:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223505269
STAT #2 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)'
STAT #2 id=2 cnt=3000001 pid=1 pos=1 bj=12662 p='TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)'
=====================
PARSING IN CURSOR #2 len=35 dep=0 uid=30 ct=42 lid=30 tim=1224563232033798 hv=310044142 ad='0'
alter session set sql_trace = false
END OF STMT
PARSE #2:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033795
EXEC #2:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033856
8.使用tkprof工具对上面的trace文件格式化后，SQL运行的统计信息尽收眼底。
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_28863.trc ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_28863.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
********************************************************************************
select count(*)
from
t
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.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.54 0.52 0 37988 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)
3000001 TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)
********************************************************************************
alter session set sql_trace = false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 30
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 2
Fetch 2 0.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.54 0.52 0 37988 0 3
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
4 user SQL statements in session.
0 internal SQL statements in session.
4 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_28863.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
4 user SQL statements in trace file.
0 internal SQL statements in trace file.
4 SQL statements in trace file.
3 unique SQL statements in trace file.
47 lines in trace file.
13 elapsed seconds in trace file.
-- The End --
当然，针对一条SQL的跟踪同样有效，类似Explain Plan和AUTOTRACE。
这里演示一下对当前session进行跟踪的情况。
1.开启sql_trace
sec@ora10g> alter session set sql_trace = true;
Session altered.
2.执行待跟踪的SQL语句
sec@ora10g> select count(*) from t;
COUNT(*)
----------
3000001
3.关闭sql_trace，停止跟踪
sec@ora10g> alter session set sql_trace = false;
Session altered.
4.确认一下当前执行的sqlplus的spid，以便下一步骤确定生成的trace文件
sec@ora10g> select spid from V$session s,v$process p,v$mystat m where s.paddr = p.addr and s.sid = m.sid and m.statistic# = 0;
SPID
------------
28863
5.进入到用户转储区udump目录，sql_trace生成的trace文件就在这个文件夹中生成
ora10g@secDB /home/oracle$ cd $ORACLE_BASE/admin/$ORACLE_SID/udump
6.使用第4步骤得到的spid得到对应的trace文件
$ ls -l | grep 28863
-rw-r----- 1 oracle oinstall 2.4K Sep 26 16:12 ora10g_ora_28863.trc
7.查看一下原汁原味的trace文件，细心查找一下上面我们运行过的三个SQL语句。有点乱，这时tkprof工具就派上用场了
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.trc
/oracle/app/oracle/admin/ora10g/udump/ora10g_ora_28863.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining Scoring Engine options
ORACLE_HOME = /oracle/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: asdlabdb01
Release: 2.6.18-128.el5
Version: #1 SMP Wed Dec 17 11:41:38 EST 2008
Machine: x86_64
Instance name: ora10g
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 28863, image: oracle@asdlabdb01 (TNS V1-V3)
*** 2009-09-26 16:12:16.005
*** ACTION NAME:() 2009-09-26 16:12:16.005
*** MODULE NAME:(SQL*Plus) 2009-09-26 16:12:16.005
*** SERVICE NAME:(SYS$USERS) 2009-09-26 16:12:16.005
*** SESSION ID:(525.2176) 2009-09-26 16:12:16.005
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563218755381 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563218755376
EXEC #3:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563218755807
=====================
PARSING IN CURSOR #2 len=22 dep=0 uid=30 ct=3 lid=30 tim=1224563222976558 hv=2763161912 ad='ccd964b0'
select count(*) from t
END OF STMT
PARSE #2:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976554
EXEC #2:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976654
FETCH #2:c=540917,e=527837,p=0,cr=37988,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223504525
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563223504782
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563223505075 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563223505071
EXEC #3:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223505269
STAT #2 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)'
STAT #2 id=2 cnt=3000001 pid=1 pos=1 bj=12662 p='TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)'
=====================
PARSING IN CURSOR #2 len=35 dep=0 uid=30 ct=42 lid=30 tim=1224563232033798 hv=310044142 ad='0'
alter session set sql_trace = false
END OF STMT
PARSE #2:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033795
EXEC #2:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033856
8.使用tkprof工具对上面的trace文件格式化后，SQL运行的统计信息尽收眼底。
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_28863.trc ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_28863.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
********************************************************************************
select count(*)
from
t
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.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.54 0.52 0 37988 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)
3000001 TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)
********************************************************************************
alter session set sql_trace = false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 30
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 2
Fetch 2 0.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.54 0.52 0 37988 0 3
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
4 user SQL statements in session.
0 internal SQL statements in session.
4 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_28863.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
4 user SQL statements in trace file.
0 internal SQL statements in trace file.
4 SQL statements in trace file.
3 unique SQL statements in trace file.
47 lines in trace file.
13 elapsed seconds in trace file.
-- The End --
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/519536/viewspace-616240/，如需转载，请注明出处，否则将追究法律责任。
转载于:http://blog.itpub.net/519536/viewspace-616240/
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
