RE: Basic level 8 trace question

  • From: Smiley John - IL <SMILEYJ@xxxxxxxx>
  • To: "'JayMiller@xxxxxxxxxxxxxxxx'" <JayMiller@xxxxxxxxxxxxxxxx>, oracle-l@xxxxxxxxxxxxx
  • Date: Wed, 13 Oct 2004 14:56:48 -0500

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@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of JayMiller@xxxxxxxxxxxxxxxx
Sent: Wednesday, October 13, 2004 2:41 PM
To: oracle-l@xxxxxxxxxxxxx
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
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l

Other related posts: