• trace文件解读


    *********************************************************************
    示例:全表扫描的10046文件解读
    *********************************************************************
    注:trace文件略
    · 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的长度
    · [O]CT=3 Oracle command type 指Oracle中命令分类的类型 可以通过 V$SQL.COMMAND_TYPE获得对应关系,11g中提供了 V$SQLCOMMAND 视图可以看到完整的对照列表,SQL> select command_type,command_name from V$SQLCOMMAND;
    · 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 bj=0 p='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 bj=0 p=’HASH GROUP BY (cr=1143 pr=1139 pw=0 time=61372 us)’
    STAT #2 id=2 cnt=77276 pid=1 pos=1 bj=96551 p=’TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=927821 us)’
    · CR 代表一致性读的数量
    · PR 代表物理读的数量
    · pw 代表物理写的数量
    · time 单位为microsecond,本步骤的耗时
    · cost 本操作的优化器成本
    · size 评估的数据源大小,单位为字节
    · card 评估的优化器基数Cardinality.
    · XCTEND 一个事务结束的标志,如XCTEND rlbk=0, rd_only=1
    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 ff=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来获得当前等待信息。

  • 相关阅读:
    JVM内存分配及GC流程
    打印手机当前界面(位于栈顶)的activity
    AIDL通信过程中设置死亡代理
    最短路径&次短路径算法
    DEX、ODEX、OAT文件&Dalvik和ART虚拟机
    主线程中有多个handler的情况
    GB GBRT XgBoost
    logistic回归为什么要使用sigmoid函数
    十道海量数据处理面试题与十个方法大总结
    常见数据结构和算法题
  • 原文地址:https://www.cnblogs.com/zfox2017/p/7159176.html
Copyright © 2020-2023  润新知