Re: long running select min(timestamp) query
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 read944.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