zoukankan      html  css  js  c++  java
  • Oracle 10046 trace文件分析

    生成10046 trace文件:

    SQL> create table t10046 as select * from dba_objects;
    
    Table created.
    
    SQL> select file_id,block_id,blocks from dba_extents where segment_name='T10046';
    
       FILE_ID   BLOCK_ID     BLOCKS
    ---------- ---------- ----------
             1      94664          8
             1      94672          8
             1      94680          8
             1      94688          8
             1      94696          8
             1      94704          8
             1      94712          8
             1      94896          8
             1      94904          8
             1      94912          8
             1      94920          8
             1      94928          8
             1      94936          8
             1      94944          8
             1      94952          8
             1      94960          8
             1      95872        128
             1      96000        128
             1      96128        128
             1      96256        128
             1      96384        128
             1      96512        128
             1      96640        128
             1      96768        128
             1      96896        128
    
    25 rows selected.
    
    SQL> alter session set events '10046 trace name context forever,level 12';
    
    Session altered.
    
    #没有创建索引,会走全表扫描
    SQL> select count(*) from t10046;
    
      COUNT(*)
    ----------
         86956
    
    SQL> alter session set events '10046 trace name context off';
    

    10046 trace 文件的内容:

    =====================
    PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad='7bf41070' sqlid='awzvq6b3da
    pqt'
    select count(*) from t10046
    END OF STMT
    PARSE #140231913930616:c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403
    EXEC #140231913930616:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292551
    WAIT #140231913930616: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1458364346292607
    WAIT #140231913930616: nam='enq: KO - fast object checkpoint' ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=145836434629669
    1
    WAIT #140231913930616: nam='direct path read' ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284
    WAIT #140231913930616: nam='direct path read' ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150
    WAIT #140231913930616: nam='direct path read' ela= 912 file number=1 first dba=95872 block cnt=128 obj#=88635 tim=1458364346300730
    WAIT #140231913930616: nam='direct path read' ela= 386 file number=1 first dba=96000 block cnt=128 obj#=88635 tim=1458364346301893
    WAIT #140231913930616: nam='direct path read' ela= 299 file number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928
    WAIT #140231913930616: nam='direct path read' ela= 371 file number=1 first dba=96256 block cnt=128 obj#=88635 tim=1458364346304307
    WAIT #140231913930616: nam='direct path read' ela= 236 file number=1 first dba=96384 block cnt=128 obj#=88635 tim=1458364346305513
    WAIT #140231913930616: nam='direct path read' ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513
    WAIT #140231913930616: nam='direct path read' ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527
    WAIT #140231913930616: nam='direct path read' ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125
    WAIT #140231913930616: nam='direct path read' ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304
    FETCH #140231913930616:c=14998,e=19124,p=1240,cr=1243,cu=0,mis=0,r=1,dep=0,og=1,plh=2130400753,tim=1458364346311758
    STAT #140231913930616 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us)'
    STAT #140231913930616 id=2 cnt=86956 pid=1 pos=1 obj=88635 op='TABLE ACCESS FULL T10046 (cr=1243 pr=1240 pw=0 time=24549 us cost=338
     size=0 card=70030)'
    WAIT #140231913930616: nam='SQL*Net message from client' ela= 225 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=1458364346312363
    FETCH #140231913930616:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2130400753,tim=1458364346312405
    WAIT #140231913930616: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=1458364346312426
    
    *** 2016-03-19 13:12:37.876
    WAIT #140231913930616: nam='SQL*Net message from client' ela= 11563756 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=14583643578
    76195
    CLOSE #140231913930616:c=0,e=10,dep=0,type=0,tim=1458364357876316
    =====================
    

    10046 trace 文件内容分析:

    1.数据库调用
    含3个子分类:解析,执行和获取
    这3个分类与通过调用DBMS_SQL的子例程DBMS_SQL.PARSE,DBMS_SQL.EXECUTE,DBMS_SQL.FETCH_ROWS来跑SQL的步调相一致
    解析在跟踪文件中通常通过两个相邻的条目表示:第一个是PARSING IN CURSOR,第二个是PARSE。如下所示:

    PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad='7bf41070' sqlid='awzvq6b3da
    pqt'
    select count(*) from t10046
    END OF STMT
    PARSE #140231913930616:c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403
    

    (1)PARSING IN CURSOR各项的具体含义

    参数 说明
    len 表示sql语句文本字节长度   #"select count(*) from t10046"字节长度为27
    dep 递归调用深度  #本次调用深度为0
    uid 解析用户标识符,对应于all_users.user_id以及v$sql.parsing_user_id  #本次是以sys用户执行的,故uid=0
    oct oracle命令类型,对应于v$sql.command_type以及v$session.command  #select对应类型是3
    lid 解析模式标识符,对应于all_users.user_id以及v$sql.parsing_schema_id,可能与uid不同
    tim 微秒单位时间戳,在关联的parse条目中通常比tim的值早一点
    hv 哈希值,对应于v$sql.hash_value
    ad address,对应于v$sql.address
    sqlid sql id,对应与v$sql.sql_id

    (2)PARSE各项的具体含义

    参数 说明
    c cpu开销
    e 运行时间
    p 物理读
    cr 一致读
    cu 当前处理的数据块
    mis 游标丢失,0表示软解析;1表示硬解析
    r 被处理的数据行
    dep 递归调用深度
    og 优化目标。1:all_rows,2:first_rows,3:rule,4:choose。oracle 10g 后默认是all_rows
    plh 执行计划的hash值。对应于v$sql_plan.plan_hash_value,v$sql_plan_statistics_all.plan_hash_value以及v$sqlstats.plan_hash_value
    tim 时间戳,单位为微秒

    2.执行计划,统计信息与STAT条目格式

    一组STAT条目的每一行代表了形成语句结果的行源。所谓的行源,指从索引或表中检索的数据或者多表连接的中间结果(因为必须先进行两表连接)。
    10g以后,STAT条目仅在TIMED_STATISTICS=TRUE,并且SQL_TRACE=TRUE时才被写入。请注意,若STATISTICS_LEVEL=BASIC(缺省为TYPICAL)时会隐式设置TIMED_STATISTICS=FASLE。

    STAT #140231913930616 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us)'
    STAT #140231913930616 id=2 cnt=86956 pid=1 pos=1 obj=88635 op='TABLE ACCESS FULL T10046 (cr=1243 pr=1240 pw=0 time=24549 us cost=338
     size=0 card=70030)'
    

    (1)stat说明

    参数 说明
    id 执行计划中指示行数据源顺序的标识符,通常一个执行计划的第一条stat行的id=1
    cnt 被处理的行数
    pid 父标识符,通常一个执行计划的第一条stat行的pid=0。通过比一个计划的父步骤高一个级别缩进的依赖步骤,tkprof和esqltrcprof使用id以及pid生成适当缩进的执行计划
    pos 父步骤中的一个步骤的位置
    obj 对象标识符,对应于all_objects.object_id和v$sql_plan.object#
    op 执行的行数据源操作,比如表访问、索引扫描、排序、联合等,对应于v$sql_plan.operation。在10g中,在行数据源信息后面op的括号中包含实际语句执行指标
    cr 一致性读
    pr 物理读
    pw 物理写
    time 估计的运行时间,单位为微秒
    cost cbo计算的执行计划成本
    size 估计的数量,单位为字节
    card 估计的基数,即被处理的行数

    3.等待事件和WAIT条目格式

    WAIT #140231913930616: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1458364346292607
    WAIT #140231913930616: nam='enq: KO - fast object checkpoint' ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=145836434629669
    1
    WAIT #140231913930616: nam='direct path read' ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284
    WAIT #140231913930616: nam='direct path read' ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150
    WAIT #140231913930616: nam='direct path read' ela= 912 file number=1 first dba=95872 block cnt=128 obj#=88635 tim=1458364346300730
    WAIT #140231913930616: nam='direct path read' ela= 386 file number=1 first dba=96000 block cnt=128 obj#=88635 tim=1458364346301893
    WAIT #140231913930616: nam='direct path read' ela= 299 file number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928
    WAIT #140231913930616: nam='direct path read' ela= 371 file number=1 first dba=96256 block cnt=128 obj#=88635 tim=1458364346304307
    WAIT #140231913930616: nam='direct path read' ela= 236 file number=1 first dba=96384 block cnt=128 obj#=88635 tim=1458364346305513
    WAIT #140231913930616: nam='direct path read' ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513
    WAIT #140231913930616: nam='direct path read' ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527
    WAIT #140231913930616: nam='direct path read' ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125
    WAIT #140231913930616: nam='direct path read' ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304
    
    参数 说明
    ela 运行时间,单位为微秒
    p1 等待事件的第一个参数。对应于v$session_wait.p1
    p2 等待事件的第二个参数。对应于v$session_wait.p2
    p3 等待事件的第三个参数。对应于v$session_wait.p3
    tim 时间戳
    file# 绝对文件编号
    block# 数据块号
    blocks 数据块数量
    obj# 对象编号,就是object_id
    nam 等待事件的名称

    参考:http://blog.itpub.net/29320885/viewspace-1223962/

  • 相关阅读:
    linux查看CPU和内存信息
    linux yum命令详解
    查看文件中关键字前后几行的内容
    vue.js+web storm安装及第一个vue.js
    android GPS: code should explicitly check to see if permission is available
    ASP.NET MVC Identity 使用自己的SQL Server数据库
    阿里云服务器,tomcat启动,一直卡在At least one JAR was scanned for TLDs yet contained no TLDs就不动了
    ASP.NET MVC4 MVC 当前上下文中不存在名称“Scripts”
    python 将windows字体中的汉字生成图片的方法
    Java android DES+Base64加密解密
  • 原文地址:https://www.cnblogs.com/abclife/p/5298125.html
Copyright © 2011-2022 走看看