Re: TKPROF output

From: Ron Crisco <ron.crisco_at_method-r.com>
Date: Wed, 30 Mar 2011 14:19:14 -0500
Message-ID: <AANLkTi=qgEvjcpQLGvgWYHMPKL2cbwSt29a=xxKC3SfO_at_mail.gmail.com>

Keep in mind that Fetch implies moving data from the server (the database instance) to the client (whatever client issued the SQL statement). So the Fetch includes the time elapsed while actually getting the data ready to send, which you'll see in events like db file sequential read, and the time elapsed while sending the data to the client (SQL*Net message to client), and the time waiting for the client to say it's ready to receive the next bit of data (SQL*Net message from client). Your example shows that 29757 rows were sent to the client, but not all at once in one network roundtrip. Instead, there were 27457 roundtrips. That's a good indication that array processing is not being used effectively, and is a possible optimization you should investigate.

Note: The SQL*Net message to client is not very well instrumented in the kernel, so that the elapsed time that should rightly be attributed to it is instead folded into the subsequent SQL*Net message from client. This topic is thoroughly covered in the book Optimizing Oracle Performance and in papers on our website at method-r.com.

Ron Crisco

On Wed, Mar 30, 2011 at 1:55 PM, <lyallbarbour_at_sanfranmail.com> wrote:

> 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 Wed Mar 30 2011 - 14:19:14 CDT