Re: long running select min(timestamp) query

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Tue, 29 Jan 2008 07:48:15 -0800 (PST)
Message-ID: <97f99f21-33e2-4235-8daa-ceab413ecd0e@s12g2000prg.googlegroups.com>

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. Received on Tue Jan 29 2008 - 09:48:15 CST