Oracle SQL Trace 和 10046 事件

Oracle SQL Trace 和 10046 事件 

 

一. SQL_TRACE

 

当SQL语句出现性能问题时，我们可以用SQL_TRACE来跟踪SQL的执行情况，通过跟踪，我们可以了解一条SQL或者PL/SQL包的运行情况，SQL_TRACE命令会将SQL执行的整个过程输出到一个trace文件中，我们可以读这个trace 文件来了解在这个SQL执行过程中Oracle 都做了哪些操作。

 

 

 

可以通过sql命令启动SQL_TRACE，或者在初始化参数里面。

 

 

 

SQL>alter session set sql_trace=true;

 

或者

 

SQL> alter database set sql_trace=true;

 

 

 

这两条命令的区别：

 

                在session级别设置，只对当前session进行跟踪，在实例级别，会对实例上所有的SQL做跟踪，这种方式跟踪的SQL太多，代价是非常大的，所有很少用。

 

 

 

如果是在初始化文件里面设置，只需要在参数文件里添加一个sql_trace 参数即可。

 

 

 

 

 

示例：

 

 

 

1.       确定当前的trace文件。

 

 

 

1.1   通过设置trace 文件标识

 

SQL> alter session set tracefile_identifier='安庆怀宁';

 

会话已更改。

 

 

 

设置标识的目的就是方便我们查找生成的trace文件。我们只需要在trace目录查找文件名里带有标识的文件即可。 在Oracle 10g中，SQL_TRACE生成的trace文件默认路劲是$ORACLE_BASE/admin/SID/udump. 

 

到了11g，trace 默认路径在：$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目录下.

 

 

 

1.2直接用如下SQL直接查出，当前的trace文件名。

 

/* Formatted on 2010/9/1 23:56:24 (QP5 v5.115.810.9015) */

 

SELECT      d.VALUE

 

         || '/'

 

         || LOWER (RTRIM (i.INSTANCE, CHR (0)))

 

         || '_ora_'

 

         || p.spid

 

         || '.trc'

 

            AS "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 t.thread# = TO_NUMBER (v.VALUE))) i,

 

         (SELECT   VALUE

 

            FROM   v$parameter

 

           WHERE   NAME = 'user_dump_dest') d;

 

 

 

SQL> SELECT    d.VALUE

 

  2        || '/'

 

  3        || LOWER (RTRIM (i.INSTANCE, CHR (0)))

 

  4        || '_ora_'

 

  5        || p.spid

 

  6        || '.trc' as "trace_file_name"

 

  7    FROM (SELECT p.spid

 

  8            FROM v$mystat m, v$session s, v$process p

 

  9          WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

 

 10        (SELECT t.INSTANCE

 

 11            FROM v$thread t, v$parameter v

 

 12          WHERE v.NAME = 'thread'

 

 13            AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

 

 14        (SELECT VALUE

 

 15            FROM v$parameter

 

 16          WHERE NAME = 'user_dump_dest') d;

 

 

 

trace_file_name

 

--------------------------------------------------------------------------------

 

d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048.trc

 

 

 

2.       启动SQL_TRACE

 

SQL> alter session set sql_trace=true;

 

会话已更改。

 

 

 

3.       进行相关事务操作

 

SQL> select * from t;

 

 

 

4.       关闭SQL_TRACE

 

SQL> alter session set sql_trace=false;

 

会话已更改。

 

 

 

注意，这里是显示的关闭SQL_TRACE，在session级别，也可以直接退出SQLPLUS来终止SQL_TRACE。

 

 

 

 

 

二． TKPROF 工具

 

                Oracle 官网的资料：

 

                                Using Application Tracing Tools

 

                        http://download.oracle.com/docs/cd/E11882_01/server.112/e10821/sqltrace.htm#PFGRF010

 

 

 

SQL_TRACE 生成最原始的trace文件的可读性比较差，所以通常我们使用tkprof 工具来处理trace文件。 Tkprof 工具是Oracle 自带的一个工具，用于处理原始的trace文件，它的作用主要是合并汇总trace文件中的一些项，规范化文件的格式，使文件更具有可读性。

 

 

注意：tkprof 工具只能用在处理SQL_TRACE和10046事件产生的trace，其他事件如10053不能处理。

 

 

 

                                http://blog.csdn.net/tianlesoftware/archive/2010/05/29/5632003.aspx

 

               

 

    刚才看了一些，也是比较粗糙，不详细，重新在整理一下。 Tkprof 是系统级别的，直接在系统下执行即可。先看一下tkprof的帮助文档：

 

 

 

C:/Users/Administrator.DavidDai>tkprof

 

Usage:

 tkprof tracefile outputfile [explain= ] [table= ]

 

              [print= ] [insert= ] [sys= ] [sort= ]

 

  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.

 

  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.

 

  print=integer    List only the first 'integer' SQL statements.

 

  aggregate=yes|no

 

  insert=filename  List SQL statements and data inside INSERT statements.

 

  sys=no           TKPROF does not list SQL statements run as user SYS.

 

  record=filename  Record non-recursive statements found in the trace file.

 

  waits=yes|no     Record summary for any wait events found in the trace file.

 

  sort=option      Set of zero or more of the following sort options:

 

    prscnt  number of times parse was called

 

    prscpu  cpu time parsing

 

    prsela  elapsed time parsing

 

    prsdsk  number of disk reads during parse

 

    prsqry  number of buffers for consistent read during parse

 

    prscu   number of buffers for current read during parse

 

    prsmis  number of misses in library cache during parse

 

    execnt  number of execute was called

 

    execpu  cpu time spent executing

 

    exeela  elapsed time executing

 

    exedsk  number of disk reads during execute

 

    exeqry  number of buffers for consistent read during execute

 

    execu   number of buffers for current read during execute

 

    exerow  number of rows processed during execute

 

    exemis  number of library cache misses during execute

 

    fchcnt  number of times fetch was called

 

    fchcpu  cpu time spent fetching

 

    fchela  elapsed time fetching

 

    fchdsk  number of disk reads during fetch

 

    fchqry  number of buffers for consistent read during fetch

 

    fchcu   number of buffers for current read during fetch

 

    fchrow  number of rows fetched

 

    userid  userid of user that parsed the cursor

 

 

 

这个帮助对tkprof工具的参数做了说明。

 

 

 

2.1  explain=user/password

 

    在trace文件中输入SQL的执行计划，需要注意的是，如果不使用explain，在trace 文件中我们看到的是SQL实际的执行路劲。 如果使用了explain，tkprof在trace文件中不但输入SQL的实际执行路径，还会生成该SQL的执行计划。

 

 

 

2.2 sys=no

 

                如果设置为yes，在trace 文件中将输入所有的SYS用户的操作，也包含用户SQL语句引发的递归SQL。

 

如果为no，则不输出这些信息。

 

 

 

不过默认情况下是yes，实际上设置为no后，trace文件具有更佳的可读性，因此一般在用tkprof工具时都手工的把该参数设置为no。

 

 

 

 

 

2.3 aggregate=yes|no

 

    默认情况下，tkprof工具将所有相同的SQL在输入文件中做合并，如果设置为no，则分别列出每个SQL的信息。一般合并后看起来比较简洁，如果需要查看每一个SQL单独的信息，可以把aggregate设置为no。

 

 

 

2.4 查看第一节中生成的trace文件

 

 

 

C:/Users/Administrator.DavidDai>cd d:/app/administrator/diag/rdbms/orcl/orcl/trace

 

C:/Users/Administrator.DavidDai>D:

 

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>tkprof orcl_ora_3048_安庆怀宁.trc 安徽安庆怀宁.txt sys=no

 

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

 

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

 

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>

 

 

 

生成的 安徽安庆怀宁.txt文件内容如下：

 

 

 

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

 

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

 

 

 

Trace file: orcl_ora_3048_安庆怀宁.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

 

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

 

# 以上文件头信息描述了tkprof的版本信息，以及报告中一些列的含义

 

 

 

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS   #非递归SQL语句

 

 

 

call     count       cpu    elapsed       disk      query    current        rows

 

------- ------  -------- ---------- ---------- ---------- ----------  ----------

 

Parse        4      0.01       0.03          0          0          0           0

 

Execute      5      0.00       0.00          0          0          0           2

 

Fetch       67      0.00       0.00          0        140          0         980

 

------- ------  -------- ---------- ---------- ---------- ----------  ----------

 

total       76      0.01       0.03          0        140          0         982

 

 

 

 

 

Misses in library cache during parse: 2  #shared pool 中没有命令，说明做了2次硬解析，软解析此处为0

 

Oracle SQL的硬解析和软解析

 

http://blog.csdn.net/tianlesoftware/archive/2010/04/08/5458896.aspx

 

 

 

Misses in library cache during execute: 1

 

 

 

 

 

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS   #递归SQL语句

 

 

 

call     count       cpu    elapsed       disk      query    current        rows

 

------- ------  -------- ---------- ---------- ---------- ----------  ----------

 

Parse        5      0.00       0.00          0          0          0           0

 

Execute     57      0.00       0.00          0          0          0           0

 

Fetch      113      0.00       0.00          0        176          0         110

 

------- ------  -------- ---------- ---------- ---------- ----------  ----------

 

total      175      0.00       0.00          0        176          0         110

 

 

 

Misses in library cache during parse: 0

 

 

 

    5  user  SQL statements in session.

 

   57  internal SQL statements in session.

 

   62  SQL statements in session.

 

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

 

Trace file: orcl_ora_3048_安庆怀宁.trc

 

Trace file compatibility: 11.1.0.7

 

Sort options: default

 

 

 

       3  sessions in tracefile.

 

      10  user  SQL statements in trace file.

 

     114  internal SQL statements in trace file.

 

      62  SQL statements in trace file.

 

       9  unique SQL statements in trace file.

 

     613  lines in trace file.

 

      27  elapsed seconds in trace file.

 

 

 

 

 

2.5 查看trace 文件

 

                在2.4中，我们看到了tkprof生成的报告，这个报告是一个汇总的结果集，如果想确切的知道SQL 语句的每一步执行是如果操作的，就需要分析原始的trace文件。 这个trace 虽然没有tkprof工具处理之后易读，但是却能够清楚的知道SQL在那个点做了什么，以及SQL是如何工作的，这对与理解SQL语句的执行过程非常有用。

 

 

 

直接打开 orcl_ora_3048_安庆怀宁.trc 文件：

 

 

 

Trace file d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048_安庆怀宁.trc

 

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

 

With the Partitioning, OLAP, Data Mining and Real Application Testing options

 

Windows NT Version V6.1 

 

CPU                 : 2 - type 586, 2 Physical Cores

 

Process Affinity    : 0x0x00000000

 

Memory (Avail/Total): Ph:1559M/4095M, Ph+PgF:4170M/8188M, VA:2881M/4095M

 

Instance name: orcl

 

Redo thread mounted by this instance: 1

 

Oracle process number: 29

 

Windows thread id: 3048, image: ORACLE.EXE (SHAD)

 

 

 

 

 

*** 2010-09-01 23:45:51.877

 

*** SESSION ID:(267.996) 2010-09-01 23:45:51.877

 

*** CLIENT ID:() 2010-09-01 23:45:51.877

 

*** SERVICE NAME:(SYS$USERS) 2010-09-01 23:45:51.877

 

*** MODULE NAME:(sqlplus.exe) 2010-09-01 23:45:51.877

 

*** ACTION NAME:() 2010-09-01 23:45:51.877

 

 

 

……..

 

=====================

 

PARSING IN CURSOR #12 len=493 dep=1 uid=0 oct=3 lid=0 tim=488541717777 hv=2584065658 ad='b1dad758' sqlid='1gu8t96d0bdmu'

 

select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)

 

END OF STMT

 

PARSE #12:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541717773

 

EXEC #12:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541718176

 

FETCH #12:c=0,e=127,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2035254952,tim=488541718359

 

STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op='MERGE JOIN OUTER (cr=4 pr=0 pw=0 time=0 us cost=2 size=189 card=1)'

 

STAT #12 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=137 card=1)'

 

STAT #12 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'

 

STAT #12 id=4 cnt=0 pid=1 pos=2 obj=0 op='BUFFER SORT (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

 

STAT #12 id=5 cnt=0 pid=4 pos=1 obj=429 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

 

STAT #12 id=6 cnt=0 pid=5 pos=1 obj=430 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'

 

CLOSE #12:c=0,e=11607,dep=1,type=3,tim=488541730026

 

…………

 

 

 

这个文件的可读性要差很多。 对这里面的一些参数做些说明：

 

 

 

PARSING IN CURSOR 部分：   

 

                Len: 被解析SQL的长度

 

                Dep: 产生递归SQL的深度

 

                Uid：user id

 

                Otc: Oracle command type 命令的类型

 

                Lid: 私有用户id

 

                Tim：时间戳

 

                Hv： hash value

 

                Ad：SQL address

 

 

 

PARSE,EXEC,FETCH 部分

 

                C: 消耗的CPU time

 

                E：elapsed time 操作的用时

 

                P: physical reads 物理读的次数

 

                Cr: consistent reads 一致性方式读取的数据块

 

                Cu：current 方式读取的数据块

 

                Mis：cursor misss in cache 硬分析次数

 

                R: -rows 处理的行数

 

                Dep: depth 递归SQL的深度

 

                Og： optimizer goal 优化器模式

 

                Tim：timestamp时间戳

 

 

 

STATS 部分：

 

                Id: 执行计划的行源号

 

                Cnt：当前行源返回的行数

 

                Pid：当前行源号的父号

 

                Pos：执行计划中的位置

 

                Obj：当前操作的对象id（如果当前行原始一个对象的话）

 

                Op：当前行源的数据访问操作

 

 

 

 

 

 

 

三． 10046 事件

 

                Oracle 的事件很多。 具体参考blog：

 

                                Oracle 跟踪事件 set event

 

                                http://blog.csdn.net/tianlesoftware/archive/2009/12/13/4977827.aspx

 

10046 事件主要用来跟踪SQL语句，它并不是ORACLE 官方提供给用户的命令，在官方文档上也找不到事件的说明信息。 但是用的却比较多，因为10046事件获取SQL的信息比SQL_TRACE 更多。 更有利于我们对SQL的判断。

 

 

 

 

 

10046 事件按照收集信息内容，可以分成4个级别：

 

                Level 1： 等同于SQL_TRACE 的功能

 

                Level 4： 在Level 1的基础上增加收集绑定变量的信息

 

                Level 8： 在Level 1 的基础上增加等待事件的信息

 

                Level 12：等同于Level 4+Level 8, 即同时收集绑定变量信息和等待事件信息。

 

 

 

3.1 对当前session 使用10046事件

 

                SQL>alter session set events ‘10046 trace name context forever, level 12’; --启动10046事件

 

                执行相关事务

 

                SQL>alter session set events ‘10046 trace name context off’; -- 关闭10046事件

 

 

 

该事件收集的信息也是放在trace文件中，查看trace文件的方法，参考第二节：TKPROF 工具。

 

 

 

3.2对其他的会话进行跟踪

 

   之前说的都是对当前session进行跟踪，在生产环境中，可能需要对其他session进行跟踪，有如下2种方法：

 

 

 

3.2.1  用SQL_TRACE跟踪

 

SQL> select sid,serial# from v$session where SID=267;

 

       SID    SERIAL#

 

---------- ----------

 

       267        996

 

 

 

SQL> execute dbms_system.set_sql_trace_in_session(267,996,true);  -- 启动SQL_TRACE

 

PL/SQL 过程已成功完成。

 

 

 

SQL> execute dbms_system.set_sql_trace_in_session(267,996,false); -- 关闭SQL_TRACE

 

PL/SQL 过程已成功完成。

 

 

 

3.2.2 使用10046 事件跟踪

 

SQL> exec dbms_monitor.session_trace_enable(267,996,waits=>true,binds=>true);  -- 启动trace

 

PL/SQL 过程已成功完成。

 

 

 

SQL> exec dbms_monitor.session_trace_disable(267,996); -- 关闭trace

 

PL/SQL 过程已成功完成。

 

 

 

 

 

注意：

 

    如果一条SQL语句中包含了通过DBLINK进行的数据操作，我们想对这条SQL进行trace跟踪，在本地只能够trace到本地执行的SQL信息，而对于远程的SQL语句，由于它运行在远端的数据库上，我们要获得它的信息，需要到远端的数据库上，找到运行这条SQL语句的session，然后对它做Trace。 另外，这条SQL语句的执行计划也只能从远端数据库上捕获到。

 

 

 

 

 

总之，当SQL语句操作出现性能问题时，我们可以用SQL_TRACE 或者10046事件进行跟踪是最合适的。 如果是数据库整体性能下降，就需要使用statspack或者AWR对数据库进行分析。