Re: long running select min(timestamp) query

On Jan 29, 10:48 am, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
> On Jan 29, 9:55 am, "bobdu..._at_gmail.com" <bobdu..._at_gmail.com> wrote:
>
>
>
> > 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)'
>
> > 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
>
> It is hard to tell from the small snippet that you posted. My guess
> is that Oracle is attempting to apply undo to build a consistent image
> of the index blocks based on the last commit. It appears that the
> server has a slow single block read time, which could mean that you
> need to spread out the I/O over a greater number of spindles (but that
> might not be the case).
> Wait events:
> Trace Time Wait Time Wait Event
> 0.000206 0.000s SQL*Net message to client
> 0.012654 0.012s db file sequential read
> 0.024509 0.012s db file sequential read
> 0.026754 0.002s db file sequential read
> 0.033117 0.006s db file sequential read
> 0.042893 0.010s db file sequential read
> ...
> 944.90019 0.009s db file sequential read
> 944.900376 0.000s db file sequential read
> 944.910382 0.010s db file sequential read
>
> Execution statistics - seems like a lot of time required for a parse,
> CPU was involved in the fetch for 7.9 of the 944.9 seconds - the rest
> of the time is likely from the file system performing single block
> reads:
> |PARSEs 1|CPU S 0.031250|CLOCK S 0.068246|ROWs 0|PHY RD BLKs 2|
> CON RD BLKs (Mem) 199|CUR RD BLKs (Mem) 0|
> |EXECs 1|CPU S 0.000000|CLOCK S 0.000050|ROWs 0|PHY RD BLKs 0|
> CON RD BLKs (Mem) 0|CUR RD BLKs (Mem) 0|
> |FETCHs 2|CPU S 7.906250|CLOCK S 944.910346|ROWs 1|PHY RD BLKs 118910|
> CON RD BLKs (Mem) 118953|CUR RD BLKs (Mem) 0|
>
> Actual execution plan: 118,953 consistent reads (in memory), 118910
> physical reads (from disk):
> SORT AGGREGATE (cr=118953 pr=118910 pw=0 time=305509471 us
> INDEX FULL SCAN (MIN/ MAX) EVENTS_EVENTDATE (cr=118953 pr=118910
> pw=0 time=305509450 us)
>
> Do you have a session that has made a lot of changes to the table, but
> not committed?
>
> Charles Hooper
> IT Manager/Oracle DBA
> K&M Machine-Fabricating, Inc.

There is certainly no CURRENT session in the database that has a large number of uncommitted operations, but it is certainly possible there was one in the past, and perhaps it never finished properly. A typical operation on the database involves doing a "DELETE FROM EVENTS WHERE EVENTDATE < ?" - its possible one of these happenned in the past and didn't finish properly.

Is there some way i can get evidence of something like this? I'm searching the sessions as we speak and see none of my application sessions lingering. When i look at top activity when the query is not running, it doesn't look like anything else is happenning - how can i tell if oracle IS busy with a crapped out session, or maintenance (no other jobs running either).

Thanks AGAIN!!!
Bob Received on Tue Jan 29 2008 - 11:25:17 CST