Thursday, September 22, 2005
Trace Changes in 10.2
I was intrigued by one of Cary Millsap and Tom Kytes favourite new features in 10.2 I thought I'd have a look at a 10.2 trace file. There surely is a lot more information in there. I have a table t1 which is just a copy of all_objects with no indexes etc. I ran select count(*) from t1; against it in 10gr1 and 10gr2. About as simple a test case as you can get.
The 10.1 output
Now here is the 10.2 output
So 10.2 has the timestamps for the wait events (as Tom mentioned), in addition the p1 to p3 data items get a meaningful description emitted where there is one.
2 Comments
The 10.1 output
PARSING IN CURSOR #9 len=23 dep=0 uid=61 oct=3 lid=61 tim=8536154153 hv=2648217100 ad='25729404'
select count(*)
from t1
END OF STMT
PARSE #9:c=20029,e=403533,p=343,cr=116,cu=0,mis=1,r=0,dep=0,og=1,tim=8536154147
EXEC #9:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=8536154621
WAIT #9: nam='SQL*Net message to client' ela= 5 p1=1111838976 p2=1 p3=0
WAIT #9: nam='db file scattered read' ela= 40330 p1=4 p2=5148 p3=5
WAIT #9: nam='db file scattered read' ela= 1646 p1=4 p2=5153 p3=8
WAIT #9: nam='db file scattered read' ela= 13053 p1=4 p2=5162 p3=3
WAIT #9: nam='db file scattered read' ela= 765 p1=4 p2=5166 p3=3
...
WAIT #9: nam='SQL*Net message from client' ela= 19237 p1=1111838976 p2=1 p3=0
Now here is the 10.2 output
PARSING IN CURSOR #4 len=23 dep=0 uid=61 oct=3 lid=61 tim=881471072 hv=2648217100 ad='6cf05b48'
select count(*)
from t1
END OF STMT
PARSE #4:c=265625,e=1683003,p=544,cr=274,cu=0,mis=1,r=0,dep=0,og=1,tim=881471065
EXEC #4:c=0,e=75,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=881471221
WAIT #4: nam='SQL*Net message to client' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=52566 tim=881471274
WAIT #4: nam='db file scattered read' ela= 28810 file#=4 block#=548 blocks=5 obj#=52566 tim=881500264
WAIT #4: nam='db file scattered read' ela= 1658 file#=4 block#=553 blocks=8 obj#=52566 tim=881502205
WAIT #4: nam='db file scattered read' ela= 16724 file#=4 block#=562 blocks=7 obj#=52566 tim=881526262
WAIT #4: nam='db file scattered read' ela= 1091 file#=4 block#=569 blocks=8 obj#=52566 tim=881527647
WAIT #4: nam='db file scattered read' ela= 321 file#=4 block#=578 blocks=7 obj#=52566 tim=881528277
WAIT #4: nam='db file scattered read' ela= 332 file#=4 block#=585 blocks=8 obj#=52566 tim=881528833
WAIT #4: nam='db file scattered read' ela= 32976 file#=4 block#=594 blocks=7 obj#=52566 tim=881562089
WAIT #4: nam='db file scattered read' ela= 2543 file#=4 block#=601 blocks=8 obj#=52566 tim=881565062
WAIT #4: nam='db file scattered read' ela= 10338 file#=4 block#=610 blocks=7 obj#=52566 tim=881575679
WAIT #4: nam='db file scattered read' ela= 6777 file#=4 block#=617 blocks=8 obj#=52566 tim=881582714
WAIT #4: nam='db file scattered read' ela= 1402 file#=4 block#=626 blocks=7 obj#=52566 tim=881584403
......
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=52566 tim=887316187
WAIT #4: nam='SQL*Net message from client' ela= 40457 driver id=1111838976 #bytes=1 p3=0 obj#=52566 tim=887356685
So 10.2 has the timestamps for the wait events (as Tom mentioned), in addition the p1 to p3 data items get a meaningful description emitted where there is one.
2 Comments:
The tool I wrote would read in the values of p1,p2,p3 from v$event_name and map them together. Now, no longer need that file/db connection. Having time stamps in the WAIT lines are a real bonus.
While these are a nice addition, in 10gR1, the actual latch and enqueue names are in the nam field. Really nice! No longer have to translate p1 values to determine what specific enqueue or having to map against v$latchname to find out what specific latch.
Post a Comment
While these are a nice addition, in 10gR1, the actual latch and enqueue names are in the nam field. Really nice! No longer have to translate p1 values to determine what specific enqueue or having to map against v$latchname to find out what specific latch.
# posted by 
: 8:58 PM, September 22, 2005
: 8:58 PM, September 22, 2005
