Re: long running select min(timestamp) query
Date: Tue, 29 Jan 2008 06:55:33 -0800 (PST)
Message-ID: <36c4c637-c3a0-4a2e-92cf-33fef461273a@t1g2000pra.googlegroups.com>
Thanks again for all your help!
I enabled the trace as described, but think perhaps i had it enabled globally already :) Anyways, i found the statement in the 12mb trace file, it starts out like this:
PARSING IN CURSOR #14 len=45 dep=0 uid=5 oct=3 lid=5 tim=3655566168 hv=2521884448 ad='1cdca248'
select min(eventdate) from myschema.events END OF STMT
PARSE
#14:c=31250,e=68246,p=2,cr=199,cu=0,mis=1,r=0,dep=0,og=1,tim=3655566161
EXEC #14:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3655566330 WAIT #14: nam='SQL*Net message to client' ela= 4 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=3655566374
WAIT #14: nam='db file sequential read' ela= 12382 file#=4 block#=1918069 blocks=1 obj#=92627 tim=3655578822 WAIT #14: nam='db file sequential read' ela= 11811 file#=4 block#=1596398 blocks=1 obj#=92627 tim=3655590677 WAIT #14: nam='db file sequential read' ela= 2206 file#=4 block#=1596792 blocks=1 obj#=92627 tim=3655592922 WAIT #14: nam='db file sequential read' ela= 6319 file#=4 block#=1596715 blocks=1 obj#=92627 tim=3655599285 WAIT #14: nam='db file sequential read' ela= 9718 file#=4 block#=1596788 blocks=1 obj#=92627 tim=3655609061....
.... (snipsnip - vast majority of file looks like this, roughly 10mb worth)
....
WAIT #14: nam='db file sequential read' ela= 9378 file#=4 block#=31781 blocks=1 obj#=92627 tim=4600466358 WAIT #14: nam='db file sequential read' ela= 149 file#=4 block#=20220 blocks=1 obj#=92627 tim=4600466544 WAIT #14: nam='db file sequential read' ela= 9970 file#=4 block#=31820 blocks=1 obj#=92627 tim=4600476550
FETCH
#14:c=7906250,e=944910345,p=118910,cr=118953,cu=0,mis=0,r=1,dep=0,og=1,tim=4600476756
WAIT #14: nam='SQL*Net message from client' ela= 191 driver id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477050 FETCH #14:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=4600477098 WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=92627 tim=4600477129
WAIT #14: nam='SQL*Net message from client' ela= 625 driver id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477781 *** SESSION ID:(106.29859) 2008-01-29 09:32:42.976 STAT #14 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=118953 pr=118910 pw=0 time=305509471 us)'
STAT #14 id=2 cnt=1 pid=1 pos=1 obj=92627 op='INDEX FULL SCAN (MIN/ MAX) EVENTS_EVENTDATE (cr=118953 pr=118910 pw=0 time=305509450 us)' WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=92627 tim=4600526669
WAIT #0: nam='SQL*Net message from client' ela= 95 driver id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600526796
PARSING IN CURSOR #7 len=789 dep=1 uid=0 oct=3 lid=0 tim=4600527186 hv=3159716790 ad='20ae3d74'
select
i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree $,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree, 1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$, 256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable# +c.valid#,
0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres $,null,null,mod(trunc(i.pctthres$/256),
256)),ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats $ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer, 1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
END OF STMT
PARSE #7:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4600527182 EXEC #7:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4600527482 FETCH #7:c=0,e=403,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=4600527920
(snipsnip - a whole bunch more, 1.5mb worth or so, exceeded googles 190000 char limit so i clipped it)
FETCH
#8:c=78125,e=262061,p=38,cr=1566,cu=14,mis=0,r=9,dep=1,og=1,tim=4601143193
FETCH
#7:c=203125,e=487298,p=85,cr=2335,cu=46,mis=0,r=1,dep=0,og=1,tim=4601143310
WAIT #7: nam='SQL*Net message from client' ela= 210 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601143694
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601143770
STAT #14 id=1 cnt=3 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=6 pr=3
pw=0 time=9196 us)'
STAT #14 id=2 cnt=3 pid=1 pos=1 obj=95137 op='TABLE ACCESS FULL
PLAN_TABLE (cr=6 pr=0 pw=0 time=107 us)'
STAT #14 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0
pw=0 time=42 us)'
STAT #14 id=4 cnt=1 pid=3 pos=1 obj=95137 op='TABLE ACCESS FULL
PLAN_TABLE (cr=3 pr=0 pw=0 time=27 us)'
FETCH #7:c=0,e=283,p=0,cr=0,cu=0,mis=0,r=8,dep=0,og=1,tim=4601144021
WAIT #7: nam='SQL*Net message from client' ela= 2162 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601146239
STAT #7 id=1 cnt=9 pid=0 pos=1 obj=0 op='COLLECTION ITERATOR PICKLER
FETCH DISPLAY (cr=2335 pr=85 pw=0 time=487284 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601146360
WAIT #0: nam='SQL*Net message from client' ela= 131 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601146517
PARSING IN CURSOR #13 len=45 dep=0 uid=5 oct=7 lid=5 tim=4601146608 hv=349105966 ad='1ce642a4'
DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1 END OF STMT
PARSE #13:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4601146604 EXEC #13:c=0,e=203,p=0,cr=3,cu=3,mis=0,r=3,dep=0,og=1,tim=4601146912 WAIT #13: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601146969
WAIT #13: nam='SQL*Net message from client' ela= 65 driver id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601147066 STAT #13 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE PLAN_TABLE (cr=3 pr=0 pw=0 time=167 us)'
STAT #13 id=2 cnt=3 pid=1 pos=1 obj=95137 op='TABLE ACCESS FULL PLAN_TABLE (cr=3 pr=0 pw=0 time=45 us)'
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601147205
*** 2008-01-29 09:39:33.937
WAIT #0: nam='SQL*Net message from client' ela= 410325557 driver id=1111838976 #bytes=1 p3=0 obj#=355 tim=5011472799 *** SESSION ID:(106.29859) 2008-01-29 09:39:33.953 XCTEND rlbk=0, rd_only=0
Sorry about the clipping - let me know if i can send the 13mb file directly.
Why is it stuck waiting? Normally there are a bunch of sessions accessing this table, but to run these tests i shut down the application and am ONLY touching oracle with sqlplus. What could it be waiting on? Is it doing maintenance perhaps?
Thanks again for any help you can provide, Bob Received on Tue Jan 29 2008 - 08:55:33 CST