Maclean教你读Oracle 10046 SQL TRACE

有同学一直向Maclean反应希望做一期10046 SQL trace的教程, 正好这几天有空 我们就理一理。

为什么我们要使用10046 trace?

10046 trace帮助我们解析 一条/多条SQL、PL/SQL语句的运行状态 ,这些状态包括 :Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等等。

即10046 为我们揭示了 一条/多条SQL 的运行情况, 对于  以点入手的 SQL调优是很好的辅助工具,特别是在 10g之前没有ASH的情况下。 但整体系统调优 不是10046 所擅长的,  10046 是 性能调优的起钉器 , AWR是性能调优 的锤子。

10046还能帮助我们分析 一些 DDL维护命令的内部工作原理, RMAN、Data Pump Expdp/Impdp等工具的缓慢问题等, 是研究 oracle 数据库原理的 居家旅行必备良品。

10046 和SQL TRACE的区别?

10046 比 SQL_TRACE参数提供更多的控制选项, 更详细的内容输出, 一般Maclean只用10046 而不用sql_trace

10046 和10053 的区别?

10053 是最常用的Oracle 优化器optimizer 跟踪trace, 10053 可以作为我们解析 优化器为什么选择某个执行计划,其中的理由的辅助工具,但并不告诉我们这个执行计划 到底运行地如何。

而10046 并不解释 optimizer优化器的工作, 但它同样说明了在SQL解析parse阶段所遇到的等待事件和所消耗的CPU等资源,以及Execute执行和Fetch阶段的各项指标。

简而言之10046 告诉我们SQL(执行计划)运行地如何, 10053告诉我们 优化器为什么为这个SQL选择某个执行计划。

 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

设置的方法如下:

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

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

针对非本会话的 某一个进程设置,如果你知道他的SPID 操作系统进程号

oradebug setospid SPID;

oradebug event 10046 trace name context forever, level X;

例如:

[oracle@vrh8 ~]$ ps -ef|grep LOCAL  
oracle   12421 12420  0 Aug21 ?        00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle   12522 12521  0 Aug21 ?        00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle   12533     1  0 Aug21 ?        00:00:00 oracleG10R25 (LOCAL=NO)
oracle   15354 15353  0 Aug21 ?        00:00:08 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle   15419 15418  0 Aug21 ?        00:00:11 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle   16219 16218  0 Aug21 ?        00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle   17098 17097  0 03:12 ?        00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

要跟踪 17098  这个进程

SQL> oradebug event 10046 trace name context forever, level 28;
Statement processed.

从 sid 定位到 SPID 或者 ORAPID 的 查询如下:

SQL> select distinct sid from v$mystat;

       SID
----------
       141

SQL> select spid,pid from v$Process where addr=(select paddr from v$session where sid=141);

SPID                PID
------------ ----------
17196                24

select spid,pid from v$Process where addr=(select paddr from v$session where sid=&SID)

如果只知道 ORA的PID 那么也可以

oradebug setorapid 24;
oradebug event 10046 trace name context forever, level 28;

10046 trace 示例解析

这里我们引入一个全表扫描的10046例子 并解析该例子中的TRACE信息:


PARSING IN CURSOR #20 len=44 dep=0 uid=0 oct=3 lid=0 tim=1344883874047619 hv=2241892608 ad='a7902a08'
select count(*) from fullscan where owner=:v
END OF STMT
PARSE #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610

PARSING IN CURSOR #26 len=198 dep=1 uid=0 oct=3 lid=0 tim=1344883874048534 hv=4125641360 ad='a7ab9fc0'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkna
me is null and subname is null
END OF STMT
PARSE #26:c=0,e=531,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874048501
BINDS #26:
kkscoacd
 Bind#0
  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=01  flg=05
  value=0
 Bind#1  
  oacdty=01 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f9ccfec6ba0  bln=32  avl=08  flg=05
  value="FULLSCAN"  askmaclean.com
 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=7f9ccfec6b70  bln=24  avl=02  flg=05
  value=1
EXEC #26:c=1998,e=1506,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874050177
WAIT #26: nam='db file sequential read' ela= 26 file#=1 block#=58007 blocks=1 obj#=37 tim=1344883874050345
WAIT #26: nam='db file sequential read' ela= 19 file#=1 block#=58966 blocks=1 obj#=18 tim=1344883874050452

PARSING IN CURSOR #25 len=493 dep=1 uid=0 oct=3 lid=0 tim=1344883874051980 hv=2584065658 ad='a7a9ef68'
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.e
mpcnt,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),n
vl(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 #25:c=1000,e=585,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874051971
BINDS #25:
kkscoacd
 Bind#0
  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
  value=96551
EXEC #25:c=3000,e=2757,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874054930
WAIT #25: nam='db file sequential read' ela= 21 file#=1 block#=48756 blocks=1 obj#=3 tim=1344883874055059
WAIT #25: nam='db file sequential read' ela= 18 file#=1 block#=51327 blocks=1 obj#=4 tim=1344883874055149
FETCH #25:c=0,e=538,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=1344883874055512
STAT #25 id=1 cnt=1 pid=0 pos=1 obj=0 op='MERGE JOIN OUTER (cr=5 pr=2 pw=0 time=565 us)'
STAT #25 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=2 pw=0 time=228 us)'
STAT #25 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=1 pw=0 time=115 us)'
STAT #25 id=4 cnt=0 pid=1 pos=2 obj=0 op='BUFFER SORT (cr=2 pr=0 pw=0 time=251 us)'
STAT #25 id=5 cnt=0 pid=4 pos=1 obj=709 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=2 pr=0 pw=0 time=207 us)'
STAT #25 id=6 cnt=0 pid=5 pos=1 obj=710 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=2 pr=0 pw=0 time=33 us)'

................

BINDS #20:
kkscoacd
 Bind#0
  oacdty=96 mxl=2000(150) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=873 siz=2000 off=0
  kxsbbbfp=7f9ccfec6420  bln=2000  avl=50  flg=05
  value="MACLEAN                                           "
EXEC #20:c=20996,e=21249,p=7,cr=19,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874068951
WAIT #20: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=36 tim=1344883874069011
WAIT #20: nam='db file sequential read' ela= 23 file#=1 block#=80385 blocks=1 obj#=96551 tim=1344883874069159
WAIT #20: nam='db file scattered read' ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383
WAIT #20: nam='db file scattered read' ela= 41 file#=1 block#=82313 blocks=8 obj#=96551 tim=1344883874069543
WAIT #20: nam='db file scattered read' ela= 30 file#=1 block#=82321 blocks=8 obj#=96551 tim=1344883874069678
WAIT #20: nam='db file scattered read' ela= 38 file#=1 block#=82329 blocks=8 obj#=96551 tim=1344883874069949
WAIT #20: nam='db file scattered read' ela= 848 file#=1 block#=82337 blocks=8 obj#=96551 tim=1344883874070846
WAIT #20: nam='db file scattered read' ela= 63 file#=1 block#=82345 blocks=8 obj#=96551 tim=1344883874071042
WAIT #20: nam='db file scattered read' ela= 37 file#=1 block#=92593 blocks=8 obj#=96551 tim=1344883874071190
WAIT #20: nam='db file scattered read' ela= 73 file#=1 block#=92601 blocks=8 obj#=96551 tim=1344883874071393
FETCH #20:c=18997,e=18234,p=1139,cr=1143,cu=0,mis=0,r=1,dep=0,og=1,tim=1344883874087322
WAIT #20: nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883874087675
FETCH #20:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1344883874087715
WAIT #20: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883874087744
*** 2013-08-22 04:44:59.527
WAIT #20: nam='SQL*Net message from client' ela= 12169104 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886256887
STAT #20 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1143 pr=1139 pw=0 time=18243 us)'
STAT #20 id=2 cnt=0 pid=1 pos=1 obj=96551 op='TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=18200 us)'
WAIT #0: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886257193
WAIT #0: nam='SQL*Net message from client' ela= 455225 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886712468
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886712594

PARSING IN CURSOR #20 len=44 dep=0 uid=0 oct=3 lid=0 tim=1344883874047619 hv=2241892608 ad=’a7902a08′
select count(*) from fullscan where owner=:v
END OF STMT
PARSE #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610

PARSING IN CURSOR #20 ,这里的#20是游标号, 这个游标号非常重要, 后面的 FETCH 、WAIT、EXECUTE、PARSE 都通过这个游标号和前面的SQL联系起来。  

注意可以看到 在执行PARSING IN CURSOR #20 后 ,PARSE #20之后没有紧跟着 #20游标的运行 ,而是跟了 #25、#26游标的运行情况, 仔细看一下 #25和#26他们是 系统递归的recursive SQL  ,这些递归SQL由 用户的SQL触发,一般来说是查一些数据字典基表例如 obj$、tab$等,常规情况下 递归SQL运行消耗的资源和时间都非常少。

LEN=44  指SQL的长度

OCT=3    Oracle command type 指Oracle中命令分类的类型  可以通过 V$SQL.COMMAND_TYPE获得对应关系

11g中提供了 V$SQLCOMMAND 视图可以看到完整的对照列表, http://www.askmaclean.com/archives/vsqlcommand-sql-opcodes-and-names.html

LID=0 权限用户ID  Privilege user id.

TIM   timestamp 一个时间戳, 在9i之前 这个指标的单位是 1/100 s 即 10ms 。 到9i以后单位为 1/1000000  的microsecond 。 这个时间戳可以用来判断 trace中2个点的时间差。  这个 TIm的值来自于V$TIMER视图,这个视图是Oracle内部计时用的。

DEP=0  代表该SQL的递归深入(recursive depth),因为递归SQL可能再引发下一层的递归SQL, 如果DEP=0则说明不是递归SQL,如果DEP>0则说明是递归SQL。

 UID=0  UID即USERID 用以标明是谁在解析这个游标, 如果是0则说明是SYS 用户, 具体 用户名和UID对应可以通过如下查询获得:

select user#,name from user$;

OG=1  OG 代表optimizer_mode ,具体对应关系见下表

  • 0  游标不可见 或 优化器环境未合理创建
  • 1 –  ALL_ROWS
  • 2  - FIRST_ROWS
  • 3   – RULE
  • 4   – CHOOSE

mis=0   该指标说明library cache未发生miss,则本次解析 我们没有需要硬解析 而是采用软解析或者更好的方式。 硬解析在Oracle中成本是很高的。 注意由于在任何阶段包括PARSE/EXECUTE/FETCH阶段都可能发生游标被age out的现象,所以在这些阶段都会打印mis指标。如果mis>0则说明可能发生了硬解析。

HV     代表这个SQL 的hash value , 10g之前没有SQL_ID 时 主要靠HASH VALUE 来定位一个SQL

AD      代表SQLTEXT 的地址 来源于 V$SQLAREA.ADDRESS

err     代表 Oracle错误代码 例如ORA-1555

PARSE    是SQL运行的第一个阶段,解析SQL

EXEC       是SQL运行的第二个阶段,运行已经解析过的语句

FETCH   从游标中  fetch数据行

UNMAP   是当游标使用临时表时,若游标关闭则使用UNMAP释放临时表相关的资源,包括释放锁和释放临时段

C   比较重要的指标,代表本步操作消耗的CPU 时间片; 9i以后单位为microsecond

E    Elapsed Time ,代表本步操作消耗的自然时间,  9i以后单位为microsecond

这里存在一个问题例如 在我们的例子中PARSE #20:c=2000,e=1087   CPU_TIME> Elapsed time  ;

理论上 应当是  Elapsed Time = CPU TIME + WAIT TIME (等待事件的时间), 但是由于CPU TIME 和Elapsed time使用了不同 的clock时钟计时,所以在 2者都很短,或者 是CPU敏感的操作时 有可能 CPU TIME> Elapsed time。

相关的BUG 有:

  • Bug 4161114 : IN V$SQL, CPU_TIME > ELAPSED_TIME
  • Bug 7603849 : CPU_TIME > ELAPSED_TIME FOR CERTAIN SQL’S IN V$SQL
  • Bug 7580277 : ELAPSED_TIME SHOWING 0 FOR CERTAIN SQL’S IN V$SQL
  • Bug 8243074 : INCORRECT ELAPSED_TIME IN V$SQL

该问题可能 在12c中得到修复

 p   物理读的数目

CR  CR一致性读引起的buffer get  数目

CU  当前读current read 引起的buffer get 数目

r     处理的行数

CLOSE #[CURSOR]:c=%u e=%u dep=%d type=%u tim=%u   ==》一个游标关闭的例子

 CLOSE   游标关闭

type    关闭游标的操作类型

  • 0    该游标从未被缓存且执行次数小于3次,也叫hard close
  • 1      该游标从未被缓存但执行次数至少3次,若在session cached cursor中有free slot 则将该游标放入session cached cursor
  • 2     该游标从未被缓存但执行次数至少3次,该游标置入session cached cursor的条件是讲老的缓存age out掉
  • 3      该游标已经在缓存里,则还会去

STAT #[CURSOR] id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']  

  • STAT   相关行反应解释执行计划的统计信息
  • [CURSOR]     游标号
  • id    执行计划的行数 从1开始
  • cnt    该数据源的行数
  • pid    该数据源的 父ID
  • pos    在执行计划中的位置
  • obj     对应数据源的  object id
  • op=    数据源的访问操作,例如 FULL SCAN

11g 以上还提供如下信息:

STAT #2 id=1 cnt=26 pid=0 pos=1 obj=0 op=’HASH GROUP BY (cr=1143 pr=1139 pw=0 time=61372 us)’
STAT #2 id=2 cnt=77276 pid=1 pos=1 obj=96551 op=’TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=927821 us)’

  • CR 代表一致性读的数量
  • PR  代表物理读的数量
  • pw  代表物理写的数量
  • time   单位为microsecond,本步骤的耗时
  • cost    本操作的优化器成本
  • size    评估的数据源大小,单位为字节
  • card       评估的优化器基数Cardinality.

 XCTEND rlbk=0, rd_only=1

  •  XCTEND  一个事务结束的标志
  • rlbk           如果是1代表 有回滚操作, 如果是0 代表不会滚 即 commit提交了
  • rd_only     如果是1代表 事务只读 , 如果是0 说明数据改变发生过

绑定变量  

BINDS #20:
kkscoacd
Bind#0
oacdty=96 mxl=2000(150) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=2000 off=0
kxsbbbfp=7f9ccfec6420 bln=2000 avl=50 flg=05
value=”MACLEAN

  • BINDS #20:  说明 绑定变量 是针对 20号游标的
  • kkscoacd  是绑定变量相关的描述符
  • Bind#0   说明是第0个变量
  • oacdty      data type   96 是 ANSI fixed char
  • oacflg      代表绑定选项的特殊标志位
  • size           为该内存chunk分配的内存大小
  • mxl       绑定变量的最大长度
  • pre      precision
  • scl      Scale
  • kxsbbbfp         buffer point
  • bln               bind buffer length
  • avl     实际的值的长度
  • flg          代表绑定状态
  • value=”MACLEAN    实际的绑定值

如果看到 “bind 6: (No oacdef for this bind)”类似的信息则说明在trace时 还没有定义绑定数据。 这可能是在trace时游标还没绑定变量。

WAIT #20: nam=’db file scattered read’ ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383

  • WAIT #20 等待 20号游标的相关等待事件
  • Nam      等待针对的事件名字,它的P1、P2、P3可以参考视图V$EVENT_NAME,也可以从V$SESSION、ASH中观察到等待事件
  • ela           本操作的耗时,单位为microsecond
  • p1,p2,p3       针对该事件的三个描述参数,见V$EVENT_NAME

在上例中针对 db file scattered read , P1为文件号, P2为 起始块号, p3为 读的块数,  即db file scattered read 是从 1号文件的第80386 个块开始一次读取了7个块。

注意在10046中 出现的WAIT 行信息 都是 已经结束的等待事件, 而当前等待则不会在trace中出现,直到这个当前等待结束。 你可以通过systemstate dump/errorstack等trace来获得当前等待信息。

Comments:

Post a Comment:
  • HTML Syntax: NOT allowed
About

author's avatar The Maclean Liu
Advanced Customer Services
AskMaclean Logo 10g_ocm SHOUG

Search

Categories
Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today