RE: mostly latch-free SCN?

Thanks for the description of the *** lines.  I should have done more
research before asking this.

Here's why I originally posted the question, just so you know my frame of
mind.  I run a problematic session that had been hurting this client's
nightly batch load for months.  I knew we had some SQL optimization issues
and was going to go through the exercise of training their DBAs how to
trace, analyze, etc.  While running this thing I was showing them what's in
V$SESSION_WAIT and noticed the session waiting on latch free waits, p2=88
(which on 9.2.0.4 is the mostly latch-free SCN latch, as I learned).  I then
started examining the trace file and while tailing it, saw it "stuck" on
this latch free wait.  I expected the next line in the trace file to have
either a large ela value on a named wait event or a high CPU/elapsed value
for an LIO.

After waiting about 10 minutes, the trace file started dumping more data and
the next 100 or so lines were mbr waits, all with relatively small elapsed
times.  I guess I expected a "big value" following this latch 88 wait.  I
suppose the sum of the consecutive db file scattered read waits that
followed this latch wait will have a long elapsed time, but typically don't
you see these waits "stream" to the trace file while the session is waiting
on them?  And if they're not streaming w/ explainable wait times, what then?

I admit I didn't check the next fetch/exec/parse line for this - I just
expected the next posted line to the trace file would have high values.  If
this next "cpu" line does have high elapsed/cpu times, as we would expect,
what does that mean about all the db file scattered read waits between the
time the trace file was not being written to (10 minutes) before the next db
call?  I think you've got something about this in your book but don't recall
(and don't have it with me).

When I get back online at the office I'll double-check and hopefully things
will become more clear.

Thanks

-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Cary Millsap
Sent: Thursday, December 09, 2004 10:26 PM
To: Oracle-L@xxxxxxxxxxxxx
Subject: RE: mostly latch-free SCN?

John,

Your 'latch free' excerpt is microscopic and definitely not a concern in =
the
excerpt. That particular type of 'latch free' event has contributed only
0.000049 seconds to the approximately 6.5 MINUTES represented by your =
trace
data. Pursuing a fix to your latch "problem" will improve your response =
time
by--at most!--about 0.000013%. So, you're asking the wrong question. :)

The *** lines you're seeing are emitted by Oracle kernel calls to
dbms_system.ksdddt(). The Oracle kernel behaves as if there's a function
called "write_to_trace()" in the kernel code that handles Oracle =
extended
SQL trace file writing in the following manner:

{
        static int time_of_prior_write =3D 0;
        subroutine write_to_trace(TRACE, text) {
                if now() - time_of_prior_write > 10 seconds {
                        ksdddt;
                }
                time_of_prior_write =3D now();
                write(TRACE, text);
        }
}

The *** line doesn't mean that your 'latch free' consumed a bunch of =
time.
The ela value for each timed event shows you how much time that event =
has
consumed. The *** line is telling you that it's a long time between =
calls to
Oracle timed events. This almost always indicates that the process being
traced is accessing the database buffer cache way too many times. This =
is
common because so many books, courses, etc. teach you that making sure
everything is in the buffer cache is golden goodness.

The dbcall (PARSE, EXEC, FETCH, ...) that immediately /follows/ this =
excerpt
will have a huge c value (lots of CPU service consumption for the call), =
and
a huge e value (lots of elapsed time for the call). It will almost
undoubtedly also have a huge cr+cu value as well, which will confirm =
that
you're suffering from, I would estimate, on the order of tens of =
millions of
unnecessary "consistent gets" and "db block gets."

Bottom line: You have some very inefficient SQL here that you need to =
fix.

The book "Optimizing Oracle Performance" explains further.


Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *

Upcoming events:
- Performance Diagnosis 101: 1/4 Calgary
- SQL Optimization 101: 12/13 Atlanta
- Hotsos Symposium 2005: March 6-10 Dallas
- Visit www.hotsos.com for schedule details...


-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx =
[mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of John Clarke
Sent: Thursday, December 09, 2004 4:51 PM
To: oracle-l@xxxxxxxxxxxxx
Subject: mostly latch-free SCN?

Anyone have any idea what this is=3D3F

I was 10046 tracing a process and found it post a wait on mostly =
latch-f=3D
ree SCN latch.  Excerpt from trace file below.

WAIT #2: nam=3D3D'db file scattered read' ela=3D3D 1054 p1=3D3D17 =
p2=3D3D30500 p=3D
3=3D3D3
WAIT #2: nam=3D3D'db file sequential read' ela=3D3D 1377 p1=3D3D17 =
p2=3D3D30504 =3D
p3=3D3D1
*** 2004-12-09 17:27:55.695
WAIT #2: nam=3D3D'latch free' ela=3D3D 49 p1=3D3D-4611686009467115424 =
p2=3D3D88 =3D
p3=3D3D0
*** 2004-12-09 17:34:20.573
WAIT #2: nam=3D3D'db file sequential read' ela=3D3D 4850 p1=3D3D50 =
p2=3D3D119591=3D
 p3=3D3D1
WAIT #2: nam=3D3D'db file sequential read' ela=3D3D 6175 p1=3D3D50 =
p2=3D3D119590=3D
 p3=3D3D1


I'm not positive what the "^***" lines mean, but what I can tell is =
that=3D
 when hit the latch wait and displayed a wall time of 17:27, it didn't =
d=3D
o anything until the next "^***" line.  Shouldn't the ela in either the =
=3D
current or next wait match the elasped time=3D3F

Thanks in advance.

--
http://www.freelists.org/webpage/oracle-l

--
http://www.freelists.org/webpage/oracle-l

--
http://www.freelists.org/webpage/oracle-l

Other related posts: