Oracle-L: slow SQL query, diagnosis using 10046 trace event

From: Suhen Pather <Suhen.Pather_at_strandbags.com.au>
Date: Sun, 05 May 2002 17:08:20 -0800
Message-ID: <F001.00458681.20020505170820@fatcity.com>

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: Suhen Pather
  INET: Suhen.Pather_at_strandbags.com.au

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 Sun May 05 2002 - 20:08:20 CDT