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

痛定思痛。 2022-09-26 02:19 439阅读 0赞

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