Re: Very slow fetches with high cputime
Date: Mon, 16 Feb 2009 10:05:43 -0700
Message-ID: <49999CE7.1050107_at_optimaldba.com>
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_at_zonnet.nl wrote:Received on Mon Feb 16 2009 - 11:05:43 CST
> 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
>
-- http://www.freelists.org/webpage/oracle-l