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/

时间： 2024-12-11 16:10:23

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

[Android Pro] 通过Android trace文件分析死锁ANR

转载自: http://blog.csdn.net/oujunli/article/details/9102101#reply 对于从事Android开发的人来说,遇到ANR(Application Not Responding)是比较常见的问题.一般情况下,如果有ANR发生,系统都会在/data/anr/目录下生成trace文件,通过分析trace文件,可以定位产生ANR的原因.产生ANR的原因有很多,比如CPU使用过高.事件没有得到及时的响应.死锁等,下面将通过一次因为死锁导致的ANR问题,

Oracle中有个tkprof来格式化oracle的trace文件

1.MySQL日志文件系统的组成2.慢查询日志3.慢查询日志演示long_query_time : 设定慢查询的阀值,超出次设定值的SQL即被记录到慢查询日志,缺省值为10sslow_query_log : 指定是否开启慢查询日志log_slow_queries : 指定是否开启慢查询日志(该参数要被slow_query_log取代,做兼容性保留)slow_query_log_file : 指定慢日志文件存放位置,可以为空,系统会给一个缺省的文件host_name-slow.logmin_exa

oracle学习----trace文件

1.查看v$diag_info视图,能查看跟踪文件的位置,具体的名称等信息. name列中,Diag Trace是11g跟踪文件所在位置 Default Trace File是当前会话的跟踪文件名 2.查询可以生成跟踪文件名select c.value||'\'||d.instance_name||'_ora_'||a.spid||'.trc'||case when e.value is not null then '_'||e.value end as tracefrom v$process

Trace文件分析

delay.awk BEGIN { highest_packet_id = 0; } { action = $1; time = $2; from = $3; to = $4; type = $5; pktsize = $6; flow_id = $8; src = $9; dst = $10; seq_no = $11; packet_id = $12; if ( packet_id > highest_packet_id ) highest_packet_id = packet_id; if

[Oracle]如何查看 10046 trace 中的 tim= ... 的具体时刻

可以在  Linux 下,用下列方式: 如10046 trace 文件中如果有如下的内容:... tim = 1503032923 可以用 date 命令加 option 来看它的时刻: date -u -d '@1503032923' 显示为: 2017年  8月 18日 星期五 05:08:43 UTC

Oracle 10046事件 介绍(二) ---tkprof

之前简单的写了10046事件介绍的文章http://hbxztc.blog.51cto.com/1587495/1898624,当然收集10046 trace不是最终的目的,能够读懂并且通过分析10046 trace进而分析相应sql的性能问题才是10046 trace真正发挥作用的地方.但是10046事件所产生的原始trace文件习惯称之为裸trace文件(raw trace),Oracle记录在裸trace文件中的内容一眼看上去并不是那么观,也不是那么容易看懂.为了祼trace文件能够以一种

10046 trace详解(1)

10046 trace帮助我们解析一条/多条SQL.PL/SQL语句的运行状态,这些状态包括:Parse/Fetch/Execute三个阶段中遇到的等待事件.消耗的物理和逻辑读.CPU时间.执行计划等,它为我们揭示了一条.多条SQL的运行情况,对SQL调优是一个非常好的辅助工具,同时还能帮我们分析一些DDL维护命令的内部工作原理,RMAN.Data Pump Expdp/impdp等工具缓慢问题. 记得进公司面试时提到这个一样问题,查看SQL执行计划有哪此方法,10046.PL/SQL F5快捷

Linux内核跟踪之trace框架分析【转】

转自:http://blog.chinaunix.net/uid-20543183-id-1930846.html ------------------------------------------ 本文系本站原创,欢迎转载! 转载请注明出处:http://ericxiao.cublog.cn/ ------------------------------------------ 一: 前言 本文主要是对trace的框架做详尽的分析, 在后续的分析中,再来分析接入到框架中的几个重要的trace