RE: Help with 10046 level 12 trace

Don't feel bad: it's HARD. It took us more than three man-years of research and software development labor to get to the point where we are comfortable exposing this software to the public. :)

Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com

Upcoming events:
- Hotsos Clinic, Oct 1-3 San Francisco, Oct 15-17 Dallas, Dec 9-11
Honolulu
- 2003 Hotsos Symposium on OracleR System Performance, Feb 9-12 Dallas

• Next event: Miracle Database Forum, Sep 20-22 Middelfart Denmark

-----Original Message-----
Douglass
Sent: Friday, August 23, 2002 10:04 AM
To: Multiple recipients of list ORACLE-L

You're right, there's more there than meets the eye and your Profiler really
highlights that. I'm really quite jealous of your Profiler -- my attempts at
distilling level 12 tracefiles into a useful report have been clumsy and inaccurate by comparison.

• Original Message ----- To: "Multiple recipients of list ORACLE-L" <ORACLE-L_at_fatcity.com> Sent: Friday, August 23, 2002 2:18 AM

> ...there isn't much point in regretting how much data tkprof ignores > in the tracefile.

I agree only partly. It's clear from the tkprof output that the code suffers from at least one type of inefficiency. But you can't tell how much that inefficiency *costs*, or whether the first inefficiency you saw is really the one that's going to make a big difference.

Mandar did upload his trace file. If you're curious, the program's response time consisted of:

SQL*Net message from client 100.18s (76.5%) = 6,921 calls x 0.014475s/call

CPU service                   15.57s  (11.6%) = 6,352 calls x
0.002451s/call
unaccounted-for               13.47s  (10.3%)
other                          1.76s   (1.3%)
---------------------------------------------
TOTAL                        130.98s (100.0%)

>From this, it looks like either a slow LAN or a really fast WAN in action (14ms is a bit large for a LAN), but the real Profiler output showed a max wait time of almost 16s, which influenced the average upward but which probably does not indicate a network inefficiency.

Exactly as Philip noted, this program makes more db calls than it should. But now we know the cost, and we know for certain that this is the problem that needs attacking first. The reason we wrote the Profiler is that often the "obvious" problem isn't the correct problem to be working on (examples of this phenomenon are at www.hotsos.com/dnloads/1/cases/2002.05.22.pdf).

Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com

Upcoming events:
- Hotsos Clinic, Oct 1-3 San Francisco, Oct 15-17 Dallas, Dec 9-11
Honolulu
- 2003 Hotsos Symposium on OracleR System Performance, Feb 9-12 Dallas

• Next event: Miracle Database Forum, Sep 20-22 Middelfart Denmark

-----Original Message-----
Douglass
Sent: Thursday, August 22, 2002 7:38 PM
To: Multiple recipients of list ORACLE-L

Yes, I noticed the noticed the extra parses too. I've noticed other Delphi
developers (including some of our own) also have a strong tendency to produce very similar inefficient code. I haven't asked, but I wonder if there is something in that development environment that encourages this kind
of coding.

It seems to me that since it is so obvious where the primary problem is, as
well as what the solution is, there isn't much point in regretting how much
data tkprof ignores in the tracefile. Whether or not the excessive parsing
is causing latch contention seems irrelevant, unless one really wants to beat the poor Delphi developer over the head with it. On second thought...

--
Philip Douglass
Internet Networking Group
Database Administrator
SIRS Mandarin, Inc.

----- Original Message -----
To: "Multiple recipients of list ORACLE-L" <ORACLE-L_at_fatcity.com>
Sent: Thursday, August 22, 2002 6:14 PM


I'll second that motion. Oddly, though, it's even worse than that: This
code is actually parsing MORE times than it's executing! ("Parse.
Thanks, but nevermind. Okay, now parse the same thing again. Okay, now
execute...")

I pulled the trigger pretty quickly a minute ago when I suggested that
Mandar should upload the file to our site. There's a lot you can learn
from tkprof output alone. However, amplifying Mladen's point a little
bit, you're losing a lot of data by viewing raw trace files with tkprof.
For example, are so many parse calls causing latch contention to be a
significant component of response time? With tkprof output, we can only
guess.

<ad>Even tkprof 9i output ignores significant amounts of useful
data.</ad>

We'll be glad to look at the raw trace file. Just let me know if you'd
like us to.


Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com

Upcoming events:


- Hotsos Clinic, Oct 1-3 San Francisco, Oct 15-17 Dallas, Dec 9-11

Honolulu


- 2003 Hotsos Symposium on OracleR System Performance, Feb 9-12 Dallas

- Next event: Miracle Database Forum, Sep 20-22 Middelfart Denmark




-----Original Message-----
Douglass
Sent: Thursday, August 22, 2002 4:20 PM
To: Multiple recipients of list ORACLE-L

Well, I'm sure a guru here will correct me if I am wrong, but at first
blush it looks like your developer is not only parsing, executing and
fetching in a loop, but is also parsing a few extra times just for fun.
I'm pretty sure you will find that the bulk of your performance problem
lies there.

== the bad way ==
loop
    parse
    execute
    fetch
    close
end loop

== the good way ==
parse
execute
loop
    fetch
end loop
close
--
Philip Douglass
Internet Networking Group
Database Administrator
SIRS Mandarin, Inc.

----- Original Message -----
To: "Multiple recipients of list ORACLE-L" <ORACLE-L_at_fatcity.com>
Sent: Thursday, August 22, 2002 4:41 PM


Hello All,

One our lead developers has just written a Delphi application to process
some printing jobs. The application would every other minute query a job
table and generate a report to be printed to specific network printers.

I ran a 10046 level 12 trace using dbms_system.set_ev.

I would be very glad if experts can help me understand how to interpret
the trace and tkprof output. Also pls let me know if ull find anything
which points to or would lead to performance problems.

I am thinking of setting session_cached_cursors to a non zero value.

thanks
Mandar

Tkprofed trace file
[...snipped by Philip Douglass...]

--
Please see the official ORACLE-L FAQ: http://www.orafaq.com
--
Author: Philip Douglass
  INET: philipd_at_sirs.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).

--
Please see the official ORACLE-L FAQ: http://www.orafaq.com
--
Author: Cary Millsap
  INET: cary.millsap_at_hotsos.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).


-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.com
-- 
Author: Philip Douglass
  INET: philipd_at_sirs.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).

-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.com
-- 
Author: Cary Millsap
  INET: cary.millsap_at_hotsos.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).