RE: TKPROF output

From: D'Hooge Freek <Freek.DHooge_at_uptime.be>
Date: Thu, 31 Mar 2011 08:01:42 +0200
Message-ID: <4814386347E41145AAE79139EAA398981500A12D3E_at_ws03-exch07.iconos.be>



Hi,

The main wait time is "sql*net message from client", meaning that you are waiting on response from the aplication server. Can you check in the raw trace file if these waits are happening between the fetches or not?

If they are happening between the fetches, it means that the application server is slow to request more rows from the query result. Reason for this could be some processing that happens on the application server or maybe a network problem (like a wrong dns server on the application server).

If the waits are happening after all the fetches are completed, then these waits are probably not relevant (unless you are sure that the trace was stopped at the moment the application showed the result of the query). How did you trace this session?

regards,

Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
---

From: oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] On Behalf Of lyallbarbour_at_sanfranmail.com [lyallbarbour_at_sanfranmail.com] Sent: 30 March 2011 20:55
To: oracle-l_at_freelists.org
Subject: TKPROF output

Trying to understand Fetch in a TKPROF output. We have an application on Oracle Apps Server 10.1 Database 10.2.0.4 On production, a specific query runs in about 3 seconds. On this new database server we created, it runs about 30 secs. Looks like the query does the same thing in the database, but we have a ton of SQL*Net message waits on the query below. What are Fetches? What are reasons why waits for SQL*Net messaging happens that relate to Fetches? See below...

Here it is:
SELECT ROWID,SCRAP_ID,TX_ID,SHIFT_ID,ON_TX_ID,SCRAP_COMP_CODE,WEIGHT_UOM,   DEPT_CODE,INV_COMP_CODE,INV_ITEM_CODE,SCRAP_CODE,TYPE,CUST_NUM,PART,   QUANTITY,LENGTH,SCRAP_WEIGHT,TX_START_DT,RESPONSIBILITY_CODE,DEFECT_CODE,   NOTES
FROM
 ST_PRODTX_SCRAP WHERE (WEIGHT_UOM=:1) call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch    27457      0.91       0.90          0      29757          0      164741

------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 27459 0.91 0.90 0 29757 0 164741

Misses in library cache during parse: 1
Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS
Parsing user id: 677 (LBARBOUR)

Rows Row Source Operation
------- ---------------------------------------------------
 164741 TABLE ACCESS FULL ST_PRODTX_SCRAP (cr=29757 pr=0 pw=0 time=165118 us)

Rows Execution Plan
------- ---------------------------------------------------

      0 SELECT STATEMENT MODE: ALL_ROWS  164741 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ST_PRODTX_SCRAP' (TABLE) Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   27457        0.00          0.01
  SQL*Net message from client                 27457        1.07        100.33--
http://www.freelists.org/webpage/oracle-l Received on Thu Mar 31 2011 - 01:01:42 CDT

Original text of this message