Re: Very slow fetches with high cputime
- From: Daniel Fink <daniel.fink@xxxxxxxxxxxxxx>
- To: ronpet@xxxxxxxxx
- Date: Mon, 16 Feb 2009 10:05:43 -0700
The timing mechanisms for CPU and Elapsed time is different, which can
lead to timing irregularities like you are seeing. It is usually less
dramatic, but you are dealing with a large time value, so it appears to
be very significant. I would worry less about that than the number of
current read operations...
The real issue is the number of current operations in the fetch (which
is likely related to the high cpu time). The query performed about 4200
current reads per row returned. Without seeing the execution plan and
row stats, it is hard to see which operation was performing the most
current reads. There are several things to look for...
1) Consistent reads that are applying a lot of undo. I have seen this
when a massive uncommitted update is occurring and the query is having
to rebuild a consistent view of the data as of 3 days ago (yes...3
days!). What tablespaces do the commonly accessed files belong to? If it
is the undo tablespace, you are likely rebuilding consistent views of
the data.
2) Multiple accesses of indexes can also show up as an increase in
current reads. The blocks are cached, so the number of physical reads
are low, but you are accessing index blocks over and over and over again.
It would be helpful if you could post the execution plan with row source
statistics from the tkprof output. That might help isolate the
operations performing the most logical i/o.
Regards,
Daniel Fink
--
Daniel Fink
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/
ronpet@xxxxxxxxx wrote:
Dear list,
I'm trying to fix a performance issue on a query that runs 48 hours,
where it normally runs for 5 minutes.
During last slow-run, I activated a 10046 traceevent, to find out
where time is spend on.
Query stats (tkprof) are:
call count cpu elapsed disk query
current rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 0 0.00 0.00 0 0
0 0
Execute 0 0.00 0.00 0 0
0 0
Fetch 604 170203.78 167091.28 44687 2765869668
0 661012
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 604 170203.78 167091.28 44687 2765869668
0 661012
Misses in library cache during parse: 0
Parsing user id: 71
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
SQL*Net more data to client 5448
0.00 0.51
db file sequential read 12574 0.14
36.56
db file scattered read 424
0.05 4.81
SQL*Net message from client 605
0.02 4.74
SQL*Net message to client 604
0.00 0.00
latch: cache buffers chains 992 0.45
241.80
read by other session 25
0.01 0.06
latch free 54 0.30
14.29
********************************************************************************
Since an average fetch takes about 5 minutes, I browsed through the
trace-file. I noticed that:
* a FETCH cputime (c=) itself is about 5 minutes
* a FETCH elapsetime (e=) is often smaller the FETCH cpu-time
* the total of WAIT's is only about 2 seconds
Does anyone have anyone have idea what's making the fetch so slow and
why FETCH elapsetime is smaller than FETCH cpu-time. My main concern
is to find out how I can solve this performance issue.
I included a part of the 10046 tracefile (between 2 fetches) below.
Thnx for any feedback,
Ronald Peters
--
//www.freelists.org/webpage/oracle-l
Other related posts:
