10046和dtrace研究一致读

<pre name="code" class="sql">SESSION 1:
SQL> update t set owner='AA' where object_id=500;

已更新 1 行。


SQL>   select xidusn,xidslot,xidsqn,ubablk,ubafil,ubarec,to_char(START_SCN,'9999999999999') from v$transaction;

    XIDUSN    XIDSLOT     XIDSQN     UBABLK     UBAFIL     UBAREC TO_CHAR(START_
---------- ---------- ---------- ---------- ---------- ---------- --------------
         4         30        903        413          3          1        1023079

SQL>  select name from v$rollname where usn=4;

NAME
------------------------------
_SYSSMU4_2140711993$




SQL> select spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum < 2));

SPID
------------------------
2744

SQL>  alter system flush BUFFER_CACHE;

系统已更改。

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

会话已更改。

SQL> select * from test.t where  object_id=500;

 OBJECT_ID OWNER
---------- ------------------------------
       500 SYS

SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

会话已更改。



PARSING IN CURSOR #18446741324891889432 len=41 dep=0 uid=0 oct=3 lid=0 tim=49676949297 hv=263580754 ad='ee3e8460' sqlid='bjdqj107vbv2k'
select * from test.t where  object_id=500
END OF STMT
PARSE #18446741324891889432:c=1260,e=1260,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=51703167,tim=49676949285
EXEC #18446741324891889432:c=103,e=103,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=51703167,tim=49676949453
WAIT #18446741324891889432: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=5541 tim=49676949491
WAIT #18446741324891889432: nam='Disk file operations I/O' ela= 75 FileOperation=2 fileno=5 filetype=2 obj#=88606 tim=49676949733
WAIT #18446741324891889432: nam='db file scattered read' ela= 203 file#=5 block#=496 blocks=8 obj#=88606 tim=49676949967
WAIT #18446741324891889432: nam='db file sequential read' ela= 9 file#=5 block#=491 blocks=1 obj#=88605 tim=49676950124
WAIT #18446741324891889432: nam='Disk file operations I/O' ela= 20 FileOperation=2 fileno=3 filetype=2 obj#=0 tim=49676950199
WAIT #18446741324891889432: nam='db file sequential read' ela= 7 file#=3 block#=176 blocks=1 obj#=0 tim=49676950218
FETCH #18446741324891889432:c=1001,e=1001,p=10,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=51703167,tim=49676950519
STAT #18446741324891889432 id=1 cnt=1 pid=0 pos=1 obj=88605 op='TABLE ACCESS BY INDEX ROWID T (cr=5 pr=10 pw=0 time=1005 us cost=2 size=8 card=1)'
STAT #18446741324891889432 id=2 cnt=1 pid=1 pos=1 obj=88606 op='INDEX UNIQUE SCAN T_ID_PK (cr=2 pr=8 pw=0 time=588 us cost=1 size=0 card=1)'
WAIT #18446741324891889432: nam='SQL*Net message from client' ela= 250 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=49676950883
FETCH #18446741324891889432:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=51703167,tim=49676950910
WAIT #18446741324891889432: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=49676950925

*** 2014-08-24 11:54:39.961
WAIT #18446741324891889432: nam='SQL*Net message from client' ela= 5981149 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=49682932083
CLOSE #18446741324891889432:c=9,e=10,dep=0,type=0,tim=49682932215
=====================
PARSING IN CURSOR #18446741324891889432 len=55 dep=0 uid=0 oct=42 lid=0 tim=49682932360 hv=2655499671 ad='0' sqlid='0kjg1c2g4gdcr'
ALTER SESSION SET EVENTS '10046 trace name context off'
END OF STMT
PARSE #18446741324891889432:c=102,e=103,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=49682932360
EXEC #18446741324891889432:c=294,e=295,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=49682933264

ela 表示消耗时间,单位毫秒

WAIT #18446741324891889432: nam='db file scattered read' ela= 203 file#=5 block#=496 blocks=8 obj#=88606 tim=49676949967
WAIT #18446741324891889432: nam='db file sequential read' ela= 9 file#=5 block#=491 blocks=1 obj#=88605 tim=49676950124

WAIT #18446741324891889432: nam='db file sequential read' ela= 7 file#=3 block#=176 blocks=1 obj#=0 tim=49676950218


-bash-3.2# ./dtrace1.d 2744
    1 pid2744:oracle:kcbgtcr:entry 0x014001f3[5,499]  --T_ID_PK
    2 pid2744:oracle:kcbgtcr:entry 0x014001f4[5,500]  --T_ID_PK
    3 pid2744:oracle:kcbgtcr:entry 0x014001eb[5,491]  --T
    4 pid2744:oracle:kcbgtcr:entry 0x00c000b0[3,176]  --_SYSSMU4_2140711993$段头
    5 pid2744:oracle:kcbgtcr:entry 0x00c0019d[3,413]  --UNDO 块

object_id='88606' --T_ID_PK

object_id='88605' --T



和dtrace 的结果完全不一致


可以看到10046的输出和dtrace存在差异