Oracle-L: RE: Help Interpreting TKProf

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Wed, 12 Nov 2003 11:09:28 -0800
Message-ID: <F001.005D671C.20031112110928@fatcity.com>

Barb,

I think tkprof prints output in seconds, so I think you're looking at 10.73 seconds of response time here.

First, some definitions:

The "SQL*Net message from client" event maps to an OS read() call to the file descriptor to which SQL*Net is connected.
The "SQL*Net message to client" event maps to an OS write() call to the file descriptor to which SQL*Net is connected.

The Oracle kernel uses a "to" event just to write a short message (often 1 byte) to a pipe. It takes practically no time to do that--usually on the order of 3 microseconds (0.000003 seconds).

However, as soon as a given "to" event completes, the kernel often next executes a read() from the same file descriptor. The duration of this read() is what ultimately shows up as the "from" event's duration.

What this means is that all the time spent in the following "tiers" gets logged as "SQL*Net message from client" (see p13 of my book for a picture):

comm from db server to apps server
apps server computation time
comm from apps server to browser
browser computation time
user think time
comm from browser to apps server
apps server computation time
comm from apps server to db server

Thus you'll almost always (maybe even "always always") see "from" events lasting longer than "to" events.

Getting good information out of "SQL*Net message from client" is possible only if you are careful in how you collect your trace data. If, for example, you allow 10 seconds of user think time into your trace data, then it forces you to do a lot more analytical work on your trace data to properly "ignore" the right data--unless, of course, the thing you need to find out is that the user is wasting your business's time by consuming 10 seconds instead of 2.

"Optimizing Oracle Performance" covers all this in great detail.

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

Upcoming events:
- Performance Diagnosis 101: 11/19 Sydney, 12/16 Detroit

SQL Optimization 101: 12/8 Dallas, 2/16 Dallas
Hotsos Symposium 2004: March 7-10 Dallas
Visit www.hotsos.com for schedule details...

-----Original Message-----
Barbara Baker
Sent: Wednesday, November 12, 2003 12:09 PM To: Multiple recipients of list ORACLE-L

Hi.
I'm running tkprof on my PC with a version 9i client. The trace file was generated on a Solars version 8.1.7.4 database. (I'm using tkprof on 9i to get wait statistics.) The trace is 10046 level 12

I assume the time waited is in addition to the elapsed time for the call -- correct?

Since the database itself is 8i, does that mean that the wait stats are in centiseconds? I want to know what the sql*net message from client wait time of 10.73 represents:

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

Waited ---------- --------- SQL*Net message to client 8 0.00 0.00 SQL*Net message from client 8 10.71 10.73

Here's all the code:

select /*ClassSQL*/ distinct co.class,cl.claname from
classorder co,class cl where co.paper='DNA' and co.page='EM' and co.class=
cl.class and co.paper=cl.paper and cl.clatype='0' order by 1

call     count       cpu    elapsed       disk     
query    current        rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse        1      0.01       0.01          0        
 0          0           0
Execute      1      0.00       0.00          0        
 0          0           0
Fetch        8      0.01       0.01          0       
169          0          82

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total       10      0.02       0.02          0       
169          0          82

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 586 (SYSADMIN)

Rows Row Source Operation

     82  SORT UNIQUE 
     82   NESTED LOOPS 
     83    INDEX RANGE SCAN (object id 395118)
     82    TABLE ACCESS BY INDEX ROWID CLASS 
    164     INDEX UNIQUE SCAN (object id 395113)


Rows     Execution Plan

      0  SELECT STATEMENT   GOAL: CHOOSE
     82   SORT (UNIQUE)
     82    NESTED LOOPS
     83     INDEX   GOAL: ANALYZED (RANGE SCAN) OF

'I_CLO1' (NON-UNIQUE) 82 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'CLASS'
164 INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'I_CLA1' (UNIQUE) Thanks for any help.

Barb

Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard http://antispam.yahoo.com/whatsnewfree

-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.net
-- 
Author: Barbara Baker
  INET: barbarabbaker_at_yahoo.com

Fat City Network Services    -- 858-538-5051 http://www.fatcity.com
San Diego, California        -- Mailing list and web hosting services
---------------------------------------------------------------------
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.net
-- 
Author: Cary Millsap
  INET: cary.millsap_at_hotsos.com

Fat City Network Services    -- 858-538-5051 http://www.fatcity.com
San Diego, California        -- Mailing list and web hosting services
---------------------------------------------------------------------
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).

Received on Wed Nov 12 2003 - 13:09:28 CST