Re: [Fwd: Re: 10046 trace - unaccounted for time]
- From: "Keith Moore" <kmoore@xxxxxxxxxxxx>
- To: kmoore@xxxxxxxxxxxx
- Date: Wed, 6 Aug 2008 16:27:14 -0500 (CDT)
Ok, we got our test system setup and turned on system wide tracing and now
have the SQL statement where the hang occurs. The statement is querying
all_constraints but it is not recursive SQL. It is being called from the
application.
Below is a relevant section of the trace file. It looks like it reuses CURSOR
#12 but the 2nd query is on cdef$ which is also related to constraints. Not
sure I understand that.
It's also still not clear to me whether the unaccounted for time is for Cursor
#12 or Cursor #11 or from something outside this session.
This problem has now been reproduced on a 2nd server with a duplicate of the
database. This server is very lightly loaded so I don't think it is server
related.
Keith
=====================
PARSING IN CURSOR #12 len=370 dep=0 uid=19 oct=3 lid=19 tim=5188376520447
hv=4197965074 ad='eb59a6d8'
SELECT /*+ RULE */ '', b.owner, b.table_name, b.column_name, b.position,
b.constraint_name FROM ALL_CONSTRAINTS a, ALL_CONS_COLUMNS
b WHERE (b.table_name='LSCHANNELCUTDATA' and b.owner='PWRLINE') AND
(a.table_name='LSCHANNELCUTDATA' and a.owner='PWRLINE' and a.con
straint_type='P') AND (a.constraint_name = b.constraint_name) ORDER BY
b.owner, b.table_name, b.position
END OF STMT
PARSE #12:c=30000,e=27460,p=0,cr=4,cu=0,mis=1,r=0,dep=0,og=3,tim=5188376520440
BINDS #12:
EXEC #12:c=0,e=294,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=5188376520993
WAIT #12: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
FETCH
#12:c=210000,e=215303,p=0,cr=26873,cu=0,mis=0,r=1,dep=0,og=3,tim=5188376736498
WAIT #12: nam='SQL*Net message from client' ela= 1307 p1=1413697536 p2=1 p3=0
FETCH #12:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=5188376738979
WAIT #12: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #12: nam='SQL*Net message from client' ela= 1051 p1=1413697536 p2=1 p3=0
STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=26873 r=0 w=0
time=215259 us)'
STAT #12 id=2 cnt=1 pid=1 pos=1 obj=0 op='FILTER (cr=26873 r=0 w=0
time=215042 us)'
STAT #12 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26873 r=0 w=0
time=215004 us)'
STAT #12 id=4 cnt=1 pid=3 pos=1 obj=0 op='NESTED LOOPS (cr=26871 r=0 w=0
time=214938 us)'
STAT #12 id=5 cnt=1 pid=4 pos=1 obj=0 op='NESTED LOOPS (cr=26868 r=0 w=0
time=214856 us)'
STAT #12 id=6 cnt=1 pid=5 pos=1 obj=0 op='NESTED LOOPS (cr=26865 r=0 w=0
time=214797 us)'
STAT #12 id=7 cnt=1 pid=6 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26862 r=0 w=0
time=214683 us)'
STAT #12 id=8 cnt=1 pid=7 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26862 r=0 w=0
time=214647 us)'
STAT #12 id=9 cnt=1 pid=8 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26861 r=0 w=0
time=214602 us)'
STAT #12 id=10 cnt=1 pid=9 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26861 r=0
w=0 time=214561 us)'
STAT #12 id=11 cnt=1 pid=10 pos=1 obj=0 op='NESTED LOOPS (cr=26861 r=0 w=0
time=214531 us)'
STAT #12 id=12 cnt=422 pid=11 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=26015 r=0
w=0 time=209540 us)'
STAT #12 id=13 cnt=422 pid=12 pos=1 obj=0 op='NESTED LOOPS (cr=25591 r=0 w=0
time=206114 us)'
STAT #12 id=14 cnt=4158 pid=13 pos=1 obj=0 op='NESTED LOOPS (cr=17273 r=0 w=0
time=146224 us)'
STAT #12 id=15 cnt=4158 pid=14 pos=1 obj=0 op='NESTED LOOPS (cr=8955 r=0 w=0
time=85745 us)'
STAT #12 id=16 cnt=4158 pid=15 pos=1 obj=0 op='NESTED LOOPS (cr=637 r=0 w=0
time=20752 us)'
STAT #12 id=17 cnt=1 pid=16 pos=1 obj=0 op='NESTED LOOPS (cr=4 r=0 w=0
time=116 us)'
STAT #12 id=18 cnt=1 pid=17 pos=1 obj=22 op='TABLE ACCESS BY INDEX ROWID USER$
(cr=2 r=0 w=0 time=84 us)'
STAT #12 id=19 cnt=1 pid=18 pos=1 obj=41 op='INDEX UNIQUE SCAN I_USER1 (cr=1
r=0 w=0 time=39 us)'
STAT #12 id=20 cnt=1 pid=17 pos=2 obj=22 op='TABLE ACCESS BY INDEX ROWID USER$
(cr=2 r=0 w=0 time=21 us)'
STAT #12 id=21 cnt=1 pid=20 pos=1 obj=41 op='INDEX UNIQUE SCAN I_USER1 (cr=1
r=0 w=0 time=9 us)'
STAT #12 id=22 cnt=4158 pid=16 pos=2 obj=25 op='TABLE ACCESS BY INDEX ROWID
CON$ (cr=633 r=0 w=0 time=18633 us)'
STAT #12 id=23 cnt=4158 pid=22 pos=1 obj=45 op='INDEX RANGE SCAN I_CON1 (cr=13
r=0 w=0 time=6407 us)'
STAT #12 id=24 cnt=4158 pid=15 pos=2 obj=28 op='TABLE ACCESS BY INDEX ROWID
CDEF$ (cr=8318 r=0 w=0 time=53792 us)'
STAT #12 id=25 cnt=4158 pid=24 pos=1 obj=47 op='INDEX UNIQUE SCAN I_CDEF1
(cr=4160 r=0 w=0 time=23782 us)'
STAT #12 id=26 cnt=4158 pid=14 pos=2 obj=25 op='TABLE ACCESS BY INDEX ROWID
CON$ (cr=8318 r=0 w=0 time=48156 us)'
STAT #12 id=27 cnt=4158 pid=26 pos=1 obj=45 op='INDEX UNIQUE SCAN I_CON1
(cr=4160 r=0 w=0 time=26274 us)'
STAT #12 id=28 cnt=422 pid=13 pos=2 obj=28 op='TABLE ACCESS BY INDEX ROWID
CDEF$ (cr=8318 r=0 w=0 time=49692 us)'
STAT #12 id=29 cnt=4158 pid=28 pos=1 obj=47 op='INDEX UNIQUE SCAN I_CDEF1
(cr=4160 r=0 w=0 time=20922 us)'
STAT #12 id=30 cnt=422 pid=12 pos=2 obj=33 op='INDEX UNIQUE SCAN I_OBJ1
(cr=424 r=0 w=0 time=2309 us)'
STAT #12 id=31 cnt=1 pid=11 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$
(cr=846 r=0 w=0 time=4200 us)'
STAT #12 id=32 cnt=422 pid=31 pos=1 obj=33 op='INDEX UNIQUE SCAN I_OBJ1
(cr=424 r=0 w=0 time=1827 us)'
STAT #12 id=33 cnt=0 pid=10 pos=2 obj=33 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0
r=0 w=0 time=1 us)'
STAT #12 id=34 cnt=0 pid=9 pos=2 obj=25 op='TABLE ACCESS BY INDEX ROWID CON$
(cr=0 r=0 w=0 time=3 us)'
STAT #12 id=35 cnt=0 pid=34 pos=1 obj=46 op='INDEX UNIQUE SCAN I_CON2 (cr=0
r=0 w=0 time=0 us)'
STAT #12 id=36 cnt=0 pid=8 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=1
r=0 w=0 time=12 us)'
STAT #12 id=37 cnt=0 pid=36 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=1
r=0 w=0 time=11 us)'
STAT #12 id=38 cnt=0 pid=7 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0
r=0 w=0 time=2 us)'
STAT #12 id=39 cnt=0 pid=38 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0
r=0 w=0 time=0 us)'
STAT #12 id=40 cnt=1 pid=6 pos=2 obj=29 op='TABLE ACCESS BY INDEX ROWID CCOL$
(cr=3 r=0 w=0 time=72 us)'
STAT #12 id=41 cnt=1 pid=40 pos=1 obj=52 op='INDEX RANGE SCAN I_CCOL2 (cr=2
r=0 w=0 time=55 us)'
STAT #12 id=42 cnt=1 pid=5 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$
(cr=3 r=0 w=0 time=26 us)'
STAT #12 id=43 cnt=1 pid=42 pos=1 obj=33 op='INDEX UNIQUE SCAN I_OBJ1 (cr=2
r=0 w=0 time=11 us)'
STAT #12 id=44 cnt=1 pid=4 pos=2 obj=21 op='TABLE ACCESS BY INDEX ROWID COL$
(cr=3 r=0 w=0 time=45 us)'
STAT #12 id=45 cnt=1 pid=44 pos=1 obj=44 op='INDEX UNIQUE SCAN I_COL3 (cr=2
r=0 w=0 time=22 us)'
=====================
PARSING IN CURSOR #11 len=116 dep=1 uid=0 oct=3 lid=0 tim=5188376745310
hv=431456802 ad='ebf8c1d0'
select
o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj#,o.flags
from obj$ o where o.obj#=:1
END OF STMT
PARSE #11:c=0,e=193,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5188376745302
BINDS #11:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=1033da928 bln=22 avl=03 flg=05
value=244
EXEC #11:c=0,e=329,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5188376745992
FETCH #11:c=0,e=91,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=5188376746151
STAT #12 id=46 cnt=0 pid=3 pos=2 obj=244 op='TABLE ACCESS CLUSTER ATTRCOL$
(cr=2 r=0 w=0 time=34 us)'
STAT #12 id=47 cnt=0 pid=2 pos=2 obj=0 op='NESTED LOOPS (cr=0 r=0 w=0 time=0
us)'
STAT #12 id=48 cnt=0 pid=47 pos=1 obj=309 op='FIXED TABLE FULL X$KZSRO (cr=0
r=0 w=0 time=0 us)'
STAT #12 id=49 cnt=0 pid=47 pos=2 obj=101 op='INDEX RANGE SCAN I_OBJAUTH2
(cr=0 r=0 w=0 time=0 us)'
STAT #12 id=50 cnt=0 pid=2 pos=2 obj=310 op='FIXED TABLE FULL X$KZSPR (cr=0
r=0 w=0 time=0 us)'
STAT #12 id=51 cnt=0 pid=2 pos=2 obj=0 op='NESTED LOOPS (cr=0 r=0 w=0 time=0
us)'
STAT #12 id=52 cnt=0 pid=51 pos=1 obj=309 op='FIXED TABLE FULL X$KZSRO (cr=0
r=0 w=0 time=0 us)'
STAT #12 id=53 cnt=0 pid=51 pos=2 obj=101 op='INDEX RANGE SCAN I_OBJAUTH2
(cr=0 r=0 w=0 time=0 us)'
STAT #12 id=54 cnt=0 pid=2 pos=2 obj=310 op='FIXED TABLE FULL X$KZSPR (cr=0
r=0 w=0 time=0 us)'
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=5188376747198
WAIT #3: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #3: nam='SQL*Net message from client' ela= 51308 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #11 len=69 dep=0 uid=19 oct=3 lid=19 tim=5188376801958
hv=2860960970 ad='eb55e868'
SELECT "UIDCHANNELCUT","VALUECODES" FROM "PWRLINE"."LSCHANNELCUTDATA"
END OF STMT
PARSE #11:c=0,e=2760,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=5188376801943
WAIT #11: nam='SQL*Net message to client' ela= 6 p1=1413697536 p2=1 p3=0
WAIT #11: nam='SQL*Net message from client' ela= 2051 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #12 len=42 dep=1 uid=0 oct=3 lid=0 tim=5188376805824
hv=1307778841 ad='ebd7ef98'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #12:c=0,e=145,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5188376805816
BINDS #12:
bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16
offset=0
bfp=103370608 bln=16 avl=16 flg=05
value=00002606.0077.0001
EXEC #12:c=0,e=368,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5188376806511
FETCH #12:c=10000,e=138,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=5188376806727
STAT #12 id=1 cnt=1 pid=0 pos=1 obj=28 op='TABLE ACCESS BY USER ROWID CDEF$
(cr=1 r=0 w=0 time=78 us)'
=====================
PARSING IN CURSOR #11 len=117 dep=0 uid=19 oct=2 lid=19 tim=5188376807531
hv=157606933 ad='ea888d70'
INSERT INTO "PWRLINE"."LSCHANNELCUTDATA" ("UIDCHANNELCUT","VALUECODES") VALUES
(:1,:2) RETURNING "VALUECODES" INTO :3
END OF STMT
PARSE #11:c=10000,e=2818,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=0,tim=5188376807523
BINDS #11:
bind 0: dty=2 mxl=22(21) mal=00 scl=00 pre=00 oacflg=07 oacfl2=0 size=24
offset=0
bfp=1033b9438 bln=22 avl=06 flg=05
value=151091971
bind 1: dty=113 mxl=3876(3876) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0
size=3880 offset=0
bfp=1033b84f8 bln=3876 avl=86 flg=05
value=
Dump of memory from 0x00000001033B84F8 to 0x00000001033B854E
1033B84F0 00540000 00180000 [.T......]
1033B8500 00000000 00000000 00000000 00000000 [................]
Repeat 3 times
1033B8540 00000000 00000000 00000000 00008558 [...............X]
bind 2: dty=113 mxl=3876(3876) mal=00 scl=00 pre=00 oacflg=05 oacfl2=0
size=3880 offset=0
bfp=1033d25e0 bln=3876 avl=00 flg=05
WAIT #11: nam='db file sequential read' ela= 6853 p1=231 p2=107273 p3=1
WAIT #11: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
EXEC #11:c=0,e=10076,p=1,cr=1,cu=7,mis=0,r=1,dep=0,og=4,tim=5188376817822
WAIT #11: nam='SQL*Net message from client' ela= 7376 p1=1413697536 p2=1 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 56 p1=1413697536 p2=118 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=13 p3=0
*** 2008-08-06 15:38:28.867
WAIT #12: nam='db file sequential read' ela= 1745 p1=232 p2=113030 p3=1
*** 2008-08-06 15:38:45.859
WAIT #12: nam='direct path write (lob)' ela= 605 p1=63 p2=48670 p3=1
WAIT #12: nam='SQL*Net more data from client' ela= 109 p1=1413697536 p2=140 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 24 p1=1413697536 p2=151 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 23 p1=1413697536 p2=162 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 20 p1=1413697536 p2=173 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=184 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 19 p1=1413697536 p2=195 p3=0
WAIT #12: nam='direct path read (lob) ' ela= 7952 p1=63 p2=48670 p3=1
WAIT #12: nam='SQL*Net more data from client' ela= 38 p1=1413697536 p2=206 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=217 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 22 p1=1413697536 p2=228 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 18 p1=1413697536 p2=239 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=250 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 18 p1=1413697536 p2=5 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 20 p1=1413697536 p2=16 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 17 p1=1413697536 p2=27 p3=0
*** 2008-08-06 15:40:04.003
WAIT #12: nam='db file sequential read' ela= 9247 p1=232 p2=113031 p3=1
*** 2008-08-06 15:40:21.566
WAIT #12: nam='SQL*Net more data from client' ela= 148 p1=1413697536 p2=38 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=49 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 29 p1=1413697536 p2=60 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 23 p1=1413697536 p2=71 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 26 p1=1413697536 p2=82 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 22 p1=1413697536 p2=93 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 27 p1=1413697536 p2=104 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 21 p1=1413697536 p2=115 p3=0
*** 2008-08-06 15:41:33.474
WAIT #12: nam='db file sequential read' ela= 9106 p1=232 p2=113032 p3=1
*** 2008-08-06 15:42:00.517
WAIT #12: nam='SQL*Net more data from client' ela= 78 p1=1413697536 p2=126 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 25 p1=1413697536 p2=137 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 46 p1=1413697536 p2=148 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 783 p1=1413697536 p2=159 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 74 p1=1413697536 p2=170 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 38 p1=1413697536 p2=181 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 31 p1=1413697536 p2=192 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 24 p1=1413697536 p2=203 p3=0
*** 2008-08-06 15:43:04.069
WAIT #12: nam='latch free' ela= 6 p1=16749741904 p2=98 p3=0
WAIT #12: nam='db file sequential read' ela= 1385 p1=232 p2=113033 p3=1
*** 2008-08-06 15:43:40.956
WAIT #12: nam='SQL*Net more data from client' ela= 129 p1=1413697536 p2=214 p3=0
WAIT #12: nam='SQL*Net more data from client' ela= 27 p1=1413697536 p2=225 p3=0
> Sorry, my mistake.
>
> I checked the trace file and Cursor #10 is not in there. In fact I checked
> several traces and there are many SQL statements but never the one for the
> unaccounted for time.
>
> I am not the one who setup the traces but I've been told that the trace is
> started at the beginning of the process. I need to research that further.
>
> I'll let you know if I find anything.
>
> Keith
>
>> What is the text for CURSOR #10?
>>
>> --
>> Daniel Fink
>>
>> Help me support The Children's Hospital of Denver!
>> I'm riding in the 2008 Courage Classic - 157 miles in 3 days
>> Help me reach my goal of $2,500.00 in donations.
>> Visit my Personal Rider Page http://www.couragetours.com/2008/danielwfink to
>> donate
>>
>> OptimalDBA.com - Oracle Performance, Diagnosis, Data Recovery and Training
>>
>> OptimalDBA http://www.optimaldba.com
>> Oracle Blog http://optimaldba.blogspot.com
>>
>> Lost Data? http://www.ora600.be/
>
>
> --
> //www.freelists.org/webpage/oracle-l
>
>
>
--
//www.freelists.org/webpage/oracle-l
Other related posts:
