Re: slow SQL query, diagnosis using 10046 trace event

There is an optimization that has been put into OCI8. If you fetch 2 rows and you know that it will only one row but receive an EOF for the second row. The key thing is that after that EOF the query will be cancelled and all resources aquired will be released. So it kind of makes sense to retrieve with an array fetch always one more row than what is returned. This way you save on round trips to cancel the query (what nobody does anyway) and save on resources on the server so that you support more users on the servers.

Here is a comment about that:

              Implicit pre-fetching returns the first batch of a result set from a SELECT

             statement to the client along with the statement acknowledgment during an

             execute call. This data is transparently buffered by Oracle Call Interface so

             that when the application asks to fetch the data it is returned without

             incurring an additional client/server round-trip. Further, when a cursor is

             pre-fetched to end-of-fetch, the cursor is automatically de-allocated by the

             server releasing all in-use memory. Implicit pre-fetching significantly

             reduces client/server network traffic and reduces session memory taken up

             by queries left with pending data, which can often account for a significant

             portion of session memory.

So all tools that use the OCI8 or higher interface will benefit from that. SQL*Plus is one of those tools. Try to set arraysize to 1 and you will see that it will always fetch 2 rows. I remember the pre-fetching to be configiurable.

Anjo.

Jonathan Lewis wrote:

> Don't forget that sorts are not the only thing
> that use the temporary tablespace - hash joins
> are another possible usage.
>
> Is your db_files parameter set to 100, if so these
> are direct reads against the first file in your
> temporary tablespace.
>
> The fact that they are all single block, and that
> the cost figures are very high tends to suggest
> that Oracle is using a hash partition in a highly
> inappropriate situation, and the statistics on the
> tables are strangely incorrect leading to a very
> bad estimate of the appropriate number of
> hash buckets and partition count in the hash
> tables.
>
> The large numbers of wait for message to and
> from client is simply the effect of two rows being
> supplied to the client on each FETCH. I have an
> idea, in fact, that when you do single row fetch
> (as opposed to array fetch) in recent versions
> of Oracle, there is actually a hidden optimisation
> that attempts to fetch two rows and buffers the
> second row locally - but this is just a hypothesis
> that I have not yet examined in detail.
>
> Jonathan Lewis
> http://www.jlcomp.demon.co.uk
>
> Author of:
> Practical Oracle 8i: Building Efficient Databases
>
> Next Seminar - Australia - July/August
> http://www.jlcomp.demon.co.uk/seminar.html
>
> Host to The Co-Operative Oracle Users' FAQ
> http://www.jlcomp.demon.co.uk/faq/ind_faq.html
>
> -----Original Message-----
> To: Multiple recipients of list ORACLE-L <ORACLE-L_at_fatcity.com>
> Date: 06 May 2002 01:39
>
> |Tuning Gurus,
> |
> |I am tuning one of our dayend batch jobs using the 10046 wait event
> (level
> |8).
> |I see a whole lot of direct path read/ write events (1000's) in the
> trace
> |file.
> |Also many SQL*NET messages from/ to client waits.
> |
> |Not sure if this is the way PRO*C works, connects fetches and
> disconnects
> |multiple time.
> |Therefore there are also many FETCHES.
> |
> |Not sure what these events relate to. I am not sure if it may be
> related to
> |sorting.
> |However the session stats show only 3 sorts. (2 in memory and 1 to
> disk).
> |This is a PROC*C program.
> |
> |Snippet from trace
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=167180 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=167183 p3=1
> |WAIT #5: nam='direct path read' ela= 3 p1=101 p2=167892 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=160653 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=160295 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=165431 p3=1
> |WAIT #5: nam='direct path read' ela= 4 p1=101 p2=166769 p3=1
> |WAIT #5: nam='direct path read' ela= 2 p1=101 p2=166770 p3=2
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166772 p3=1
> |WAIT #5: nam='direct path read' ela= 3 p1=101 p2=166773 p3=2
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=165382 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=161977 p3=1
> |WAIT #5: nam='direct path read' ela= 5 p1=101 p2=162178 p3=1
> |WAIT #5: nam='direct path read' ela= 3 p1=101 p2=166148 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=165788 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166562 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166565 p3=1
> |WAIT #5: nam='direct path read' ela= 4 p1=101 p2=166566 p3=2
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166352 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166355 p3=1
> |WAIT #5: nam='direct path read' ela= 0 p1=101 p2=166201 p3=1
> |WAIT #5: nam='direct path read' ela= 8 p1=101 p2=166204 p3=1
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1111838976 p2=1
> p3=0
> |FETCH #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=2,tim=28537720
> |WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1111838976 p2=1
> p3=0
> |
> |Query Plan
> |
> |select orgplvee.org_lvl_parent ,prdplvee.prd_lvl_parent ,
> | (NVL(invbalee.on_hand_qty,0)+NVL(to_intrn_qty,0)) ,
> | (NVL(invbalee.on_hand_retl,0)+NVL(to_intrn_retl,0)) ,
> | (NVL(invbalee.on_hand_cost,0)+NVL(to_intrn_cost,0))
> |from
> | invbalee ,orgplvee ,prdplvee where (orgplvee.org_lvl_child=
> | invbalee.org_lvl_child and
> prdplvee.prd_lvl_child=invbalee.prd_lvl_child)
> | order by orgplvee.org_lvl_parent,prdplvee.prd_lvl_parent
> |
> |
> |call count cpu elapsed disk query current
> |rows
> |------- ------ -------- ---------- ---------- ---------- ----------
> |----------
> |Parse 0 0.00 0.00 0 0 0
> |0
> |Execute 0 0.00 0.00 0 0 0
> |0
> |Fetch 1073155 383.55 401.00 5501 0 0
> |2146310
> |------- ------ -------- ---------- ---------- ---------- ----------
> |----------
> |total 1073155 383.55 401.00 5501 0 0
> |2146310
> |
> |Misses in library cache during parse: 0
> |Parsing user id: 20
> |
> |Execution Plan
> |Id Par Pos Ins Plan
> |--- ---- ---- ----
> |---------------------------------------------------------------------
> -------
> |----
> | 0 #### SELECT STATEMENT (choose) Cost
> |(48836,5333714,170678848)
> | 1 0 1 SORT (order by) Cost
> (48836,5333714,170678848)
> | 2 1 1 HASH JOIN Cost (1705,5333714,170678848)
> | 3 2 1 INDEX (analyzed) UNIQUE JDAPROD ORGPLVEEP1
> (fast
> |full scan) Cost (1,1073,5365)
> | 4 2 2 HASH JOIN Cost (1690,1357040,36640080)
> | 5 4 1 INDEX (analyzed) UNIQUE JDAPROD
> PRDPLVEEP1
> |(fast full scan) Cost (16,100070,8005
> | 6 4 2 1 TABLE ACCESS (analyzed) JDAPROD
> INVBALEE
> |(full) Cost (746,1257164,23886116)
> |
> |
> |Each fetch call returned an average of 2 rows.
> |Not sure if I need to increase the arraysize in SQLPLUS to perform
> bulk
> |fetches.
> |
> |Thanks & Regards
> |Suhen
> |
>
> --
> Please see the official ORACLE-L FAQ: http://www.orafaq.com
> --
> Author: Jonathan Lewis
> INET: jonathan_at_jlcomp.demon.co.uk
>
> Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051
> San Diego, California -- Public Internet access / Mailing Lists
> --------------------------------------------------------------------
> 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.com
-- 
Author: Anjo Kolk
  INET: anjo_at_oraperf.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists
--------------------------------------------------------------------
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).