Oracle-L: RE: More help with TKPROF

From: Cary Millsap <cary.millsap_at_hotsos.com>
Date: Thu, 13 Nov 2003 09:09:26 -0800
Message-ID: <F001.005D691B.20031113090926@fatcity.com>

Not a coincidence. See Optimizing Oracle Performance, Chapter 12, "Case 3: Large SQL*Net Event Duration" on pages 337-344. See also the SQL*Net material on pp311-315.

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: Thursday, November 13, 2003 9:09 AM To: Multiple recipients of list ORACLE-L

List:
My apologies. Seems like I'm taking up more than my share of bandwith. I'm doing major battle with a vendor. Their app runs this "thing" that takes 10 seconds. Unfortunately it runs this thing several thousand times a day. This is a critical issue for us.

I trapped what's running in that 10 seconds. The code looks just swell. Seems pretty obvious to me that the problem is with the large number of parses occurring. I see 1 spot where they parse 5 times and return 0 rows; another where they parse, execute, and fetch 5 times for no obvious reason.

We do not have access to the vendor code. The vendor says set cursor_sharing to "force". I say that's solving the wrong problem.

First naive question: Without their code, is there any way for me to know what could cause this large number of parses?

2nd question: I see an exact match between the number of parses and the times waited on "sql*net message to client". Is this coincidence, or can I make some correlation here?

Thanks so much for your patience and your help. Database is 8.1.7.4 on Solaris 8.

Barb

SELECT PAPER, PAGE, PAGENAME, PAGENO, COLUMNS, COLWIDTH, COLSPACE, HEIGHT
FROM PAGE

call     count       cpu    elapsed       disk     
query    current        rows

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

---------- ---------- Parse 2 0.02 0.02 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.01 0.01 0 13 12 72
------- ------ -------- ---------- ----------
---------- ---------- total 4 0.03 0.03 0 13 12 72

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

Rows Execution Plan

      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS   GOAL: ANALYZED (FULL) OF

'PAGE' Elapsed times include waiting on following events:

  Event waited on                             Times

Max. Wait Total Waited

Waited
---------- ------------
SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.00 0.00 SQL*Net more data to client 1 0.00 0.00

SELECT PAPER, PAGE, PAGENAME, PAGENO, COLUMNS, COLWIDTH, COLSPACE, HEIGHT
FROM
PAGE WHERE PAPER = :1 AND PAGE = :2

call     count       cpu    elapsed       disk     
query    current        rows

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

---------- ---------- Parse 2 0.00 0.01 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ----------
---------- ---------- total 4 0.00 0.01 0 2 0 1

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

Rows Execution Plan

      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS   GOAL: ANALYZED (BY INDEX
ROWID) OF 'PAGE'
      0    INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF

'I_PAG1' (UNIQUE) Elapsed times include waiting on following events:

  Event waited on                             Times

Max. Wait Total Waited

Waited
---------- ------------
SQL*Net message to client 2 0.00 0.00 SQL*Net message from client 2 0.09 0.09

SELECT HID, PARENT, CHILD, NODE_TYPE, NODE_ITEM, TAG, ATTRIBUTE_ITEM
FROM
XMLS_HIERARCHY WHERE HID = :1

call     count       cpu    elapsed       disk     
query    current        rows

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

---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 0 0.00 0.00 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ----------
---------- ---------- total 5 0.00 0.00 0 0 0 0

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

Rows Execution Plan

      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS   GOAL: ANALYZED (BY INDEX
ROWID) OF 
              'XMLS_HIERARCHY'
      0    INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF
'PK_XMLS_HIERARCHY' 
               (UNIQUE)


Elapsed times include waiting on following events:
  Event waited on                             Times

Max. Wait Total Waited

Waited
---------- ------------
SQL*Net message to client 5 0.00 0.00 SQL*Net message from client 5 0.01 0.01

SELECT HID , PARENT , CHILD , NODE_TYPE , NODE_ITEM , TAG , ATTRIBUTE_ITEM ,
XMLS_HIERARCHY."ROWID"
FROM
XMLS_HIERARCHY WHERE HID = :1

call     count       cpu    elapsed       disk     
query    current        rows

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

---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 5 0.01 0.00 0 0 0 0 Fetch 5 0.00 0.00 0 10 0 5
------- ------ -------- ---------- ----------
---------- ---------- total 15 0.01 0.00 0 10 0 5

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

Rows Row Source Operation

      1  TABLE ACCESS BY INDEX ROWID XMLS_HIERARCHY 
      2   INDEX UNIQUE SCAN (object id 394972)


Rows     Execution Plan

      0  SELECT STATEMENT   GOAL: CHOOSE
      1   TABLE ACCESS   GOAL: ANALYZED (BY INDEX
ROWID) OF 
              'XMLS_HIERARCHY'
      2    INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF
'PK_XMLS_HIERARCHY' 
               (UNIQUE)


Elapsed times include waiting on following events:
  Event waited on                             Times

Max. Wait Total Waited

Waited
---------- ------------
SQL*Net message to client 5 0.00 0.00 SQL*Net message from client 4 1.39 4.63

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk     
query    current        rows

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

---------- ---------- Parse 14 0.02 0.03 0 0 0 0 Execute 7 0.01 0.00 0 0 0 0 Fetch 7 0.01 0.01 0 25 12 78
------- ------ -------- ---------- ----------
---------- ---------- total 28 0.04 0.04 0 25 12 78

Misses in library cache during parse: 4

Elapsed times include waiting on following events:

  Event waited on                             Times

Max. Wait Total Waited

Waited
---------- ------------
SQL*Net message to client 14 0.00 0.00 SQL*Net message from client 13 1.39 4.73 SQL*Net more data to client 1 0.00 0.00

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 Thu Nov 13 2003 - 11:09:26 CST