Oracle 10046 trace追踪脚本

Oracle 10046 trace追踪

一、查找当前session的10046跟踪日志

1、alter session set tracefile_identifier='kay10046';(可选）

2、alter session set events '10046 trace name context forever, level 12';

备注：系统级别可将session改为system

3、执行sql statement

4、结束跟踪
alter session set events '10046 trace name context off';

5、查找10046日志文件
如果没有做10046identifier，通过如下查位置：

select distinct(m.sid),s.serial#,p.spid,p.tracefile from v$mystat m,v$session s,v$process p where m.sid=s.sid and s.paddr=p.addr;

如上sql查找的是被跟踪seesion的spid，也就是系统pid为关键字的trace文件
如果使用了identifier，再接在trace目录查找

ll -hrt *10046*

6、格式化trace

tkprof /u02/app/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_13995_kay10046.trc aa.tkp sys=no waits=yes explain=admin/oracle 

二、查找其他session 10046跟踪日志

通过sid去查ospid以及orapid

1、先获取其他seesion sid,serial#
select b.sid,b.serial#,a.sql_text from v$sqlarea a,v$session b where sql_text like 'sql text%';

2、执行跟踪

开始：exec dbms_system.set_ev(1371,17,10046,12,'');

执行sql statement

结束：exec dbms_system.set_ev(1371,17,10046,0,'');

3、根据其他会话的sid查找10046trace日志

select p.tracefile from V$PROCESS p,v$session s where s.paddr=p.addr and sid=(1371);

4、格式化trace

tkprof /u02/app/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_20788.trc 10046_a.tkp sys=no

可选explain=admin/oracle

三、根据sql_id trace

–sql_id trace

ALTER SYSTEM SET EVENTS 'SQL_trace [SQL:&&SQL_id] level 12,bind=true, wait=true';
ALTER SYSTEM SET EVENTS 'SQL_trace [SQL:&&SQL_id] off';

四、tkprof参数解析

4.1 tkprof格式化参数解析

count = number of times OCI procedure was executed
表示当前的操作被执行了多少次

cpu = cpu time in seconds executing
当前的操作消耗的CPU时间(秒)

elapsed = elapsed time in seconds executing
当前的操作用了多少CPU及等待时间

disk = number of physical reads of buffers from disk
当前阶段读硬盘(或文件系统buffer)的次数，该值越小越好

query = number of buffers gotten for consistent read
当前阶段以consistent方式从db buffer中查询的buffer数。对于select查询，
其buffer一般都是以consistent mode方式被读取。

current = number of buffers gotten in current mode (usually for update)
当前阶段以current mode方式从db buffer中查询的buffer数，常常是针对DML。
current mode与consistent mode的区别见下面的总结。
query+current 的和是该SQL总的存取的buffer数目。

rows = number of rows processed by the fetch or execute call
SQL语句最后处理的行数，对于select语句，该值产生于fetch阶段;对于dml
该值产生于execute阶段。

consistent mode 是在基于query mode 下的，当查询开始的时候oracle将确立一个时间点，凡是在这个时间点以前提交的数据oracle将能看见，之后提交的数据将不能看见。但查询的时候可能遇上这样的情况，该块中数据已经被修改了，没有提交，或者提交的时间点比查询开始
的时间晚，则oracle为了保证 读的一致性，需要去回滚段获取 该块中变化前的数据(before image)。这叫 consistent reads 。

current mode 当看到当前的block中的内容的时候，是什么就是什么，跟时间点无关，不用去回滚段获取之前的数据。什么时候会是这样的模式？ 除了9i以前版本的FTS对数据字典的获取是current mode外（这是因为关于数据字典的获取必须是当前看见的状态），主要就是发生在DML
的时候，当发生DML的时候，session所看见的必须是当前的block的状态，不能去回滚段获取数据(否则就乱套了)。假如当前block中数据是被session更改过还没有提交，那么看当前状态数据则被其他session 锁定，出现等待 (这才是正常的)。（查询去回滚段获取数据，读和更新之间不会出现锁的情况）

一般来说，elapsed_time = cpu_time + wait_time, 不过对于并行，可能出现cpu_time大于elapsed time的情况。

Misses in library cache during parse: 0 — 说明硬解析次数。上面的parse包含软解析和硬解析次数

trace中的执行计划：
cr是一致性模式下逻辑读出的数据块数。
pr是从磁盘物理读出的数据块数。
pw是物理写入磁盘的数据块数。
time是以微秒表示的总的消耗时间。要注意根据统计得到的值不总是精确的。实际上，为了减少开销，可能用了采样。
cost是操作的评估开销。这个值只有在Oracle 11g才提供。
size是操作返回的预估数据量(字节数)。这个值只有在Oracle 11g才提供。
card是操作返回的预估行数。这个值只有在Oracle 11g才提供。

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS — 非递归SQL汇总,表示用户的语句

— 递归SQL汇总, 递归SQL是你的SQL或PL/SQL语句所引起的后台语句执行（如：触发器，数据字典操作，表空间操作语句等等）。

     1  session in tracefile.        ---  会话数量  
     310  user  SQL statements in trace file.   ---  SQL语句数量  
      92  internal SQL statements in trace file.  --- 内部SQL数量 
     402  SQL statements in trace file.           --- 总SQL数量 
     202  unique SQL statements in trace file.    --- 唯一SQL数量 
    6046  lines in trace file.
     385  elapsed seconds in trace file.          --- 花费总时间

4.2 原始trace文件参数

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'
 cursor	 cursor number
 len	 sql 语句长度
 dep	 sql 语句递归深度
 uid	 user id
 oct	 oracle command type
 lid	 privilege user id
 tim	 timestamp，时间戳
 hv	 hash id
 ad	 sql address 地址, 用在 v$sqltext
 sqlid	 sql id

接着, 下面的语句说明了 sql 语句具体的执行过程以及每一个步骤消耗 CPU 的时间等性能指标

PARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319
EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482
FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462

 c	 CPU 消耗的时间
 e	 Elapsed time 
 p	 number of physical reads 物理读的次数
 cr	 number of buffers retrieved for CR reads   逻辑读的数据块
 cu	 number of buffers retrieved in current mode (current 模式读取的数据块)
 mis	 cursor missed in the cache 库缓存中丢失的游标, 硬解析次数
 r	 number of rows processed 处理的行数
 dep	 递归深度
 og	 optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
 plh	 plan hash value
 tim	 timestamp 时间戳

以及执行过程中的发生的等待事件

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512
 nam	 an event that we waited for 等待事件
 ela	 此操作消耗的时间
 p3	 block 块号
 trm	 timestamp 时间戳

最后显示的是该游标的执行计划

STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'
STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'
STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'
STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'
STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000
 cnt	 当前行源返回的行数
 pid	 parent id of this row source 当前行源的父结点 id
 pos	 position in explain plan 执行计划的位置
 obj	 object id of row source (if this is a base object)
 op 	 the row source access operation
例如, 执行步骤 merge join 消耗的逻辑读为 119, 物理读为 0, 耗费的时间为 28 us, 成本 cost 193，返回 10 条记录

其中，Misses in library cache during parse ：1 意思是解析的时候库缓存丢失游标, 也就是说发生了一次硬解析

参考

http://blog.itpub.net/35489/viewspace-1124818/
读懂trace file (tkprof格式化) 2

https://blog.csdn.net/dataminer_2007/article/details/42040853
使用 10046 查看执行计划并读懂 trace 文件

http://blog.itpub.net/31544156/viewspace-2220305/
Oracle数据块转储并查看块的详细内容
https://www.colabug.com/4943681.html