Query on trace
vivek Saxena, January 19, 2004 - 11:56 am UTC
Tom,
During the performance testing ( via Load runner ) our client had complained that our application is "SLOW". They are looking for 3200 records/hour and at present we are getting only 2000/hrs. So i have traced a session in our office and come up with following result. What i am not understood is why i am getting parse/exec/fetch for SYS.ALL_ARGUMENTS every time oracle tried to run procedure from a package. Our application has packages containing many procedure with in it.
Here is text from my trace.
=====================
PARSING IN CURSOR #1 len=165 dep=0 uid=45 oct=3 lid=45 tim=94659226 hv=106591048 ad='422ce00'
SELECT UNIQUE POSITION, DATA_TYPE, IN_OUT FROM SYS.ALL_ARGUMENTS WHERE OBJECT_ID = 31455 AND OBJECT_NAME = 'SP_ATTENDEE_TYPE' AND DATA_LEVEL=0 ORDER BY POSITION DESC
END OF STMT
PARSE #1:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659229
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659229
FETCH #1:c=1,e=2,p=0,cr=15,cu=0,mis=0,r=1,dep=0,og=4,tim=94659231
=====================
PARSING IN CURSOR #39 len=50 dep=0 uid=45 oct=47 lid=45 tim=94659231 hv=883693539 ad='422be94'
BEGIN PKG_RBK_COMMON.SP_ATTENDEE_TYPE ( :V1); END;
END OF STMT
PARSE #39:c=4,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659234
=====================
PARSING IN CURSOR #47 len=65 dep=1 uid=42 oct=3 lid=42 tim=94659235 hv=831795434 ad='47efc1c'
SELECT ATTEND_TYPE FROM RM_ATTENDTYPE ORDER BY ATTEND_TYPE DESC
END OF STMT
PARSE #47:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659237
EXEC #47:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659237
EXEC #39:c=4,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659239
FETCH #47:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=5,dep=0,og=4,tim=94659239
STAT #47 id=1 cnt=5 pid=0 pos=0 obj=31579 op='INDEX FULL SCAN DESCENDING '
XCTEND rlbk=0, rd_only=1
STAT #1 id=1 cnt=1 pid=0 pos=0 obj=0 op='SORT ORDER BY '
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT UNIQUE '
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=0 op='FILTER '
STAT #1 id=4 cnt=2 pid=3 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=5 cnt=2 pid=4 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=6 cnt=2 pid=5 pos=1 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ '
STAT #1 id=7 cnt=2 pid=6 pos=1 obj=33 op='INDEX UNIQUE SCAN '
STAT #1 id=8 cnt=2 pid=5 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ '
STAT #1 id=9 cnt=2 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN '
STAT #1 id=10 cnt=2 pid=4 pos=2 obj=63 op='TABLE ACCESS BY INDEX ROWID ARGUMENT$ '
STAT #1 id=11 cnt=4 pid=10 pos=1 obj=108 op='INDEX RANGE SCAN '
STAT #1 id=13 cnt=1 pid=3 pos=3 obj=0 op='NESTED LOOPS '
STAT #1 id=14 cnt=2 pid=13 pos=1 obj=0 op='FIXED TABLE FULL X$KZSRO '
STAT #1 id=15 cnt=2 pid=13 pos=2 obj=82 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ '
STAT #1 id=16 cnt=2 pid=15 pos=1 obj=101 op='INDEX RANGE SCAN '
STAT #1 id=12 cnt=1 pid=3 pos=2 obj=0 op='FIXED TABLE FULL X$KZSPR '
=====================
PARSING IN CURSOR #1 len=69 dep=0 uid=45 oct=47 lid=45 tim=94659254 hv=1302911214 ad='56e5370'
begin dbms_utility.name_resolve(:v1,:v2,:v3,:v4,:v5,:v6,:v7,:v8);end;
END OF STMT
PARSE #1:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659256
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659257
=====================
PARSING IN CURSOR #1 len=168 dep=0 uid=45 oct=3 lid=45 tim=94659259 hv=4229066408 ad='4288c3c'
SELECT UNIQUE POSITION, DATA_TYPE, IN_OUT FROM SYS.ALL_ARGUMENTS WHERE OBJECT_ID = 31451 AND OBJECT_NAME = 'SP_ATTENDEE_DETAILS' AND DATA_LEVEL=0 ORDER BY POSITION DESC
END OF STMT
PARSE #1:c=4,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659260
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659260
FETCH #1:c=0,e=0,p=0,cr=18,cu=0,mis=0,r=3,dep=0,og=4,tim=94659262
=====================
PARSING IN CURSOR #38 len=66 dep=0 uid=45 oct=47 lid=45 tim=94659264 hv=879131564 ad='4279c88'
BEGIN PKG_RBK_DETAILS.SP_ATTENDEE_DETAILS ( :V1, :V2, :V3); END;
END OF STMT
PARSE #38:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=94659265
=====================
PARSING IN CURSOR #47 len=727 dep=1 uid=42 oct=3 lid=42 tim=94659267 hv=801113033 ad='44af3e4'
SELECT RM_ATTENDEE.ADD_COMMENTS,RM_ATTENDEE.ATTEND_TYPE,RM_ATTENDEE.AUTO_NUMBER,RM_ATTENDEE.BL_ID,RM_ATTENDEE.BOOKING_ID,RM_ATTENDEE.CONTACT_TEL,RM_ATTENDEE.DATE_CREATED,RM_ATTENDEE.DATE_OF_VISIT,RM_ATTENDEE.INT_CONTACT,RM_ATTENDEE.NAME_FIRST,RM_ATTENDEE.NAME_LAST,RM_ATTENDEE.REQUEST_ID,RM_ATTENDEE.STATUS,RM_ATTENDEE.TIME_CREATED,RM_ATTENDEE.TIME_EXPECTED,RM_ATTENDEE.VISITOR_PASS,RM_ATTENDEE.TIME_IN,RM_ATTENDEE.TIME_OUT,EM.NAME_LAST CONTACTNAMELAST,EM.NAME_FIRST CONTACTNAMEFIRST FROM RM_ATTENDEE,EM WHERE RM_ATTENDEE.REQUEST_ID = :b1 AND RM_ATTENDEE.BOOKING_ID = :b2 AND RM_ATTENDEE.INT_CONTACT = EM.EM_ID (+) ORDER BY RM_ATTENDEE.DATE_OF_VISIT,RM_ATTENDEE.TIME_EXPECTED,RM_ATTENDEE.NAME_LAST,RM_ATTENDEE.NAME_FIRST
END OF STMT
PARSE #47:c=3,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659268
EXEC #47:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=94659270
EXEC #38:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=94659270
FETCH #47:c=0,e=0,p=0,cr=4,cu=4,mis=0,r=1,dep=0,og=4,tim=94659271
STAT #47 id=1 cnt=1 pid=0 pos=0 obj=0 op='SORT ORDER BY '
STAT #47 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER '
STAT #47 id=3 cnt=2 pid=2 pos=1 obj=31580 op='TABLE ACCESS FULL RM_ATTENDEE '
STAT #47 id=4 cnt=1 pid=2 pos=2 obj=25150 op='TABLE ACCESS BY INDEX ROWID EM '
STAT #47 id=5 cnt=2 pid=4 pos=1 obj=25159 op='INDEX UNIQUE SCAN '
XCTEND rlbk=0, rd_only=1
STAT #2 id=1 cnt=1 pid=0 pos=0 obj=27191 op='TABLE ACCESS BY INDEX ROWID CDATA '
STAT #2 id=2 cnt=2 pid=1 pos=1 obj=27192 op='INDEX UNIQUE SCAN '
=====================
This happens every time a procedure is called.
Please help.
Vivek
January 19, 2004 - 1:04 pm UTC
probably using odbc eh? what is the client.