About Oracle TraceFile

Oracle Trace File文件(SQL优化方案)

Trace file（追踪文件)是以trc为后续的文本文件,它记录了各种sql操作及所消耗的时间等,根据trace文件我们就可以了解哪些sql导致了系统的性能瓶颈，进而采取恰当的方式调优.

--# 1、查看sql_Trace value
SQL> show parameter sql_trace;
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
sql_trace                            boolean     FALSE
--value为FALSE时不会记录trace文件。

--# 2、让系统记录trace file文件 (考虑级别：会话或者系统)
--sqlplus：
SQL> alter session set sql_trace=TRUE;
--或者
SQL> execute dbms_session.set_sql_trace(TRUE);
--或者
SQL> alter system set sql_trace=TRUE;


SQL> alter session set sql_trace=FALSE;
--或者
SQL> execute dbms_session.set_sql_trace(FALSE);
--或者
SQL> alter system set sql_trace=FALSE;

--工具
select b.spid,a.sid,a.serial#,a.machine from v$session a,v$process b where a.paddr = b.addr and a.machine='PANDA-OA\IT-13';
---生成Trace文件
exec dbms_system.set_sql_trace_in_session(sid，serial#,true);
--sql语句
exec dbms_system.set_sql_trace_in_session(sid，serial#,false);

--SQL_TRACE的增强 事件10046

ALTER SESSION|SYSTEM SET EVENTS='10046 trace name context forever, level 12'；
--sql语句
ALTER SESSION|SYSTEM SET EVENTS='10046 trace name context off'；

--# 3、获取trace file 文件路径
--跟踪文件（Trace File）一般位于“user_dump_dest”参数所指定的目录中，具体路径可以通过几种方式查询获得。
--1）通过user_dump_dest获取
CREATE OR REPLACE VIEW VW_SQL_TRACE_NAME_LHR AS 
SELECT D.VALUE || '/' || LOWER(RTRIM(I.INSTANCE, CHR(0))) || '_ora_' ||
	   P.SPID || '.trc' TRACE_FILE_NAME
  FROM (SELECT P.SPID
		  FROM V$MYSTAT M, V$SESSION S, V$PROCESS P
		 WHERE M.STATISTIC# = '1'
		   AND S.SID = M.SID
		   AND P.ADDR = S.PADDR) P,
	   (SELECT T.INSTANCE
		  FROM V$THREAD T, V$PARAMETER V
		 WHERE V.NAME = 'thread'
		   AND (V.VALUE = '0' OR TO_CHAR(T.THREAD#) = V.VALUE)) I,
	   (SELECT VALUE FROM V$PARAMETER WHERE NAME = 'user_dump_dest') D; #trace 文件所在默认路径
	   
CREATE OR REPLACE PUBLIC SYNONYM SYN_TRACENAME_LHR FOR VW_SQL_TRACE_NAME_LHR;

SQL> SELECT * FROM VW_SQL_TRACE_NAME_LHR T;

TRACE_FILE_NAME
--------------------------------------------------------------------------------
/oracle/app/product/12.1.0/db_1/rdbms/log/edwdb2_ora_9150.trc

--2）Oracle 11g可以通过查询V$DIAG_INFO获取：
SELECT VALUE FROM V$DIAG_INFO WHERE NAME LIKE '%Default%';

--# 4、查看trace file 文件内容
--用oracle自带的工具TKPROF转化后再查看trace文件。

SQL> tkprof /oracle/app/product/12.1.0/db_1/rdbms/log/edwdb2_ora_9150.trc /tmp/t_call_qd.tkp sys=no waits=yes
/*
相关说明:
sys=no：表示阻止所有以sys用户执行的sql被显示出来，默认为YES
waits=yes|no (Record summary for any wait events found in the trace file|记录跟踪文件中发现的任何等待事件的摘要).
aggregate=yes|no 若用户指定AGGREGATE=NO，TKPROF将不会对相同SQL文本的多个用户进行汇总
*/

--文件分析
/*
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          2         34          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch   200001      4.72      22.09      80613      37207         14     3000000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   200003      4.72      22.09      80615      37241         14     3000000

格式化后文件格式说明：
CALL： 每次SQL语句的处理都分成三个部分（Parse，Execute,Fetch）
	Parse： 这步将SQL语句转换成执行计划，包括检查是否有正确的授权和所需要用到的表、列以及其他引用到的对象是否存在。
	Execute： 这步是真正的由Oracle来执行语句。对于insert、update、delete操作，这步会修改数据，对于select操作,这步就只是确定选择的记录。
	Fetch： 返回查询语句中所获得的记录，这步只有select语句会被执行。
COUNT: 这个语句被parse、execute、fetch的次数。
CPU： 这个语句对于所有的parse、execute、fetch所消耗的cpu的时间，以秒为单位。
ELAPSED： 这个语句所有消耗在parse、execute、fetch的总的时间。
DISK： 从磁盘上的数据文件中物理读取的块的数量。一般来说更想知道的是正在从缓存中读取的数据而不是从磁盘上读取的数据。
QUERY： 在一致性读模式下，所有parse、execute、fetch所获得的buffer的数量。 一致性模式的buffer是用于给一个长时间运行的事务提供一个一致性读的快照，缓存实际上在头部存储了状态。
CURRENT： 在current模式下所获得的buffer的数量。一般在current模式下执行insert、update、delete操作都会获取buffer。在current模式下如果在高速缓存区发现有新的缓存足够给当前的事务使用，则这些buffer都会被读入了缓存区中。
ROWS: 所有SQL语句返回的记录数目，但是不包括子查询中返回的记录数目。对于select语句，返回记录是在fetch这步，对于insert、update、delete操作，返回记录则是在execute这步。

问题判断：(参考)
1. query+current/rows 平均每行所需的block数，太大的话（超过20）SQL语句效率太低
2. Parse count/Execute count parse count应尽量接近1，如果太高的话，SQL会进行不必要的reparse。要检查Pro*C程序的MAXOPENCURSORS是不是太低了，或不适当的使用的RELEASE_CURSOR选项
3. rows Fetch/Fetch Fetch Array的大小，太小的话就没有充分利用批量Fetch的功能，增加了数据在客户端和服务器之间的往返次数。在Pro*C中可以用prefetch=NN,Java/JDBC中可调用SETROWPREFETCH,在PL/SQL中可以用BULK COLLECT,SQLPLUS中的arraysize(缺省是15)　　
4. disk/query+current 磁盘IO所占逻辑IO的比例，太大的话有可能是db_buffer_size过小(也跟SQL的具体特性有关)　　
5. elapsed/cpu 太大表示执行过程中花费了大量的时间等待某种资源　　
6. cpu　OR　elapsed 太大表示执行时间过长，或消耗了大量的CPU时间，应该考虑优化
7.　执行计划中的Rows 表示在该处理阶段所访问的行数，要尽量减少
*/
============================================================================================================================================
/*
（一）SQL_TRACE
SQL_TRACE是Oracle提供的用于进行SQL跟踪的手段，是强有力的辅助诊断工具。在日常的数据库问题诊断和解决中，SQL_TRACE是非常常用的方法。可以设置SQL_TRACE为TRUE，但是一般不推荐在全局指定为TRUE，只建议在会话级别指定。若在全局设定则对性能会造成较大影响。
（二）诊断事件
Oracle为数据库提供了多种的诊断工具，诊断事件（Event）是其中一种非常实用的方法，它能使DBA可以方便地转储数据库各种结构及跟踪特定事件的发生过程。
通过如下的脚本可以获取所有的诊断事件列表：*/
 DECLARE
   ERR_MSG VARCHAR2(32767);
 BEGIN
   DBMS_OUTPUT.ENABLE('');
   FOR ERR_NUM IN 10000 .. 10999 LOOP
     ERR_MSG := SQLERRM(-ERR_NUM);
     IF ERR_MSG NOT LIKE '%Message ' || ERR_NUM || ' not found%' THEN
       DBMS_OUTPUT.PUT_LINE(ERR_MSG);
     END IF;
  END LOOP;
END;
/
/*
在Linux系统下诊断事件的消息文件放在目录：$ORACLE_HOME/rdbms/mesg/oraus.msg。oraus.msg文件属于文本文件，可以直接打开查看。
诊断事件可以像普通的ORA错误一样采用oerr命令来查询，如下所示：*/
 [oracle@orclalhr ~]$ oerr ora 10046
 10046, 00000, "enable SQL statement timing"
 // *Cause:
 // *Action:
 [oracle@orclalhr ~]$ oerr ora 10053
 10053, 00000, "CBO Enable optimizer trace"
 // *Cause:
 // *Action:
 [oracle@orclalhr ~]$ oerr ora 10704
10704, 00000, "Print out information about what enqueues are being obtained"
// *Cause:  When enabled, prints out arguments to calls to ksqcmi and
//          ksqlrl and the return values.
// *Action: Level indicates details:
//   Level: 1-4: print out basic info for ksqlrl, ksqcmi
//          5-9: also print out stuff in callbacks:  ksqlac, ksqlop
//          10+: also print out time for each line
/*
设置诊断事件有两种方法，一种是在pfile参数文件中设置事件，这样数据库在OPEN后，将影响到所有的会话。设置格式如下：
event="eventnumber trace name eventname [forever,] [level levelnumber] : ......."
通过冒号（:）符号，可以连续设置多个事件，也可以通过连续使用event来设置多个事件。如：*/
event = "10248 trace name context forever, level 10:10249 trace name context forever, level 10"
--或者分开写，如：
event="10248 trace name context forever, level 10"
event="10249 trace name context forever, level 10"
/*
另一种方法是在会话过程中使用ALTER SESSION SET EVENTS命令，只对当前会话有影响。设置格式如下：
ALTER SESSION|SYSTEM SET EVENTS '[eventnumber|immediate] trace name eventname [forever] [, level levelnumber] : .......' 
通过英文冒号（:）符号，可以连续设置多个事件，也可以通过连续使用ALTER SESSION SET EVENTS来设置多个事件，如： */
ALTER SYSTEM SET 
           EVENTS='10325 trace name context forever, level 10','10015 trace name context forever, level 1' 
           COMMENT='Debug tracing of control and rollback';
--或：
ALTER SYSTEM SET EVENTS='10325 trace name context forever, level 10:10015 trace name context forever, level 1';
/*
格式说明：
 eventnumber指触发dump的事件号，事件号可以是Oracle错误号（出现相应错误时跟踪指定的事件）或Oralce内部事件号，内部事件号在10000到10999之间，不能与immediate关键字同用。
 immediate关键字表示命令发出后，立即将指定的结构dump到跟踪文件中，这个关键字只用在ALTER SESSION语句中，并且不能与eventnumber、forever关键字同用。
 trace name是关键词，trace name位于第二、三项，除它们外的其它限定词是供Oracle内部开发组用的。
 eventname指事件名称，即要进行dump的实际结构名。若eventname为context，则指根据内部事件号进行跟踪。
 forever关键字表示事件在实例或会话的周期内保持有效状态，不能与immediate同用。
 level为事件级别关键字。但在dump错误栈（errorstack）时不存在级别。level通常位于1-10之间（10046有时用到12），10意味着转储事件所有的信息。例如当转储控制文件时，level 1表示转储控制文件头，而level 10表明转储控制文件全部内容。
 levelnumber表示事件级别号，一般从1到10，1表示只dump结构头部信息，10表示dump结构的所有信息。
 转储所生成的trace文件在user_dump_dest初始化参数指定的位置。
 移除所有的诊断事件（Event）：*/
ALTER SYSTEM RESET EVENT SCOPE=SPFILE SID='*' ;
--如果设置了诊断事件（Event），那么如何知道在系统中设置了哪些诊断事件（Event）呢？如果事件是在pfile文件中设置的，那么可以用“SHOW PARAMETER EVENT”来查看。
--如果是通过“ALTER SYSTEM|SESSION”来设置的，那么可以使用如下的SQL来查看：
 SET SERVEROUTPUT ON SIZE 1000000
 DECLARE
   EVENT_LEVEL NUMBER;
 BEGIN
   FOR I IN 10000 .. 99999 LOOP
     SYS.DBMS_SYSTEM.READ_EV(I, EVENT_LEVEL);
     IF (EVENT_LEVEL > 0) THEN
       DBMS_OUTPUT.PUT_LINE('Event ' || TO_CHAR(I) || ' set at level ' ||TO_CHAR(EVENT_LEVEL));
     END IF;
  END LOOP;
END;
/

--但是，10046和10053事件不能通过这种方式查询，只能通过oradebug来查询，如下：
SYS@orclasm > oradebug setmypid
SYS@orclasm > oradebug eventdump system
SYS@orclasm > oradebug eventdump session
/*
设置诊断事件需要注意的是，即可以使用“ALTER SYSTEM EVENTS”，也可以使用“ALTER SYSTEM EVENT”，它们的区别在如下2点：
①　EVENTS可以动态修改，可以使用“ALTER SESSION”或“ALTER SYSTEM”设置，只影响内存不影响参数文件
②　EVENT不能动态修改，只能使用“ALTER SYSTEM”或在参数文件里设置，必须重启库方可生效
另外，“ALTER SYSTEM”会记录到告警日志中，“ALTER SESSION”不会记录在告警日志中。
 */
---
/*
Oracle中，最常用的10046及10053诊断事件的区别:
10046事件是Oracle提供的内部事件，是对SQL_TRACE的增强。Oracle的10046事件，可以跟踪应用程序所执行的SQL语句，并且得到其解析次数、执行次数、CPU使用时间等信息。这对DBA来分析、定位数据库性能问题是非常有用的。
10046事件可分成不同的级别（LEVEL），分别追踪记录不同程度的有用信息。对于这些不同的级别，应当注意的是向下兼容的，即高一级的TRACE信息包含低于此级的所有信息。
10046事件可以设置以下级别:
①　level 0：禁用SQL_TRACE，等价于SQL_TRACE=FALSE
②　level 1：启用标准的SQL_TRACE功能跟踪SQL语句，包括解析、执行、提取、提交、回滚、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其它一些额外信息，等价于SQL_TRACE=TRUE
③　level 4：Level 1 + 包括绑定变量（Bind Values）的详细信息
④　level 8：Level 1 + 包括等待事件
⑤　level 12：包括绑定变量与等待事件，包含Level 1 + Level 4 + Level 8
10053事件是最常用的Oracle优化器跟踪Trace。10053事件解析优化器为什么选择某个执行计划但并不记录这个执行计划到底运行地如何。10046事件并不解释优化器的工作，但它记录了在SQL解析阶段所遇到的等待事件和所消耗的CPU等资源，以及执行阶段的各项指标。需要注意的是，如果一个SQL语句已经被解析过，那么就不会生成10053的trace文件，但10046的trace文件可以重复生成。
简而言之，10046事件记录SQL如何运行，而10053记录优化器为什么为这个SQL选择某个执行计划。
*/

---
/*
Oracle中，跟踪会话执行语句的方法有哪几种？

因为TRACE的目标范围不同，所以导致必须使用不同的方法：
	若作用于数据库全局的，则改初始化参数。
	若只作用于当前会话的，则就用ALTER SESSION命令。
	若作用于其它会话的，则就用DBMS_SYSTEM包。

①　SQL_TRACE参数设置：非常传统的方法
SQL_TRACE可以作为初始化参数在全局启用，也可以通过命令行方式在具体会话启用。在参数文件（PFILE/SPFILE）中指定：SQL_TRACE=TRUE或ALTER SYSTEM SET SQL_TRACE=TRUE;。
通过在全局启用SQL_TRACE可以跟踪到所有后台进程及所有用户进程的活动，通过跟踪文件的实时变化，可以清晰地看到各个进程之间的紧密协调。需要注意的是，在全局启用SQL_TRACE会产生大量trace文件，很容易耗尽磁盘空间，这通常会导致比较严重的性能问题，所以在生产环境中要谨慎使用，并且及时关闭。
在大多数时候使用SQL_TRACE跟踪的都是当前会话的进程。通过跟踪当前进程可以发现当前操作的后台数据库递归活动，这在研究数据库新特性时尤其有效，在研究SQL执行，发现后台错误等方面也非常有用。
在会话级启用和停止SQL_TRACE的方式如下所示：
启用当前SESSION的跟踪: */
SQL> ALTER SESSION SET SQL_TRACE=TRUE;
Session altered.
--此时的SQL操作将被跟踪:
SQL> SELECT COUNT(*) FROM DBA_USERS;
  COUNT(*)
----------
        44
--结束跟踪:
SQL> ALTER SESSION SET SQL_TRACE=FALSE;
Session altered.
--在很多时候需要跟踪其他用户的进程，而不是当前用户，这可以通过Oracle提供的系统包DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION来完成。
--通过V$SESSION可以获得SID、SERIAL#等信息，获得进程信息，选择需要跟踪的进程：
 SQL> col spid for a8
 SQL> col spid for a10
 SQL> col username for a10
 SQL> col tracefile for a80
 SQL> SELECT S.INST_ID, S.SID, S.SERIAL#, P.SPID, S.USERNAME, P.TRACEFILE
       FROM GV$SESSION S, GV$PROCESS P
      WHERE P.ADDR = S.PADDR
        AND S.INST_ID = P.INST_ID
        AND S.USERNAME IS NOT NULL;
   INST_ID        SID    SERIAL# SPID       USERNAME   TRACEFILE
---------- ---------- ---------- ---------- ---------- ---------------------------------------------------------------------------
         1        144        293 37302      SYS        /u02/app/oracle/diag/rdbms/oratest/oratest/trace/oratest_ora_37302_lhr.trc
         1        146       1557 37340      SYS        /u02/app/oracle/diag/rdbms/oratest/oratest/trace/oratest_ora_37340.trc
         1         26        321 37380      LHR        /u02/app/oracle/diag/rdbms/oratest/oratest/trace/oratest_ora_37380.trc
         1        152       3243 37400      SYS        /u02/app/oracle/diag/rdbms/oratest/oratest/trace/oratest_ora_37400.trc
--设置跟踪SID为26的会话:
SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(26,321,TRUE);
PL/SQL procedure successfully completed.
--可以等候片刻，等待SID为26的会话执行SQL，完成后，停止跟踪：
SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(26,321,FALSE);
PL/SQL procedure successfully completed.
/*
②　使用10046事件
全局设定：参数文件中指定：EVENT="10046 TRACE NAME CONTEXT FOREVER,LEVEL 12"
或者：
SQL> ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';--启用
SQL> ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT OFF';--关闭
*/
--当前会话设定：
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
SQL> --执行SQL语句
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

--在Oracle 11g中还可以对单个SQL打开10046事件跟踪，命令如下所示：
ALTER SYSTEM SET EVENTS 'SQL_TRACE [SQL:&&SQL_ID] WAIT=TRUE,BIND=TRUE,PLAN_STAT=ALL_EXECUTIONS,LEVEL=12';
--关闭单个SQL的跟踪命令如下所示：
ALTER SYSTEM SET EVENTS 'SQL_TRACE [SQL:&&SQL_ID] OFF';
--若要针对每个新连接的会话生成10046跟踪文件，则可以使用登录触发器。如下的代码是跟踪LHR用户的信息，在用户LHR登录数据库系统时会启动10046跟踪。
CREATE OR REPLACE TRIGGER TRI_SET_TRACE_LHR
AFTER LOGON ON DATABASE
WHEN (USER IN ('LHR'))
DECLARE
BEGIN
    EXECUTE IMMEDIATE 'ALTER SESSION SET STATISTICS_LEVEL=ALL';
    EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED';
    EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
END TRI_SET_TRACE_LHR;

--③　DBMS_SESSION包：只能跟踪当前会话，不能指定会话
--跟踪当前会话：
SQL> EXEC DBMS_SESSION.SET_SQL_TRACE(TRUE);
SQL> --执行SQL
SQL> EXEC DBMS_SESSION.SET_SQL_TRACE(FALSE);
--DBMS_SESSION.SET_SQL_TRACE相当于ALTER SESSION SET SQL_TRACE，从生成的TRACE文件可以明确地看ALTER SESSION SET SQL_TRACE语句。
--使用DBMS_SESSION.SESSION_TRACE_ENABLE过程，不仅可以看到等待事件信息还可以看到绑定变量信息，相当于“ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';”语句：
SQL> EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE,BINDS=>TRUE);
SQL> --执行SQL
SQL> EXEC DBMS_SESSION.SESSION_TRACE_DISABLE(); 
--④　DBMS_SYSTEM包
--使用DBMS_SYSTEM.SET_EV设置10046事件：
SQL> EXEC DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');--启用跟踪
SQL> EXEC DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');--结束跟踪
--⑤　DBMS_MONITOR包
--该包是从Oracle 10g开始提供的，功能非常强大。可在模块级别、动作级别、客户端级别、数据库级别、会话级别进行跟踪，Oracle官方支持。
--跟踪当前会话：
SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE;
SQL> --执行SQL
SQL> EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE;
--跟踪其他会话：
SQL>EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#,WAITS=>TRUE,BINDS=>TRUE);
SQL> --执行SQL
SQL>EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#);
--⑥　oradebug
--这是SQL*Plus的工具，需要提供OSPID或者Oracle PID。
--跟踪当前会话：
 SQL> oradebug setmypid;
 Statement processed.
 SQL> oradebug unlimit;
 Statement processed.
 SQL> oradebug event 10046 trace name context forever,level 12;
 Statement processed.
 SQL> --执行SQL
 SQL> oradebug tracefile_name
 SQL> oradebug event 10046 trace name context off;
Statement processed.
--跟踪其他会话：
SQL> select spid,pid2  from v$process
    where addr in (select paddr from v$session where sid=(select distinct sid from v$mystat));
SPID                PID
------------ ----------
1457                 313
SQL> oradebug setospid 1457;
Statement processed.
--或者：
SQL> oradebug setorapid 313;
Statement processed.
SQL> oradebug unlimit;
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 12;
Statement processed.
SQL> oradebug tracefile_name
SQL> oradebug event 10046 trace name context off;
Statement processed.
--使用oradebug help可以查看oradebug的命令帮助。

参考链接