Chinaunix首页 | 论坛 | 博客
  • 博客访问: 1188890
  • 博文数量: 398
  • 博客积分: 10110
  • 博客等级: 上将
  • 技术积分: 4055
  • 用 户 组: 普通用户
  • 注册时间: 2007-12-23 20:01
个人简介

新博客http://www.cnblogs.com/zhjh256 欢迎访问

文章分类

全部博文(398)

文章存档

2012年(1)

2011年(41)

2010年(16)

2009年(98)

2008年(142)

2007年(100)

我的朋友

分类: Oracle

2008-01-22 21:17:13

跟踪文件浏览

       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代表一个简单的数据库调用,其中ce分别代表这个调用花费的CPU总时间和总延迟时间。P代表通过OS读调用得到的数据库块数,或者通过数据库缓冲缓存提取的块数(cr代表一致性读模式,cu代表当前模式),库缓存未命中的次数mis,调用返回的行数rtim代表调用大约完成的时间。

       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=mV$SESSION.SERIAL#=n。该信息在MTS下特别有用,该信息提示了跟踪文件中信息代表的会话的工作。

应用程序标识符

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

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

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

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

       Act通过SET_ACTIONSET_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 CURSOREND OF STMT之间是游标的SQL文本。Oracle内核通常使用这一部分作为一个解析调用的总结,在内核报告游标的PARSE行之前。每个PARSING IN CURSOR行包含游标的以下信息:

       LenSQL文本的长度;

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

Uid:解析语句的模式ID

OctOracle命令类型id

Lid:用户权限id;

Tim:如果tim0,那么time_statisticsfalseTim1 μs = 0.000 001为单位。

       HvSQL语句的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

       COracle进程调用期间花费的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数据块数;当前模式读是简单的读取块的当前内容;

       Mishard parse的次数,如果为1,则为硬解析;为0,则为软解析。

       R:调用返回的行数,或者DML处理的行数;

       Dep:递归游标的深度;

       Og:调用期间的优化器模式,1 ALL_ROWS2 FIRST_ROWS3 RULE4 CHOOSE

       Tim:调用动作完成时的时间;

       ErrOra-xxx,发生异常的异常号;

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

等待事件

       如果level-8level-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-4level-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开始,每个区域包含了关于绑定的几个统计,如下:

       Dtyoacdty):由应用程序提供的值的外部数据类型,外部数据类型是很有价值的,因为有时候我们会发现优化器并没有使用应该使用的索引。

       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 μsEXEC调用消耗了额外的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的语句包括DDLPL/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中更加明显。

时钟查看公式

time的关系如下:

或者

因此当前行的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

   

阅读(2251) | 评论(0) | 转发(0) |
0

上一篇:SQL调优基础

下一篇:mysql 连接错误

给主人留下些什么吧!~~