裸跟踪文件解析

跟踪文件浏览

       SQL trace是一个很强大的教育和诊断工具，其输出记录了数据库上Oracle响应应用程序请求的线性纪录历史。

       通过理解理解裸跟踪文件，能够比tkprof知道更多的诊断信息。跟踪文件的其中一部分如下：

=====================

PARSING IN CURSOR #1 len=50 dep=0 uid=55 oct=47 lid=55 tim=1482356280336 hv=1410705492 ad='6ce267dc'

begin INSERT_test(80,'Manager','Shanghai'); end;

END OF STMT

PARSE #1:c=0,e=2065,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1482356280330

BINDS #1:

BINDS #3:

kkscoacd

 Bind#0

  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00

  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0

  kxsbbbfp=67599094  bln=22  avl=02  flg=09

  value=80

 Bind#1

  oacdty=01 mxl=32(07) mxlc=00 mal=00 scl=00 pre=00

  oacflg=13 fl2=206001 frm=01 csi=852 siz=32 off=0

  kxsbbbfp=675990ac  bln=32  avl=07  flg=09

  value="Manager"

 Bind#2

  oacdty=01 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00

  oacflg=13 fl2=206001 frm=01 csi=852 siz=32 off=0

  kxsbbbfp=675990b4  bln=32  avl=08  flg=09

  value="Shanghai"

EXEC #3:c=0,e=243,p=0,cr=0,cu=3,mis=0,r=1,dep=1,og=1,tim=1482356280738

XCTEND rlbk=0, rd_only=0

EXEC #4:c=0,e=87,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=0,tim=1482356280870

EXEC #1:c=0,e=494,p=0,cr=0,cu=4,mis=0,r=1,dep=0,og=1,tim=1482356280907

WAIT #1: nam='log file sync' ela= 720 buffer#=3902 p2=0 p3=0 obj#=52654 tim=1482356281698

WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=52654 tim=1482356281751

WAIT #1: nam='SQL*Net message from client' ela= 24947 driver id=1111838976 #bytes=1 p3=0 obj#=52654 tim=1482356306744     

内核通过PARSING IN CURSOR识别会话使用的每个SQL语句，PARSING IN CURSOR部分显示了SQL文本的属性以及SQL文本本身。

       跟踪文件中的动作行以PARSE, EXEC, FETCH，以及WAIT开始。每个PARSE, EXEC, FETCH代表一个简单的数据库调用，其中c和e分别代表这个调用花费的CPU总时间和总延迟时间。P代表通过OS读调用得到的数据库块数，或者通过数据库缓冲缓存提取的块数（cr代表一致性读模式，cu代表当前模式），库缓存未命中的次数mis，调用返回的行数r，tim代表调用大约完成的时间。

       WAIT行报告在Oracle内核进程中执行的一个特定顺序的指令的延迟。Ela统计报告这样一个顺序指令的响应时间。Nam属性识别调用，p1, p2, p3提供了相应的参数值。

       同时还可能包含STAT行，该行主要提供了优化器为执行SQL语句选择的执行计划，如下：

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=3 pr=0 pw=0 time=71 us)'

STAT #2 id=2 cnt=1 pid=1 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 (cr=2 pr=0 pw=0 time=41 us)'

XCTEND在每次应用程序跟踪时执行了COMMIT/ROLLBACK时会出现。

需要精确计算一个会话响应时间的所有信息都在跟踪文件中。最重要的是可以完全知道会话在其执行期间干了什么。

 

扩展的SQL Trace数据参考

跟踪文件元素定义

游标号

       跟踪文件中出现的每一行代表Oracle内核程序执行的一个动作，每行使用#ID字符串识别内核在其上操作的游标。如下在游标1上操作：

       FETCH #1:c=0,e=177,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,tim=1038931660054596

       游标号仅在跟踪文件范围内相关。并且Oracle内核使游标号在游标被关闭后被重用。因此，跟踪文件行中包含的给定游标号不一定引用相同的游标。幸运的是，跟踪文件中对于每个创建的游标包含了时间顺序。每个PARSING IN CURSOR标识了游标的产生。如下：

PARSING IN CURSOR #1 len=70 dep=0 uid=55 oct=42 lid=55 tim=1482338748687 hv=4027404896 ad='698844d4'

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

END OF STMT

==============

PARSING IN CURSOR #1 len=21 dep=0 uid=55 oct=3 lid=55 tim=1482347535393 hv=2564406738 ad='699b8ae0'

select 'x' from dual

END OF STMT

会话标识符和时间戳

       *** 2008-01-09 15:24:24.754

       *** SESSION ID:(136.11947) 2008-01-09 15:24:24.723

       该信息可以帮助建立从tim值到系统时钟的调用。如果自从上次的记录以来超过了10秒延迟时，Oracle内核将在跟踪文件中写入一个***行。该特征允许分析者重新同步WAIT行之间的大延迟，WAIT包含大概的延迟，但是不是内核时钟值（tim）。如果希望将该行写入跟踪数据，可以调用DBMS_SYSTEM.KSDDDT。

       SESSION ID:(m.n)识别Oracle会话id以及序列号，分别来自V$SESSION.SID=m和V$SESSION.SERIAL#=n。该信息在MTS下特别有用，该信息提示了跟踪文件中信息代表的会话的工作。

应用程序标识符

       如果应用程序通过DBMS_APPLICATION_INFO设置了其模块名或动作，Oracle将在APPNAME上指示出。

       APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240

       Mod代表通过SET_MODULE过程设置的模块名；

       Mh用于识别模块的哈西值；

       Act通过SET_ACTION或SET_MODULE设置的动作名；

       ah用于识别动作的哈西值；

游标标识符

       PARSING IN CURSOR包含以下关于游标的信息：

=====================

PARSING IN CURSOR #135 len=358 dep=0 uid=173 oct=3 lid=173 tim=3675359494 hv=72759792

ad='bb13f788'

select vendor_number, vendor_id, vendor_name, vendor_type_lookup_code, type_1099,

employee_id, num_1099, vat_registration_num, awt_group_id, allow_awt_flag, hold_all_

payments_flag, num_active_pay_sites, total_prepays, available_prepays from po_

vendors_ap_v where (VENDOR_NUMBER LIKE :1) AND ( active_flag = 'Y' and enabled_flag =

'Y' ) order by vendor_number

END OF STMT

       PARSING IN CURSOR行本身包含了关于游标#ID的信息，PARSING IN CURSOR和END OF STMT之间是游标的SQL文本。Oracle内核通常使用这一部分作为一个解析调用的总结，在内核报告游标的PARSE行之前。每个PARSING IN CURSOR行包含游标的以下信息：

       Len：SQL文本的长度；

       Dep：游标递归调用的深度，某些动作会导致递归SQL，如数据库调用需要DD中的信息，激活触发器，PL/SQL块包含SQL；

Uid：解析语句的模式ID；

Oct：Oracle命令类型id；

Lid：用户权限id;

Tim:如果tim为0，那么time_statistics为false。Tim以1 μs = 0.000 001为单位。

       Hv：SQL语句的ID，基本上唯一，但不保证。

       Ad：游标的库缓存地址，在V$SQL中显示。

数据库调用

       数据库调用是Oracle内核中的一个子过程，如果在调用完成时level-1 SQL跟踪是活动的，Oracle内核将基于完成的数据库调用显示一个数据库调用行。如下：

PARSE #54:c=20000,e=11526,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=0,

tim= 1017039304725071

EXEC #1:c=10000,e=12137,p=0,cr=22,cu=0,mis=0,r=1,dep=0,og=4,

tim=1017039275981174

FETCH #3:c=10000,e=306,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,tim=1017039275973158

       ERROR #1:err=1422 tim=148448175

       C：Oracle进程调用期间花费的cpu总时间，以1 μs = 0.000 001为单位。

       E：调用期间墙上时钟的总延迟，以1 μs = 0.000 001为单位。

       P：通过OS磁盘读调用得到Oracle块数；

       Cr：通过consistent mode调用从Oracle数据库缓冲缓存得到的Oracle数据块数；从一致性模式读可能会导致从撤销块的额外一致性模式读；

       Cu：通过current mode调用从Oracle数据库缓冲缓存得到的Oracle数据块数；当前模式读是简单的读取块的当前内容；

       Mis：hard parse的次数，如果为1，则为硬解析；为0，则为软解析。

       R：调用返回的行数，或者DML处理的行数；

       Dep：递归游标的深度；

       Og：调用期间的优化器模式，1 ALL_ROWS；2 FIRST_ROWS；3 RULE；4 CHOOSE；

       Tim：调用动作完成时的时间；

       Err：Ora-xxx，发生异常的异常号；

       注意Oracle内核不会将一个数据库调用行写入跟踪文件，直到该动作完成。因为一个超长的数据库操作可能工作了几个小时，但是跟踪文件中没有任何消息。没有经过优化的SQL可能会产生消耗大量CPU的EXEC和FETCH调用。

等待事件

       如果level-8或level-12 SQL跟踪在等待事件完成时活动，Oracle内核会基于完成的事件写入一个WAIT行，如下：

WAIT #1: nam='SQL*Net message to client' ela= 40 p1=1650815232 p2=1 p3=0

WAIT #1: nam='SQL*Net message from client' ela= 1709 p1=1650815232 p2=1 p3=0

WAIT #34: nam='db file sequential read' ela= 14118 p1=52 p2=2755 p3=1

WAIT #44: nam='latch free' ela= 1327989 p1=-1721538020 p2=87 p3=13

       每行包含的信息如下：

       nam：事件名；

       ela：命名事件执行的延迟，以1 μs = 0.000 001 seconds为单位；

       p1, p2, p3，对应select name, parameter1, parameter2, parameter3 from v$event_name order by name

       注意：WAIT行出现在激活它们的数据库调用之前，这在等待事件完成时Oracle内核写入跟踪文件。

绑定变量

       如果启用了level-4或level-12 SQL跟踪，Oracle将显示BINDS区域：

=====================

PARSING IN CURSOR #1 len=105 dep=0 uid=56 oct=47 lid=56 tim=1017039275982462

hv=2108922784 ad='98becef8'

declare dummy boolean;begin fnd_profile.get_specific(:name, :userid, :respid, :

applid, :val, dummy);end;

END OF STMT

...

Several lines have been omitted for clarity

...

BINDS #1:

bind 0: dty=1 mxl=2000(1998) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=2000

offset=0

bfp=025a74a0 bln=2000 avl=19 flg=05

value="MFG_ORGANIZATION_ID"

bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=72 offset=0

bfp=025a744c bln=22 avl=04 flg=05

value=118194

bind 2: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=24

bfp=025a7464 bln=22 avl=05 flg=01

value=1003677

bind 3: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=48

bfp=025a747c bln=22 avl=03 flg=01

value=140

bind 4: dty=1 mxl=2000(1998) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=2000

offset=0

bfp=025ba490 bln=2000 avl=00 flg=05

       BINDS区域包含一个/多个绑定子区域，每个变量都将被绑定，bind单词后面的数字指示了顺序，从0开始，每个区域包含了关于绑定的几个统计，如下：

       Dty（oacdty）：由应用程序提供的值的外部数据类型，外部数据类型是很有价值的，因为有时候我们会发现优化器并没有使用应该使用的索引。

       Avl：绑定变量的长度，以字节为单位；

       Value：绑定变量的值，无论何时当avl的值大于value字段的长度时，值都表示被截断。

行源操作

       如果在游标关闭时level-1 SQL跟踪活动，Oracle内核将为SQL执行计划中的每个行源操作写入一个STAT行。

STAT #3 id=1 cnt=5 pid=0 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=20 pr=0 pw=0 time=451 us)'

STAT #3 id=2 cnt=5 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=15 pr=0 pw=0 time=269 us)'

STAT #3 id=3 cnt=5 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=10 pr=0 pw=0 time=94 us)'

STAT #3 id=4 cnt=0 pid=1 pos=2 obj=708 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=5 pr=0 pw=0 time=102 us)'

STAT #3 id=5 cnt=0 pid=4 pos=1 obj=709 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=5 pr=0 pw=0 time=48 us)'

       如果找不到，是因为在在游标关闭以前，跟踪已经停止。每个STAT行包含游标执行计划的以下统计：

       ID：在STAT行集内，行源操作的唯一ID；

       Cnt：该行源操作返回的行数；

       Pid：该操作的父操作ID；

       Pos：未知；

       Obj：行源操作的对象ID，如果操作是基于基对象的，对于不在基对象上操作的，如NESTED LOOPS,该值为0。

       Op：行源操作的名称。

              Cr：一致性模式读的块数；

              Time：延迟时间，以微秒为单位；

              W：使用OS调用写入的块数；

              R：使用OS调用读取的块数；

       父行源的统计是子行源统计的聚集；

事务和标记符

       如果在COMMIT/ROLLBACK发生期间，level-1 SQL跟踪是活动的，那么Oracle内核将在根据完成的数据库调用写入一个XCTEND行。如下：

       XCTEND rlbk=0, rd_only=0

       XCTEND包含以下统计：

       Rlbk：事务回滚时为1；

       rd_only：如果事务没有改变数据库中的任何数据，则为1；

       XCTEND标记符没有游标ID引用。

参考总结

字段	游标ID	数据库调用	等待事件	描述
C		√		数据库调用耗费的CPU总时间，以微秒为单位；
Cr		√
Cu		√
Dep	√	√
E		√		数据库调用耗费的总延迟，以微秒为单位；
Ela			√	等待事件耗费的总延迟，以微秒为单位；
Hv	√			语句id;
Mis		√		硬解析的次数
nam			√	等待事件名
P		√		OS调用读取的数据库块数；
p1, p2, p3			√
tim	√	√		事件完成的内部Oracle时间；

Oracle时间单元

      

      

 

响应时间计算

       Oracle内核在跟踪文件中记录两种类型的时间：

1．  在数据库调用内消耗的时间；

2．  在数据库调用之间消耗的时间；

一个会话的全部响应时间等于数据库调用内耗费的时间+数据库调用之间耗费的全部时间。

数据库调用内消耗的时间

=====================

PARSING IN CURSOR #4 len=132 dep=1 uid=0 oct=3 lid=0 tim=1033064137929238 hv=3111103299

ad='517ba4d8'

select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1

and part=:2 and version=:3 order by piece#

END OF STMT

PARSE #4:c=0,e=306,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137929139

EXEC #4:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137931262

_ WAIT #4: nam='db file sequential read' ela= 13060 p1=1 p2=53903 p3=1

_ WAIT #4: nam='db file sequential read' ela= 6978 p1=1 p2=4726 p3=1

_ FETCH #4:c=0,e=21340,p=2,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137953092

STAT #4 id=1 cnt=0 pid=0 pos=0 obj=72 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ '

STAT #4 id=2 cnt=0 pid=1 pos=1 obj=120 op='INDEX RANGE SCAN '

       以上跟踪文件显示了在数据库调用内消耗的时间。

       其中第一个调用解析调用花费了306 μs，EXEC调用消耗了额外的146 μs，两个数据库读操作。最后，负载执行这些读操作的父操作是FETCH调用。FETCH调用的总时间计算公式如下：

    

       一个数据调用的e是指整个数据库调用的总延迟。E包括了数据库调用的c，包括ela（在数据库调用上下文中等待事件花费的延迟）的值。

数据库调用之间的延迟

       Oracle内核同时报告在数据库调用之间发生的等待事件的延迟。如：

=====================

PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466757 hv=2475520707

ad='d4c55480'

INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID,

TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:MI:

SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility With Other

Materials" ) + ": " , log_omission ( "Materials to Avoid: " ) )', 'sa', 222, 54213, 'NO_

LANG')

END OF STMT

PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1716466757

WAIT #9: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0

WAIT #9: nam='SQL*Net message from client' ela= 3 p1=1413697536 p2=1 p3=0

=====================

PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466760 hv=2475520707

ad='d4c55480'

INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID,

TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:MI:

SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility With Other

Materials" ) + ": " , log_omission ( "Materials to Avoid: " ) )', 'sa', 222, 54213, 'NO_

LANG')

END OF STMT

PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1716466760

       此处，应用程序的扩展性不是很好，因为解析过于频繁。黑体显示了两个相同的SQL的连续解析。

 

递归SQL计数

父子关系

       能够引起递归SQL的语句包括DDL，PL/SQL，触发器，以及各类能够造成DD访问的DML。任何能够造成其他数据库调用的数据库调用都能造成递归SQL。

=====================

_ PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=1033174180230513

hv=1966425544 ad='514bb478'

select text from view$ where rowid=:1

END OF STMT

_ PARSE #2:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033174180230481

_ BINDS #2:

bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16 offset=0

bfp=0a22c34c bln=16 avl=16 flg=05

value=00000AB8.0000.0001

_ EXEC #2:c=0,e=176,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033174180230878

_ FETCH #2:c=0,e=89,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1033174180231021

_ STAT #2 id=1 cnt=1 pid=0 pos=0 obj=62 op='TABLE ACCESS BY USER ROWID VIEW$ '

=====================

_ PARSING IN CURSOR #1 len=85 dep=0 uid=5 oct=3 lid=5 tim=1033174180244680

hv=1205236555 ad='50cafbec'

select object_id, object_type, owner, object_name from dba_objects where object_id=:v

END OF STMT

_PARSE #1:c=10000,e=15073,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=0,tim=1033174180244662

       游标二是由于执行游标一引起的。确定数据库调用的递归关系的方法：

       一个dep=n + 1的数据库调用是在跟踪文件中列出的第一个随后的dep=n数据库调用的子递归。原因如下：

parse DBA_OBJECTS query

    # query VIEW$ to obtain the definition of DBA_OBJECTS

    parse VIEW$ query

        # execute the instructions necessary for the VIEW$ parse

        emit [1]"PARSING IN CURSOR #2 ..."

        emit [2]"PARSE #2: ..."

    bind to the VIEW$ cursor

        # execute the instructions necessary for the VIEW$ bind

        emit [3]"BINDS #2: ..."

    execute the VIEW$ cursor

        # execute the instructions necessary for the VIEW$ exec

        emit [4]"EXEC #2: ..."

    fetch from the VIEW$ cursor

        # execute the instructions necessary for the VIEW$ fetch

        emit [5]"FETCH #2: ..."

    close the VIEW$ cursor

        # execute the instructions necessary for the VIEW$ close

        emit [6]"STAT #2: ..."

    # execute the remaining instructions for the DBA_OBJECTS parse

    emit [7]"PARSING IN CURSOR #1 ..."

    emit [8]"PARSE #1: ..." 

Oracle内核只能在动作完成后才能在跟踪文件中写入数据库调用。内核无法计算调用的延迟，除非动作完成了。因此可以重构第一个指令的顺序如上，其构成图表如下：

递归统计

       在Oracle9i Release 2中，一个数据库调用的c, e, p, cr, cu统计包含数据库调用自身和其所有递归消耗的资源。如下：

      

       内核仅报告聚集统计，但是可以从这些统计推算出排斥的统计，每个节点自身的值=显示的值-直接下一级的值。Dep=k消耗的资源如下：

      

       因此可以得到如下公式：

一个跟踪文件的总响应时间大约等于递归级别为0的数据库调用的e总和+数据库调用之间的ela的总和。或者等于递归级别为0的数据库调用的c总和+文件中全部ela总和的值。

 

时间模型的革新

       裸跟踪文件使用以下两种方式计算响应时间：

       ·解析调用响应时间的全部CPU时间组件记录在FETCH行本身的c统计上；

       ·系统调用组件的响应时间纪录在于fetch相关的所有WAIT行的ela上。

时钟观察

       当希望从裸跟踪数据提取响应时间时，需要能够诊断事件的时间序列。查看时钟需要理解Oracle内核如何管理时间数据：

       ·行中的tim是指动作大约完成的大约时间；

       ·一个数据库调用的e字段包含那个动作所消耗的总延迟；

       ·递归SQL使用双计算；

       ·不要精确依赖察看时钟。在Oracle9i中以微秒为单位，减少了错误发生的概率。

Oracle Release 8-

       如下：

EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360834

FETCH #13:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360834

EXEC #12:c=2,e=4,p=0,cr=27,cu=0,mis=0,r=0,dep=1,og=4,tim=198360837

FETCH #12:c=2,e=10,p=10,cr=19,cu=4,mis=0,r=1,dep=1,og=4,tim=198360847

   

Oracle Release 9

       在Oracle9i中引入了微秒输出。该技术允许我们能够更加清楚地明白Oracle内核的行为。如下：

EXEC #1:c=0,e=1863,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1017039275956134

FETCH #1:c=0,e=2566,p=0,cr=23,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275958821

FETCH #1:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959013

FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959155

FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959293

FETCH #1:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959433

       计算各个时间如下：

       由于这是以微秒为单位的，因此很明显可以看到，如果使用CS，这些信息将不可见。

       并且，在Oracle9i跟踪文件中，并非所有的跟踪文件行都是以时间升序的。因为Oracle内核在开始计算PARSING IN CURSOR的信息前完成处理EXEC调用，但是，Oracle内核在输出EXEC前输出PARSING IN CURSOR。因此，会输出这种情况。这种情况再Oracle 8i之前也会有，但是Oracle9i中更加明显。

时钟查看公式

tim和e的关系如下：

或者

因此当前行的tim字段大约等于下一行的tim-下一行的e。

       因为WAIT行没有tim字段，如果希望计算WAIT行大约的tim值，可以使用以下关系推算：

      

归因转移

       当在Oracle extended SQL跟踪文件中识别出消耗时间的等待事件后，通常下一步的任务是确定应该更改哪一个应用程序减少时间消耗。应该将每个WAIT #n归因于WAIT之前的游标#n的第一次调用。这可以帮助精确的识别出哪个应用程序导致了这个响应时间。

调用事件内的转移

       对于调用的事件，比较容易理解，因为写入跟踪文件的每一行响应于动作的结束。如下：

=====================

PARSING IN CURSOR #4 len=132 dep=1 uid=0 oct=3 lid=0 tim=1033064137929238

hv=3111103299 ad='517ba4d8'

select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where

obj#=:1 and part=:2 and version=:3 order by piece#

END OF STMT

PARSE #4:c=0,e=306,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137929139

EXEC #4:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137931262

_ WAIT #4: nam='db file sequential read' ela= 13060 p1=1 p2=53903 p3=1

_ WAIT #4: nam='db file sequential read' ela= 6978 p1=1 p2=4726 p3=1

_ FETCH #4:c=0,e=21340,p=2,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137953092

       这个例子中，db file sequential read事件上下文在FETCH的内部执行。

调用事件之间的转移

       对于数据库调用之间的事件，归因转移比较复杂。一般是跟在fetch之后的wait行。

 

详细的跟踪文件浏览

       每个SQL跟踪文件首先描述数据库相关的信息；

       随后报告时间和相关的会话信息；

       之后显示模块和动作名，如果使用DBMS_APPLICATION_INFO设置了；

       内核记录到跟踪文件中的第一条实际的动作是ALTER SESSION，但是内核不会纪录ALTER SESSION的解析，因为跟踪直到解析后才会被启用。如下：

=====================

PARSING IN CURSOR #1 len=69 dep=0 uid=5 oct=42 lid=5 tim=1038931660052098

hv=1509700594 ad='50d6d560'

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

END OF STMT

EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660051673