Re: slow SQL query, diagnosis using 10046 trace event

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Tue, 07 May 2002 11:03:27 -0800
Message-ID: <F001.0045A33A.20020507110327@fatcity.com>

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).

Received on Tue May 07 2002 - 14:03:27 CDT