[Oracle] SQL优化及性能诊断好帮手——SQL_TRACE

【SQL_TRACE】SQL优化及性能诊断好帮手

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 --