Re: 10046 trace - unaccounted for time

From: Cary Millsap <cary.millsap_at_method-r.com>
Date: Wed, 6 Aug 2008 12:56:48 -0500
Message-ID: <3a2a84fc0808061056t7c010d5cgaedd17437612052@mail.gmail.com>


I agree with what Riyaj has said. It helps sometimes to realize that "waits" just means essentially "OS calls."

I'd expect your process is indeed doing a lot of buffer processing, using data that's already in your database buffer cache. You can confirm or refute this hypothesis quickly with a couple of snaps of v$sess_io.

Cary Millsap
http://method-r.com
http://carymillsap.blogspot.com

On Wed, Aug 6, 2008 at 12:46 PM, Riyaj Shamsudeen < riyaj.shamsudeen_at_gmail.com> wrote:

> Hi Keith
> That means that process is either running on CPU or waiting for CPU in the
> run queue, to be available. May be that all buffers it is trying to access
> is in buffer cache and process is running on the CPU without any waits.
>
> Cheers
> Riyaj
> The Pythian Group
> blog: http://orainternals.wordpress.com
>
> Keith Moore wrote:
>
>> Oracle 9.2.0.4, Solaris
>>
>> We are having a production issue where user processes are very slow. We
>> are
>> seeing 'cache buffers chains' latch events in the 10046 trace file.
>>
>> What I'm not fully understanding is the long periods of unaccounted for
>> time
>> where the process hangs. If I do a 'tail -f' on the trace file I can see
>> it
>> pause for several seconds. Here is a small sample of the output:
>>
>> *** 2008-08-05 15:22:57.748
>> WAIT #23: nam='latch free' ela= 8 p1=16764558008 p2=98 p3=0
>> WAIT #23: nam='latch free' ela= 12 p1=16764645560 p2=98 p3=0
>> *** 2008-08-05 15:23:16.414
>> WAIT #23: nam='latch free' ela= 9 p1=16796730344 p2=98 p3=0
>> WAIT #23: nam='latch free' ela= 10 p1=16764600056 p2=98 p3=0
>> WAIT #23: nam='db file sequential read' ela= 1893 p1=66 p2=52489 p3=1
>> *** 2008-08-05 15:23:33.376
>> WAIT #23: nam='latch free' ela= 8 p1=16764602936 p2=98 p3=0
>> *** 2008-08-05 15:23:47.319
>> WAIT #23: nam='latch free' ela= 7 p1=16796666408 p2=98 p3=0
>>
>> If you look at the first four lines, you see 20 seconds have elapsed but
>> the
>> only wait events are the two 'cache buffers chains' waits for a total of
>> 20
>> microseconds.
>>
>> Can someone explain what is going on here and how to troubleshoot?
>>
>> FYI, this process is deleting and the inserting a LOB and the hot blocks
>> seem
>> to be in the LOB index.
>>
>> Thanks
>> Keith
>>
>> --
>> http://www.freelists.org/webpage/oracle-l
>>
>>
>>
>>
>>
>
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Wed Aug 06 2008 - 12:56:48 CDT

Original text of this message