• 博客访问: 7792387
  • 博文数量: 798
  • 用 户 组: 普通用户
  • 注册时间: 2008-03-16 22:27
  • 认证徽章:
个人简介

Oracle ACE 总监,OCM联盟(ocmu.org)创始人,恩墨学院(enmoedu.com)创始人,ITPUB Oracle专题深入讨论版版主,资深Oracle数据库专家,北京大学理学硕士,获Oracle OCM 10g 11g认证,ACOUG核心成员,DATAGURU专家团成员,Blogger。Good luck.

文章分类

全部博文(798)

文章存档

2013年(1)

2012年(18)

2011年(156)

2010年(302)

2009年(309)

2008年(7)

2007年(5)

分类: Linux操作系统

2009-10-10 17:50:24

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 --
阅读(3065) | 评论(0) | 转发(0) |
给主人留下些什么吧!~~
评论热议
请登录后评论。

登录 注册