Re: TKPROF output
- From: Ron Crisco <ron.crisco@xxxxxxxxxxxx>
- To: lyallbarbour@xxxxxxxxxxxxxxx
- Date: Wed, 30 Mar 2011 14:19:14 -0500
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@xxxxxxxxxxxxxxx> 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
>
>
>
>
Other related posts:
