在生产环境中,当数据库运行异常缓慢的时候,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 [oracle@dg53 ~]$ cat trace01.log Trace file: dg53_ora_10498_hr_trace01.trc ******************************************************************************** call count cpu elapsed disk query current rows Misses in library cache during parse: 0 call count cpu elapsed disk query current rows Misses in library cache during parse: 1 (表示该sql语句执行了硬解析,未在库缓存中命中) Rows Row Source Operation 51859) Rows Execution Plan (因为在使用tkprof分析trace文件的时候使用了explain参数,所以有执行计划输出) ******************************************************************************** call count cpu elapsed disk query current rows Misses in library cache during parse: 1 ******************************************************************************** call count cpu elapsed disk query current rows Misses in library cache during parse: 2 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows Misses in library cache during parse: 15 3 user SQL statements in session. 1 session in tracefile. |
二:10046事件
10046事件按照收集的信息内容,分为4个级别
level1: 等同于前面介绍的sql_trace
level4: 在level1的基础上增加绑定变量的收集
level8: 在level1的基础上增加等待事件的收集
level12: 等同于level4+level8(所以这个级别用的最普遍)
[oracle@dg53 udump]$ cat /home/oracle/trace02.log (tkprof处理后将看不到绑定变量信息) Trace file: dg53_ora_18857_hr_trace02.trc ******************************************************************************** alter session set events '10046 trace name context forever,level 12'
Misses in library cache during parse: 0 Elapsed times include waiting on following events: select salary call count cpu elapsed disk query current rows Misses in library cache during parse: 0 Rows Row Source Operation Rows Execution Plan Elapsed times include waiting on following events: alter session set events '10046 trace name context off' call count cpu elapsed disk query current rows Misses in library cache during parse: 0 ******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows Misses in library cache during parse: 0 Elapsed times include waiting on following events: OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows Misses in library cache during parse: 0 3 user SQL statements in session. 0 session in tracefile. [oracle@dg53 udump]$ head -30 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 hv=2804619552 ad='2349fc80' obj#=-1 tim=1307750885378967 obj#=-1 tim=1307750885379118 obj#=-1 tim=1307750885379173 p3=0 obj#=-1 tim=1307750890764022 |
三:其他用户的会话进行跟踪
1:针对其他用户的sql_trace跟踪
- C:\>sqlplus hr/hr@192.168.123.13:1521/dg53.yang.com
- SQL*Plus: Release 11.2.0.3.0 Production on Fri Jun 8 14:46:33 2012
- Copyright (c) 1982, 2011, Oracle. All rights reserved.
- Connected to:
- Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
- With the Partitioning, OLAP and Data Mining options
- SQL> show user;
- USER is "HR"
- SQL> show user;
- USER is "SYS"
- SQL> select sid,serial# from v$session where username='HR';
- SID SERIAL#
- ---------- ----------
- 129 55
- SQL> select p.spid from v$session s,v$process p where s.paddr=p.addr and s.sid=129 and
- s.serial#=55;
- SPID
- ------------
- 20844
- SQL> exec dbms_system.set_sql_trace_in_session(129,55,true);
- PL/SQL procedure successfully completed.
- SQL> select distinct department_id from departments;
- DEPARTMENT_ID
- -------------
- 10
- 20
- 30
- 40
- SQL> exec dbms_system.set_sql_trace_in_session(129,55,false);
- PL/SQL procedure successfully completed.
- [oracle@dg53 udump]$ tkprof dg53_ora_20844.trc /home/oracle/trace03.log sys=no
- aggregate=yes explain=hr/hr
2:针对其他会话的10046事件的开启和关闭
- SQL> exec dbms_monitor.session_trace_enable(129,55,waits=>true,binds=>true);
- PL/SQL procedure successfully completed.
- SQL> exec dbms_monitor.session_trace_disable(129,55);
- PL/SQL procedure successfully completed
本文以《让oracle跑的更快》为指导,如有雷同,不胜荣幸!
本文转自斩月博客51CTO博客,原文链接http://blog.51cto.com/ylw6006/895017如需转载请自行联系原作者
ylw6006