18 July, 2009

Simple Tracing

A recent forums.oracle.com thread indicating possible errors in DUAL led me to create this post.

See this extract from a trace I created (Note : It is NOT the complete trace !) :

PARSING IN CURSOR #27 len=18 dep=0 uid=64 oct=3 lid=64 tim=1218679391705217 hv=942515969 ad='8f207e60'
select * from dual
END OF STMT
PARSE #27:c=1000,e=1643,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1218679391705206
BINDS #27:
EXEC #27:c=0,e=178,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1218679391705795
WAIT #27: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1218679391705922
FETCH #27:c=0,e=128,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1218679391706151
WAIT #27: nam='SQL*Net message from client' ela= 440 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1218679391706794
FETCH #27:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1218679391706966
WAIT #27: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1218679391707111
*** 2009-07-18 22:35:07.104
WAIT #27: nam='SQL*Net message from client' ela= 9761620 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1218679401468827
STAT #27 id=1 cnt=1 pid=0 pos=1 obj=258 op='TABLE ACCESS FULL DUAL (cr=3 pr=0 pw=0 time=116 us)'
XCTEND rlbk=0, rd_only=1
=====================
PARSING IN CURSOR #20 len=37 dep=0 uid=64 oct=19 lid=64 tim=1218679401470001 hv=0 ad='aca5fc08'
create synonym my_t_a for test_append
END OF STMT
PARSE #20:c=0,e=555,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1218679401469996
BINDS #20:
=====================
PARSING IN CURSOR #12 len=94 dep=1 uid=47 oct=3 lid=47 tim=1218679401475875 hv=1451648271 ad='8f2851e0'
select dummy from dual where ora_dict_obj_type = 'SYNONYM' AND ora_dict_obj_owner = 'PUBLIC'
END OF STMT
PARSE #12:c=4999,e=5279,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1218679401475861
BINDS #12:
EXEC #12:c=0,e=443,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1218679401476760
FETCH #12:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1218679401476870
STAT #12 id=1 cnt=0 pid=0 pos=1 obj=0 op='FILTER (cr=0 pr=0 pw=0 time=288 us)'
STAT #12 id=2 cnt=0 pid=1 pos=1 obj=258 op='TABLE ACCESS FULL DUAL (cr=0 pr=0 pw=0 time=0 us)'
=====================
PARSING IN CURSOR #25 len=198 dep=1 uid=0 oct=3 lid=0 tim=1218679401478610 hv=4125641360 ad='942f7470'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
PARSE #25:c=1000,e=1079,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1218679401478602
BINDS #25:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2aaaacafcbd8 bln=22 avl=02 flg=05
value=64
Bind#1
oacdty=01 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
oacflg=18 fl2=0001 frm=01 csi=31 siz=32 off=0
kxsbbbfp=2aaaacafcba0 bln=32 avl=06 flg=05
value="MY_T_A"
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2aaaacafcb70 bln=24 avl=02 flg=05
value=1
EXEC #25:c=3000,e=3453,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1218679401482554
FETCH #25:c=0,e=94,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1218679401482787
STAT #25 id=1 cnt=0 pid=0 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=2 pr=0 pw=0 time=104 us)'
STAT #25 id=2 cnt=0 pid=1 pos=1 obj=37 op='INDEX RANGE SCAN I_OBJ2 (cr=2 pr=0 pw=0 time=90 us)'
BINDS #26:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2aaaacafcbd8 bln=22 avl=02 flg=05
value=1
Bind#1
oacdty=01 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
oacflg=18 fl2=0001 frm=01 csi=31 siz=32 off=0
kxsbbbfp=2aaaacafcba0 bln=32 avl=06 flg=05
value="MY_T_A"
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2aaaacafcb70 bln=24 avl=02 flg=05
value=1
=====================
PARSING IN CURSOR #26 len=198 dep=1 uid=0 oct=3 lid=0 tim=1218679401484758 hv=4125641360 ad='942f7470'
select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #26:c=1000,e=1261,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1218679401484749
WAIT #26: nam='db file sequential read' ela= 7469 file#=1 block#=55199 blocks=1 obj#=0 tim=1218679401492652
FETCH #26:c=1000,e=7766,p=1,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1218679401492875
=====================

These are my notes :
1. Cursor#27 (being of 18 characters, indicated by "len") is the SQL statement "select * from dual"
2. There are 2 "FETCH" calls for this. The first returns 1 row but Oracle does another fetch as well.
3. The STAT line for this cursor indicate that it returned 1 row (indicated by "cnt") doing a "TABLE ACCESS FULL DUAL".
4. Finaly there is an End Transaction marker with a "XCTEND rlbk=0". Why is this so ? Because the *subsequent* SQL statement is a DDL. A DDL causes an Implicit Commit.

So, now we see
5. Cursor#20 is the SQL statement "create synonym my_t_a for test_append"
6. This causes multiple *recursive* calls. Of these, I paste only the first three ! ("dep=1" indicates that the next SQLs are recursive).
7. Before Cursor#20 can complete, it is the recursive calls, beginning with Cursor #12 that must execute.
8. Cursor #12 is "select dummy from dual where ora_dict_obj_type = 'SYNONYM' AND ora_dict_obj_owner = 'PUBLIC'" which means that Oracle is doing some validation.
9. The STAT lines for Cursor #12 indicate that Oracle does a FULL TABLE SCAN of DUAL. This actually returns 0 rows (indicated by "cnt=0"), as it should (you can validate it by running the same SQL).
10. The next recursive SQL is Cursor #25 which is obviously a lookup on OBJ$.
Here, I've also posted the Binds as well. So you can see that my DDL statement that attempted to create a synonym called "MY_T_A" is now being validated to see if "MY_T_A" exists in OBJ$ (as name = :2 where 2, being Bind#1 is "MY_T_A") {Note : owner#=:1 being '64' is the USER_ID for 'HEMANT').

What would you say about cursor#26 and it's binds ?

By the way, the entire Trace file for the the completion of that CREATE SYNONYM statement continues to 1,213 lines, with a number of other recursive SQLs thrown in. (The success of the CREATE is finally indicated to me by an "insert into obj$" statement, followed by another "XCTEND rblk=0").

.
.
.

No comments: