当前位置：首页 -> 基础 -> 数据库编程

使用10046查看执行计划并读懂trace文件(二)

2015-02-03 03:55:29 · 作者: · 浏览: 35
标签: 使用 10046 查看 执行 计划 trace 文件
el 1 标准SQL跟踪，相当于SQL_TRACE=TRUE Level 4 在level 1的基础上增加绑定变量的信息 Level 8 在level 1的基础上增加等待事件的信息 Level 12 在level 1的基础上增加绑定变量和等待事件的信息

?

分析读懂 trace 文件

现在我们打开 g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc 看看生成的 trace 文件的内容

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'
select /*+ leading(t3) use_merge(t4) */ *
from t3, t4
where t3.id = t4.t3_id and t3.n = 1100
END OF STMT
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
WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512
FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462
WAIT #22: nam='SQL*Net message from client' ela= 221 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947755
WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947803
FETCH #22:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=3831111046,tim=900460947864
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)'
 
 
从上面的 trace 文件我们可以看出 sql 语句经过了 parse(解析) -> exec(执行) -> fetch(从游标中获取数据) 几个过程, 其中第一句说明了当前跟踪执行的 sql 语句的概况,比如使用游标号, sql 语句的长度, 递归深度等等基本信息:
 
 
?
 
 
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=128