浅谈Oracle SQL trace

在生产环境中，当数据库运行异常缓慢的时候，DBA同学们都会想冲进数据库内部看看sql到底如何运行，为何语句执行的如此缓慢？在我的生产环境中，经常有多表关联查询语句运行缓慢，多数是I/O等待的问题，因而我第一步会去看sql的执行计划是否出现了问题，其次就会用到sql trace工具来跟踪下sql的实际运行情况！一：使用sql_trace
1:产生select语句的trace文件，一般会使用tracefile_identifier给trace文件起一个标识性的名称，便于查找

[Oracle@dg53 ~]$ sqlplus /nolog
SQL*Plus: Release 10.2.0.1.0 - Production on Fri Jun 8 11:53:36 2012
Copyright （c） 1982, 2005, Oracle. All rights reserved.
SQL> conn hr/hr
Connected.
SQL> alter session set tracefile_identifier="hr_trace01";
Session altered.
SQL> alter session set sql_trace=true;
Session altered.
SQL> select salary,last_name from employees where employee_id=100;
SALARY LAST_NAME
---------- -------------------------
2000 King
SQL> alter session set sql_trace=false;
Session altered.
[oracle@dg53 ~]$ cd $ORACLE_BASE/admin/orcl10g/udump/
[oracle@dg53 udump]$ ll *hr*
-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=truecall     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           0Misses 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=100call     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           1Misses 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=falsecall     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           0Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 （HR）********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     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           1Misses in library cache during parse: 2
Misses in library cache during execute: 1OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     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         633Misses 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.

Oracle使用带有输入和输出参数的存储过程Oracle真实案例之闪回区存储空间耗尽解决方法（ORA-19815解决方法）相关资讯 Oracle存储过程

Oracle存储过程拼接in语句 & 自定（今 09:21）
【PL/SQL系列】Oracle存储过程使用（04月23日）
Oracle存储过程及Java调用（05/28/2015 20:29:33）

Java调用Oracle存储过程返回多条结（04月29日）
Oracle中的存储过程简单应用（04月10日）
判断点是否落在面中的Oracle存储过（05/09/2015 09:39:30）

本文评论查看全部评论（0）

评论声明

尊重网上道德，遵守中华人民共和国的各项有关法律法规
承担一切因您的行为而直接或间接导致的民事或刑事法律责任
本站管理人员有权保留或删除其管辖留言中的任意内容