关于10046事件信息

最新推荐文章于 2024-10-01 21:51:51 发布

vict_

最新推荐文章于 2024-10-01 21:51:51 发布

阅读量746

点赞数

文章标签： oracle

本文链接：https://blog.csdn.net/vict_/article/details/10559455

版权

10046事件按照收集信息内容，分为几个等级。常见的有：
level 1: 等同于sql_trace的功能
level 4: 在level1基础上增加绑定变量
level 8: 在level1基础上增加等待事件
level 12:level4+level8

对其他会话做trace
1 SQL_TRACE
启动：execute dbms_system.set_sql_trace_in_session(sid,serial#,true)
关闭：execute dbms_system.set_sql_trace_in_session(sid,serial#,false)
以sys用户登录

PROCEDURE SET_SQL_TRACE_IN_SESSION
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SID                            NUMBER                  IN
 SERIAL#                        NUMBER                  IN
 SQL_TRACE                      BOOLEAN                 IN

2 10046事件
启动： exec dbms_monitor.session_trace_enable(sid,serial#,waits=>true,binds=>true);
关闭： exec dbms_monitor.session_trace_disable(sid,serial#)

PROCEDURE SESSION_TRACE_DISABLE
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SESSION_ID                     BINARY_INTEGER          IN     DEFAULT
 SERIAL_NUM                     BINARY_INTEGER          IN     DEFAULT
PROCEDURE SESSION_TRACE_ENABLE
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SESSION_ID                     BINARY_INTEGER          IN     DEFAULT
 SERIAL_NUM                     BINARY_INTEGER          IN     DEFAULT
 WAITS                          BOOLEAN                 IN     DEFAULT
 BINDS                          BOOLEAN                 IN     DEFAULT
 PLAN_STAT                      VARCHAR2                IN     DEFAULT

一般我们把sql运行分为三个阶段
PARSE 是SQL运行的第一个阶段，解析SQL
EXEC 是SQL运行的第二个阶段，运行已经解析过的语句

FETCH 从游标中 fetch数据行

--生成10046trace
SQL> desc t
 Name                                                  Null?    Type
 ----------------------------------------------------- -------- ------------------------------------
 OWNER                                                          VARCHAR2(30)
 OBJECT_NAME                                                    VARCHAR2(128)
 SUBOBJECT_NAME                                                 VARCHAR2(30)
 OBJECT_ID                                                      NUMBER
 DATA_OBJECT_ID                                                 NUMBER
 OBJECT_TYPE                                                    VARCHAR2(19)
 CREATED                                                        DATE
 LAST_DDL_TIME                                                  DATE
 TIMESTAMP                                                      VARCHAR2(19)
 STATUS                                                         VARCHAR2(7)
 TEMPORARY                                                      VARCHAR2(1)
 GENERATED                                                      VARCHAR2(1)
 SECONDARY                                                      VARCHAR2(1)
 NAMESPACE                                                      NUMBER
 EDITION_NAME                                                   VARCHAR2(30)

SQL> set autotrace trace
SQL> alter session set events '10046 trace name context forever,level 16';

Session altered.
 
SQL>  select * from t where object_id =100;

Execution Plan
----------------------------------------------------------
Plan hash value: 2865594568

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |     1 |    97 |    88   (2)| 00:00:02 |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |     1 |    97 |    88   (2)| 00:00:02 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          |     1 |    97 |    88   (2)| 00:00:02 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T        |     1 |    97 |    88   (2)| 00:00:02 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter("OBJECT_ID"=100)


Statistics
----------------------------------------------------------
         21  recursive calls
          0  db block gets
       1565  consistent gets
          0  physical reads
          0  redo size
       1608  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

--做一个最简单查询，10046事件说明
--以下是trace文件
Trace file /oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_26607636_YL.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/app/oracle/product/11.2.0/dbhome_1
System name:    AIX
Node name:      ZFXTDB
Release:        1
Version:        6
Machine:        00F86FDD4C00
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 57
Unix process pid: 26607636, image: oracle@ZFXTDB (TNS V1-V3)


*** 2013-08-29 09:21:16.377
*** SESSION ID:(150.11643) 2013-08-29 09:21:16.377
*** CLIENT ID:() 2013-08-29 09:21:16.377
*** SERVICE NAME:(SYS$USERS) 2013-08-29 09:21:16.377
*** MODULE NAME:(SQL*Plus) 2013-08-29 09:21:16.377
*** ACTION NAME:() 2013-08-29 09:21:16.377
 
CLOSE #4573749240:c=3,e=4,dep=0,type=1,tim=9060920688805
=====================
PARSING IN CURSOR #4573773368 len=36 dep=0 uid=84 oct=3 lid=84 tim=9060920700196 hv=2590373068 ad='70000040634b778' sqlid='60d5m6fd6bx6c'
------PARSING IN CURSOR部分
--len=36 被分析sql长度
--dep=0  代表该SQL的递归深入(recursive depth)，因为递归SQL可能再引发下一层的递归SQL， 如果DEP=0则说明不是递归SQL，如果DEP>0则说明是递归SQL。
--uid=84 user id
--oct=3  Oracle command type 指Oracle中命令分类的类型。可查询视图V$SQLCOMMAND。 对应V$SQL.COMMAND_TYPE
--lid=84 Privilege user id 权限用户ID
--tim    timestamp 时间戳， 在9i之前 这个指标的单位是 1/100 s 即 10ms 。 到9i以后单位为 1/1000000s即microsecond 。 
--type 关闭游标的操作类型
--0    该游标从未被缓存且执行次数小于3次，也叫hard close
--1    该游标从未被缓存但执行次数至少3次，若在session cached cursor中有free slot 则将该游标放入session cached cursor
--2    该游标从未被缓存但执行次数至少3次，该游标置入session cached cursor的条件是讲老的缓存age out掉
--3    该游标已经在缓存里，则还会去
--hv=2590373068     代表这个SQL 的hash value ， 10g之前没有SQL_ID 时 主要靠HASH VALUE 来定位一个SQL
--ad sql address 代表SQLTEXT 的地址 来源于 v$sqlarea.address v$sql.address
--这个时间戳可以用来判断 trace中2个点的时间差。  这个 TIm的值来自于V$TIMER视图，这个视图是Oracle内部计时用的。
--  SQL> desc v$timer;
--  Name                                                  Null?    Type
--  ----------------------------------------------------- -------- ------------------------------------
--  HSECS                                                          NUMBER
--sqlid 代表这个SQL 的sql_id 同hash_value一样可以在v$sql,v$sqlarea sql_id,hash_value 查询到。
-------PARSE EXEC FETCH部分
select * from t where object_id =100
END OF STMT
PARSE #4573773368:c=1034,e=1682,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2865594568,tim=9060920700195
EXEC #4573773368:c=693,e=289624,p=0,cr=5,cu=0,mis=0,r=0,dep=0,og=1,plh=2865594568,tim=9060920989886
FETCH #4573773368:c=451,e=4031,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=2865594568,tim=9060920994026
FETCH #4573773368:c=135,e=1248,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2865594568,tim=9060920995694
 
CLOSE #4573773368:c=3,e=5,dep=0,type=1,tim=9060920996854
=====================
--[4573773368]     游标号
--c:   消耗的 cpu time 单位为microsecond
--e:   elapsed time操作的用时 单位为microsecond Elapsed Time = CPU TIME + WAIT TIME (等待事件的时间) 
--     但是由于CPU TIME 和Elapsed time使用了不同 的clock时钟计时，
--     所以在 2者都很短，或者 是CPU敏感的操作时 有可能 CPU TIME> Elapsed time。
--p:   physical reads物理读的次数
--cr:  consistent reads 一致性方式读取的数据块
--cu： current方式读取的数据块
--mis: cursor miss in cachae硬分析次数
--     mis=0说明library cache未发生miss，则本次解析 我们没有需要硬解析 而是采用软解析或者更好的方式。 
--     硬解析在Oracle中成本是很高的。 注意由于在任何阶段包括PARSE/EXECUTE/FETCH阶段都可能发生游标被age out的现象，
--     所以在这些阶段都会打印mis指标。如果mis>0则说明可能发生了硬解析。
--r:   rows 处理的行数
--dep: depth 递归sql的深度
--og:  optimizer goal优化器模式
--     0  游标不可见 或 优化器环境未合理创建
--     1 ALL_ROWS
--     2 FIRST_ROWS
--     3 RULE
--     4 CHOOSE
--plh: plan_hash_value v$sql,v$sqlarea可查询
--tim: timestamp时间戳

STAT #4573773368 id=1 cnt=1 pid=0 pos=1 obj=0 op='PX COORDINATOR  (cr=5 pr=0 pw=0 time=293591 us)'
STAT #4573773368 id=2 cnt=0 pid=1 pos=1 obj=0 op='PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us cost=88 size=97 card=1)'
STAT #4573773368 id=3 cnt=0 pid=2 pos=1 obj=0 op='PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us cost=88 size=97 card=1)'
STAT #4573773368 id=4 cnt=0 pid=3 pos=1 obj=76825 op='TABLE ACCESS FULL T (cr=0 pr=0 pw=0 time=0 us cost=88 size=97 card=1)'
*** SESSION ID:(150.11643) 2013-08-29 09:21:16.675

CLOSE #4573773368:c=3,e=5,dep=0,type=1,tim=9060920996854
=====================
-------STATS部分
--id:   执行计划的行源号，从1开始
--cnt:  当前行源返回的行数
--pid:  当前行源号的父ID
--pos:  执行计划中的位置
--obj:  当前操作的对象id(如果当前行原始一个对象的话) object id
--op：  当前行源的数据访问操作 例如 FULL SCAN，TABLE ACCESS FULL
--11g以上 增加如下信息
--cr:   代表一致性读的数量
--pr:   代表物理读的数量
--pw:   代表物理写的数量
--time: 本步骤的耗时,单位为microsecond，
--us cost:本操作的优化器成本
--size: 评估的数据源大小，单位为字节
--card: 评估的优化器基数Cardinality

--如果有绑定变量level8,level12
--BINDS #20:  说明 绑定变量 是针对 20号游标的
--Bind#0      说明是第0个变量
--oacdty      data type   96 是 ANSI fixed char
--mxl         绑定变量的最大长度
--scl         Scale
--pre         precision
--oacflg      代表绑定选项的特殊标志位
--size        为该内存chunk分配的内存大小
--kxsbbbfp    buffer point
--bln         bind buffer length
--avl         实际的值的长度
--flg         代表绑定状态
--value       实际的绑定值
--kkscoacd    是绑定变量相关的描述符
--XCTEND      一个事务结束的标志
--rlbk        如果是1代表 有回滚操作， 如果是0 代表不会滚 即 commit提交了
--rd_only     如果是1代表 事务只读 ， 如果是0 说明数据改变发生过