RE: Basic level 8 trace question

From: Smiley John - IL <SMILEYJ_at_tusc.com>
Date: Wed, 13 Oct 2004 14:56:48 -0500
Message-ID: <F5E885BEF9540D47A7BDC03CF168808709924B4D@tuscil_ex1>

Whether or not the SQL*Net message from client wait time is significant is entirely dependent upon how you collected the trace. The beginning and ending of the trace need to coincide exactly with the beginning and ending of the business process you're interested in. If enabled tracing manually, it is very likely that the SQL*Net waits are picking up the time before and after the business process that are included in the trace. If you automated trace collection as part of the business process, chances are the waits are significant. Hotsos has a public domain utility called Sparky than can help eliminate false SQL*Net waits from the trace.

The wait times as summarized by tkprof are expressed in seconds. If you look in the raw trace, they are expressed in microseconds for 9i and above and in milliseconds for 8i and below.

John Smiley

-----Original Message-----
From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of JayMiller_at_TDWaterhouse.com
Sent: Wednesday, October 13, 2004 2:41 PM To: oracle-l_at_freelists.org
Subject: Basic level 8 trace question

I ran a level 8 trace and formatted the file with tkprof. For one of the entries the output was this:

***

select text
from
view$ where rowid=:1

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ----------

Parse 24 0.01 0.00 0 0 0 0
Execute 24 0.00 0.00 0 0 0 0
Fetch 24 0.00 0.00 7 48 0 24
------- ------ -------- ---------- ---------- ---------- ----------

total 72 0.01 0.01 7 48 0 24

Misses in library cache during parse: 0
Optimizer goal: CHOOSE

      3     HASH JOIN
   7219      TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                 'PS_RSF_OPPORTUNITY'
1852336       INDEX   GOAL: ANALYZED (RANGE SCAN DESCENDING) OF
                  'PSGRSF_OPPORTUNITY' (NON-UNIQUE)
    231      TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                 'PS_WSI_RSF_OPP_FLD'
    231       INDEX   GOAL: ANALYZED (RANGE SCAN) OF
                  'PSBWSI_RSF_OPP_FLD' (NON-UNIQUE)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total

Waited

Waited ----------
SQL*Net message to client 6 0.00 0.00 SQL*Net message from client 6 270.45 346.39 db file sequential read 45789 0.11 3.02

***

My question is whether the SQL*Net message from client refers only to those waits that occur from the start of the SQL to the end of its execution (in which case it might indicate a problem) or includes time before or after the SQL was executed (in which case it probably doesn't).

Also, what is the unit of time for total waited?

TIA! On the bright side I think I'll finally get the okay to go to the next Hotsos seminar in the NYC area (I'm praying it isn't in January). My management was really negative about allowing anyone to take training but I now have the okay from both the person below and above the stumbling block so he won't be able to say either that my department manager won't approve it or that the senior maangement won't approve it.

Thanks,
Jay Miller

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

Received on Wed Oct 13 2004 - 14:52:19 CDT