Search My Oracle Blog

Custom Search

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:

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016