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.

Daniel Fink

Daniel Fink - Oracle Performance, Diagnosis, Data Recovery and Training

Oracle Blog

Lost Data?

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


Other related posts: