ITPub博客

首页 > 数据库 > Oracle > oracle sql trace与10046浅谈

oracle sql trace与10046浅谈

原创 Oracle 作者:辛勤的小胖 时间:2014-02-11 13:53:17 0 删除 编辑
  • 什么是sql_trace?
  • 首先我们先看一下什么是sql_trace,顾名思义就是在一个或者多个sql语句在执行时的运行状态,官方文档是这么解释
 文档也写的很清楚了,是一个基础的sql性能诊断工具,sql_trace工具可以评估sql语句的执行效率,并且通过TKPROF工具生成易读统计报表,
因为直接生成到trace目录中的信息我们看起来不太直观,所以这里是oracle推荐两个工具一先一后辅助而生。我们这里的环境是11g的,所以
比10g的trace 信息存放目录要多一些,看你自己的输出目录了我存放的是/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace
可以通过sql命令启动SQL_TRACE,或者在初始化参数里面,查看官方文档,里面有写

查看当前默认的trace文件是哪一个,用sql语句查询,如下:

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           || '/'
         || 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;    

trace_file_name
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_3276808.trc
知道trace信息放哪了
SQL>alter session set sql_trace=true;  开启当前会话级别的操作,关闭为false

或者

SQL>alter system set sql_trace=true;开启这个数据库层面的很少用到,这样会生成大量的trace信息,没必要而且对数据库运行压力比较大,不推荐

我们用示例来看一下
SQL> alter session set sql_trace=true;
Session altered.


SQL> select * from t;
71176 rows selected.

  关闭SQL_TRACE

SQL> alter session set sql_trace=false;

我们去查看trace文件信息,主要包扩了Parse/Fetch/Execute三个阶
trace文件头
Trace file /u01/app/oracle/diag/rdbms/xupeng11g/xupeng11g/trace/xupeng11g_ora_5767668.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name:    AIX
Node name:      cecgt
Release:        1
Version:        6
Machine:        00CF2CD34C00
Instance name: xupeng11g
Redo thread mounted by this instance: 1
Oracle process number: 19
Unix process pid: 5767668, image: oracle@cecgt (TNS V1-V3)
主要trace信息
=====================
PARSING IN CURSOR #4 len=15 dep=0 uid=0 oct=3 lid=0 tim=6847984458 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #4:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984456
EXEC #4:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=6847984589
FETCH #4:c=0,e=86,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=6847984795
FETCH #4:c=0,e=37,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847985336
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847990552
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6847995856
FETCH #4:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848001124
FETCH #4:c=0,e=34,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848006350
FETCH #4:c=0,e=44,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848011101
FETCH #4:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=6848015655
.............................
STAT #4 id=1 cnt=71176 pid=0 pos=1 obj=73439 op='TABLE ACCESS FULL T (cr=5703 pr=0 pw=0 time=48516 us cost=280 size=10469396 ca
rd=66262)'
*** 2014-02-11 11:17:43.546
CLOSE #4:c=0,e=27,dep=0,type=0,tim=7281805082
这个文件的可读性要差很多。 对这里面的一些参数做些说明:

PARSING IN CURSOR 部分:   

                Len: 被解析SQL的长度

                Dep: 产生递归SQL的深度

                Uiduser id

                Otc: Oracle command type 命令的类型

                Lid: 私有用户id

                Tim:时间戳

                Hv hash value

                AdSQL address

 

PARSE,EXEC,FETCH 部分

                C: 消耗的CPU time

                Eelapsed time 操作的用时

                P: physical reads 物理读的次数

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

                Cucurrent 方式读取的数据块

                Miscursor misss in cache 硬分析次数

                R: -rows 处理的行数

                Dep: depth 递归SQL的深度

                Og optimizer goal 优化器模式

                Timtimestamp时间戳

 

STATS 部分:

                Id: 执行计划的行源号

                Cnt:当前行源返回的行数

                Pid:当前行源号的父号

                Pos:执行计划中的位置

                Obj:当前操作的对象id(如果当前行原始一个对象的话)

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

这种方式对于很少做优化的DBA来说那就看起来比较费劲了,有的人说看AWR报告我说没有必要,你只需要查看一个或者几个,而AWR报告
是从数据库最初的基线到数据库使用周期的性能的评估报告。我们可以使用前面我推荐给大家的工具tkprof来整理一下凌乱的trace文件
下面我介绍什么是TKPROF?
Tkprof 工具是Oracle 自带的一个工具,用于处理原始的trace文件它的作用主要是合并汇总trace文件中的一些项,规范化文件的格式,使文件更具有可读性
注意:tkprof 工具只能用在处理SQL_TRACE和10046事件(下节内容也会提到它)产生的trace,其他事件如10053不能处理。


我们看一下tkprof如何使用,我们可以查官方文档来看一下使用语法

属于操作系统命令,我们运行一下

Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
 filename1 指定的输入文件,可以是多个文件联起来
filename2 是
格式化输出文件 
  SORT   在输出到输出文件前,先进程排序。如果省去,则按照实际使用的顺序输出到文件中。排序选项有以下多种
  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

PRINT        只列出输出文件的第一个integer SQL语句。默认为所有的SQL语句。
AGGREGATE    如果= NO ,则不对多个相同的SQL进行汇总。
INSERT       SQL 语句的一种,用于将跟踪文件的统计信息存储到数据库中。在TKPROF创建脚本后,在将结果输入到数据库中。
SYS         禁止或启用 将SYS用户所发布的SQL语句列表到输出文件中。
TABLE       在输出到输出文件前,用于存放临时表的用户名和表名。
EXPLAIN     对每条SQL 语句确定其执行规划。并将执行规划写到输出文件中。

其中比较有用的一个排序选项是fchela,即按照elapsed time fetching来对分析的结果排序(记住要设置初始化参数timed_statistics=true),生成的文件将把最消耗时间的sql放在最前面显示。另外一个有用的参数就是sys,这个参数设置为no可以阻止所有以sys用户执行的sql被显示出来,这样可以减少分析出来的文件的复杂度,便于查看。
到这里我们开始使用tkprof来格式化输出一个trace文件,我们用到上面的参数,看自己的需要了我这里用的不多

$ tkprof xupeng11g_ora_5767668.trc xupengtrace.txt sys=no
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
$ ls -ltr
total 8584
-rw-r-----    1 oracle   oinstall      27698 Feb 11 11:17 xupeng11g_ora_5767668.trm
-rw-r-----    1 oracle   oinstall     405360 Feb 11 11:17 xupeng11g_ora_5767668.trc
-rw-r--r--    1 oracle   oinstall       2706 Feb 11 12:44 xupengtrace.txt
$ more xupengtrace.txt
TKPROF: Release 11.2.0.1.0 - Development on Tue Feb 11 12:44:23 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
Trace file: xupeng11g_ora_5767668.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        2      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch     4747      0.00       0.16          0       5703          0       71176
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4752      0.00       0.16          0       5703          0       71176
Misses in library cache during parse: 1  #shared pool 中没有命令,说明做了1次硬解析
Misses in library cache during execute: 1 也执行了一次sql
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS  递归SQL语句
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.
********************************************************************************
Trace file: xupeng11g_ora_5767668.trc
Trace file compatibility: 11.1.0.7
Sort options: default
     473  elapsed seconds in trace file.
    4912  lines in trace file.
       3  unique SQL statements in trace file.
       3  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  user  SQL statements in trace file.
       1  session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
    3  SQL statements in session.
    0  internal SQL statements in session.
    3  user  SQL statements in session.
Misses in library cache during parse: 0
total        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Fetch        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Parse        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
call     count       cpu    elapsed       disk      query    current        rows
     473  elapsed seconds in trace file.
    4912  lines in trace file.
       3  unique SQL statements in trace file.
       3  SQL statements in trace file.
       0  internal SQL statements in trace file.
       3  user  SQL statements in trace file.
       1  session in tracefile.
Sort options: default
Trace file compatibility: 11.1.0.7
Trace file: xupeng11g_ora_5767668.trc
********************************************************************************
    3  SQL statements in session.
    0  internal SQL statements in session.
    3  user  SQL statements in session.
Misses in library cache during parse: 0
total        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Fetch        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Parse        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
call     count       cpu    elapsed       disk      query    current        rows

tkprof就可以方便我们查看trace信息了!!! 有种高端大气上档次的赶脚,哈哈。
下面我们还要谈谈10046事件,sql_trace其实已经包含Parse/Fetch/Execute三个阶段,而10046 比 SQL_TRACE参数提供更多的控制选项, 更详细的内容输出,这个才是我们最终
为什么要选择10046事件做sql调优的原因。而且本人也推荐大家两种方法都测试一下,根据你所需要的吧,这里我不进行过多的分析了!我们继续,
10046 trace

10046 trace帮助我们解析 一条/多条SQL、PL/SQL语句的运行状态 ,这些状态包括 :Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等等。
10046 为我们揭示了 一条/多条SQL 的运行情况, 对于  以点入手的 SQL调优是很好的辅助工具,10046还能帮助我们分析 一些 DDL维护命令的内部工作原理, RMAN、Data Pump Expdp/Impdp等工具的缓慢问题等

10046 TRACE的LEVEL:

不同的Level 对应不同的跟踪级别

  • 1  启用标准的SQL_TRACE功能 ( 默认)  包含了 SQL语句、响应时间、服务时间、处理的行数,物理读和写的数目、执行计划以及其他一些额外信息。   到版本10.2中 执行计划写入到 trace 的条件是仅当相关游标 已经关闭时, 且与之相关的执行统计信息是所有执行次数的总和数据。  到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace , 执行统计信息仅仅和这第一次执行相关
  • 4 比level 1时多出 绑定变量的 trace
  • 8  比level 1多出等待事件,特别对于9i中指出 latch free等待事件很有用,对于分析全表扫描和索引扫描也很有用
  • 12  比level 1 多出 绑定变量和 等待事件
  • 16  在11g中为每一次执行生成STAT信息,仅在11.1之后可用
  • 32  比level 1少执行计划
  •  64  和level 1 相比 在第一次执行后还可能生成执行计划信息 ; 条件是某个游标在前一次执行的前提下 运行耗时变长了一分钟。仅在 11.2.0.2中可用
  • Level 28 (4 + 8 + 16) 代表 同时启用 level 4 、level 8、level 16
  • level 68 ( 64 + 4 )  代表 同时启用 level 64、level 4
设置方法和sql_trace差不多,一条DDL搞定

session 级别: alter session set events ’10046  trace name context forever,level X’;

system 级别 :      alter system  set events ’10046  trace name context forever,level X’;
10046 trace 信息也放在和查看sql_trace一样,我们查看放在哪个trace文件上。


我做在做一个示例
SQL> alter session set events '10046 trace name context forever,level 28';
Session altered.

执行一个事务查询
select * from t;
查看trace文件内容
PARSING IN CURSOR #2 len=15 dep=0 uid=0 oct=3 lid=0 tim=15535564761 hv=1134051363 ad='70000017d784f28' sqlid='89km4qj1thh13'
select * from t
END OF STMT
PARSE #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564760
EXEC #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2153619298,tim=15535564873
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535564964
FETCH #2:c=0,e=141,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2153619298,tim=15535565149
WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565662
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535565701
FETCH #2:c=0,e=61,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535565752
WAIT #2: nam='SQL*Net message from client' ela= 5257 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571040
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535571084
FETCH #2:c=0,e=52,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535571126
WAIT #2: nam='SQL*Net message from client' ela= 5228 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576386
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535576425
FETCH #2:c=0,e=72,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535576487
WAIT #2: nam='SQL*Net message from client' ela= 5382 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581907
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535581945
FETCH #2:c=0,e=54,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2153619298,tim=15535581989
WAIT #2: nam='SQL*Net message from client' ela= 5166 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587185
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=15535587229
Bind#2
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f9ccfec6bd8  bln=22  avl=04  flg=05
我们可以再一次使用tkprof来格式化输出一个文件,方法已经介绍了。我们可以对比一下sql_trace与10046的区别了,10046更加的完善了,
包括变量、WAIT Time等。推荐大家使用10046 trace我们sql_trace和10046就浅谈到这里。后续我会把oradebug工具也推荐给大家,近期
我在整理一下头绪。




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

下一篇: 用工具分析10046
请登录后发表评论 登录
全部评论

注册时间:2013-05-13

  • 博文量
    12
  • 访问量
    283163