ITPub博客

首页 > 数据库 > Oracle > 浅谈Oracle SQL trace

浅谈Oracle SQL trace

Oracle 作者:zhongshanyang 时间:2015-12-06 19:03:29 0 删除 编辑

在生产环境中,当数据库运行异常缓慢的时候,DBA同学们都会想冲进数据库内部看看sql到底如何运行,为何语句执行的如此缓慢?在我的生产环境中,经常有多表关联查询语句运行缓慢,多数是I/O等待的问题,因而我第一步会去看sql的执行计划是否出现了问题,其次就会用到sql trace工具来跟踪下sql的实际运行情况!

一:使用sql_trace
1:产生select语句的trace文件,一般会使用tracefile_identifier给trace文件起一个标识性的名称,便于查找

  1. [oracle@dg53 ~]$ sqlplus /nolog  
  2. SQL*Plus: Release 10.2.0.1.0 - Production on Fri Jun 8 11:53:36 2012  
  3. Copyright (c) 1982, 2005, Oracle.  All rights reserved.  
  4.  
  5. SQL> conn hr/hr  
  6. Connected.  
  7.  
  8. SQL> alter session set tracefile_identifier='hr_trace01';  
  9. Session altered.  
  10.  
  11. SQL> alter session set sql_trace=true;  
  12. Session altered.  
  13.  
  14. SQL> select salary,last_name from employees where employee_id=100;  
  15.  
  16.     SALARY LAST_NAME  
  17. ---------- -------------------------  
  18.       2000 King  
  19.  
  20. SQL> alter session set sql_trace=false;  
  21. Session altered.  
  22.  
  23. [oracle@dg53 ~]$ cd $ORACLE_BASE/admin/orcl10g/udump/  
  24. [oracle@dg53 udump]$ ll *hr*  
  25. -rw-r----- 1 oracle oinstall 89149 Jun  8 11:58 dg53_ora_10498_hr_trace01.trc 

2:使用tkprof工具对产生的trace文件进行过滤,抽取有用的信息,默认的trace文件输出太多信息!
sys=no代表不输出trace文件中所有sys用户的操作,包含用户sql语句引起的递归sql,使输出变的简洁;
aggragate=yes代表相同的sql语句在输入文件中做合并,使输出变的简洁;


[oracle@dg53 udump]$ tkprof dg53_ora_10498_hr_trace01.trc /home/oracle/trace01.log   aggregate=yes sys=no explain=hr/hr

[oracle@dg53 udump]$ wc -l dg53_ora_10498_hr_trace01.trc 
1097 dg53_ora_10498_hr_trace01.trc
[oracle@dg53 udump]$ wc -l /home/oracle/trace01.log 
137 /home/oracle/trace01.log

[oracle@dg53 ~]$ cat trace01.log 
TKPROF: Release 10.2.0.1.0 - Production on Fri Jun 8 12:06:23 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: dg53_ora_10498_hr_trace01.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
********************************************************************************
alter session set sql_trace=true

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.01          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.01          0          0          0           0

Misses in library cache during parse: 0
Misses in library cache during execute: 1 
Optimizer mode: ALL_ROWS
Parsing user id: 55  (HR)
********************************************************************************
select salary,last_name 
from
 employees where employee_id=100

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.01          2          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.04          2          2          0           1

Misses in library cache during parse: 1  (表示该sql语句执行了硬解析,未在库缓存中命中)
Optimizer mode: ALL_ROWS    (CBO的模式,表示尽可能快的输出全部的结果集,oltp系统分页条
件下普遍使用first_rows)
Parsing user id: 55  (HR)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=2 pw=0 time=18516 us)
      1   INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=1 pw=0 time=11715 us)(object id

51859)

Rows     Execution Plan (因为在使用tkprof分析trace文件的时候使用了explain参数,所以有执行计划输出)
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'EMPLOYEES' 
              (TABLE)
      1    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_EMP_ID_PK' (INDEX 
               (UNIQUE))

********************************************************************************
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: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55  (HR)

********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.02          0          0          0           0
Execute      3      0.00       0.01          0          0          0           0
Fetch        2      0.00       0.01          2          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.00       0.05          2          2          0           1

Misses in library cache during parse: 2
Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       21      0.01       0.02          0          0          0           0
Execute    122      0.03       0.03          0          0          0           0
Fetch      173      0.01       0.16         18        419          0         633
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      316      0.06       0.22         18        419          0         633

Misses in library cache during parse: 15
Misses in library cache during execute: 15

    3  user  SQL statements in session.
  122  internal SQL statements in session.
  125  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: dg53_ora_10498_hr_trace01.trc
Trace file compatibility: 10.01.00
Sort options: default

       1  session in tracefile.
       3  user  SQL statements in trace file.
     122  internal SQL statements in trace file.
     125  SQL statements in trace file.
      18  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           HR.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
    1097  lines in trace file.
      38  elapsed seconds in trace file.


二:10046事件
10046事件按照收集的信息内容,分为4个级别
level1: 等同于前面介绍的sql_trace
level4: 在level1的基础上增加绑定变量的收集
level8: 在level1的基础上增加等待事件的收集
level12: 等同于level4+level8(所以这个级别用的最普遍)

    SQL> alter session set tracefile_identifier='hr_trace02';  
  1. Session altered.  
  2.  
  3. SQL> var id number  
  4. SQL> exec :id :200 
  5. PL/SQL procedure successfully completed.  
  6.  
  7. SQL> alter session set events '10046 trace name context forever,level 12';  
  8. Session altered.  
  9.  
  10. SQL> select salary from employees where employee_id=:id;  
  11.  
  12.     SALARY  
  13. ----------  
  14.       4400  
  15.  
  16. SQL> alter session set events '10046 trace name context off';  
  17. Session altered.  
  18.  
  19. [oracle@dg53 udump]$ ll *hr*  
  20. -rw-r----- 1 oracle oinstall 89149 Jun  8 11:58 dg53_ora_10498_hr_trace01.trc  
  21. -rw-r----- 1 oracle oinstall  3034 Jun  8 14:28 dg53_ora_18857_hr_trace02.trc  
  22.  
  23. [oracle@dg53 udump]$ tkprof dg53_ora_18857_hr_trace02.trc /home/oracle/trace02.log   
  24.  
  25. sys=no aggregate=yes explain=hr/hr 


[oracle@dg53 udump]$ cat /home/oracle/trace02.log (tkprof处理后将看不到绑定变量信息)
TKPROF: Release 10.2.0.1.0 - Production on Fri Jun 8 14:31:46 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: dg53_ora_18857_hr_trace02.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
********************************************************************************

alter session set events '10046 trace name context forever,level 12'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      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        1      0.00       0.00          0          0          0           0 

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 55  (HR)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

select salary 
from
 employees where employee_id=:id

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.01          1          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.01          1          2          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 55  (HR)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=1 pw=0 time=16216 us)
      1   INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=128 us)(object id 51859)
 

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'EMPLOYEES' 
              (TABLE)
      1    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_EMP_ID_PK' (INDEX 
               (UNIQUE))

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

alter session set events '10046 trace name context off'

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
Optimizer mode: ALL_ROWS
Parsing user id: 55  (HR)

********************************************************************************

OVERALL TOTALS FOR ALL NON-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          0          0           0
Fetch        2      0.00       0.01          1          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.00       0.01          1          2          0           1

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       5        0.00          0.00
  SQL*Net message from client                     5       10.32         15.71
  db file sequential read                         1        0.01          0.01
 

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

    3  user  SQL statements in session.
    0  internal SQL statements in session.
    3  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: dg53_ora_18857_hr_trace02.trc
Trace file compatibility: 10.01.00
Sort options: default

       0  session in tracefile.
       3  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  SQL statements in trace file.
       3  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           HR.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
      46  lines in trace file.
      15  elapsed seconds in trace file.
 

[oracle@dg53 udump]$ head -30 dg53_ora_18857_hr_trace02.trc
/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc
 

*** TRACE DUMP CONTINUED FROM FILE

/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc ***

*** 2012-06-08 14:28:26.627
=====================
PARSING IN CURSOR #2 len=68 dep=0 uid=55 oct=42 lid=55 tim=1307750885378875

hv=2804619552 ad='2349fc80'
alter session set events '10046 trace name context forever,level 12'
END OF STMT
EXEC #2:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750885378870
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0

obj#=-1 tim=1307750885378967
WAIT #2: nam='SQL*Net message from client' ela= 126 driver id=1650815232 #bytes=1 p3=0

obj#=-1 tim=1307750885379118
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0

obj#=-1 tim=1307750885379173
WAIT #0: nam='SQL*Net message from client' ela= 5384831 driver id=1650815232 #bytes=1

p3=0 obj#=-1 tim=1307750890764022
=====================
PARSING IN CURSOR #3 len=50 dep=0 uid=55 oct=3 lid=55 tim=1307750890764197 
 hv=2273608758 ad='2349fa44'
select salary from employees where employee_id=:id
END OF STMT
PARSE #3:c=0,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764193
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=b7fb9ad0  bln=22  avl=02  flg=05
  value=200
EXEC #3:c=0,e=334,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764600
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 
 obj#=-1 tim=1307750890764630
WAIT #3: nam='db file sequential read' ela= 13073 file#=5 block#=84 blocks=1 obj#=51857
 tim=1307750890780678
FETCH #3:c=5999,e=16119,p=1,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=1307750890780769
 


 三:其他用户的会话进行跟踪
1:针对其他用户的sql_trace跟踪

  1. C:\>sqlplus hr/hr@192.168.123.13:1521/dg53.yang.com  
  2. SQL*Plus: Release 11.2.0.3.0 Production on Fri Jun 8 14:46:33 2012  
  3. Copyright (c) 1982, 2011, Oracle.  All rights reserved.  
  4.  
  5. Connected to:  
  6. Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production  
  7. With the Partitioning, OLAP and Data Mining options  
  8.  
  9. SQL> show user;  
  10. USER is "HR"  
  11.  
  12. SQL> show user;  
  13. USER is "SYS"  
  14. SQL> select sid,serial# from v$session where username='HR';  
  15.  
  16.        SID    SERIAL#  
  17. ---------- ----------  
  18.        129         55  
  19.  
  20. SQL> select p.spid from v$session s,v$process p where s.paddr=p.addr and s.sid=129 and   
  21.  
  22. s.serial#=55;  
  23.  
  24. SPID  
  25. ------------  
  26. 20844  
  27.  
  28. SQL> exec dbms_system.set_sql_trace_in_session(129,55,true);  
  29. PL/SQL procedure successfully completed.  
  30.  
  31. SQL> select distinct department_id from departments;  
  32.  
  33. DEPARTMENT_ID  
  34. -------------  
  35.            10  
  36.            20  
  37.            30  
  38.            40  
  39.  
  40. SQL> exec dbms_system.set_sql_trace_in_session(129,55,false);  
  41. PL/SQL procedure successfully completed.  
  42.  
  43. [oracle@dg53 udump]$ tkprof dg53_ora_20844.trc /home/oracle/trace03.log sys=no   
  44.  
  45. aggregate=yes explain=hr/hr 

2:针对其他会话的10046事件的开启和关闭

  1. SQL> exec dbms_monitor.session_trace_enable(129,55,waits=>true,binds=>true);  
  2. PL/SQL procedure successfully completed.  
  3.  
  4. SQL> exec dbms_monitor.session_trace_disable(129,55);  
  5. PL/SQL procedure successfully completed 

 本文以《让oracle跑的更快》为指导,如有雷同,不胜荣幸!

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/14293828/viewspace-1867081/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论

注册时间:2015-01-18

  • 博文量
    132
  • 访问量
    428394