Return-Path: Received: from newsfeed.cts.com (newsfeed.cts.com [209.68.248.164]) by naude.co.za (8.11.2/8.11.2) with SMTP id g460O1e29810 for ; Sun, 5 May 2002 20:24:01 -0400 Received: from fatcity.UUCP (uucp@localhost) by newsfeed.cts.com (8.9.3/8.9.3) with UUCP id RAA67493; Sun, 5 May 2002 17:32:17 -0700 (PDT) Received: by fatcity.com (26-Feb-2001/v1.0g-b71/bab) via UUCP id 00458681; Sun, 05 May 2002 17:08:20 -0800 Message-ID: Date: Sun, 05 May 2002 17:08:20 -0800 To: Multiple recipients of list ORACLE-L X-Comment: Oracle RDBMS Community Forum X-Sender: Suhen Pather Sender: root@fatcity.com Reply-To: ORACLE-L@fatcity.com Errors-To: ML-ERRORS@fatcity.com From: Suhen Pather Subject: slow SQL query, diagnosis using 10046 trace event Organization: Fat City Network Services, San Diego, California X-ListServer: v1.0g, build 71; ListGuru (c) 1996-2001 Bruce A. Bergman Precedence: bulk Mime-Version: 1.0 Content-Type: multipart/alternative; boundary="----_=_NextPart_001_01C1F492.C9B6AF80" ------_=_NextPart_001_01C1F492.C9B6AF80 Content-Type: text/plain; charset="iso-8859-1" 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 ------_=_NextPart_001_01C1F492.C9B6AF80 Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable

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.=A0 I am not sure if it may be = related to sorting.

However the session stats show only 3 sorts.=A0 (2 in memory and 1 to = disk).

This is a PROC*C = program.

 

Snippet from trace

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D167180 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D167183 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 3 p1=3D101 = p2=3D167892 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D160653 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D160295 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D165431 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 4 p1=3D101 = p2=3D166769 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 2 p1=3D101 = p2=3D166770 p3=3D2

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166772 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 3 p1=3D101 = p2=3D166773 p3=3D2

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D165382 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D161977 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 5 p1=3D101 = p2=3D162178 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 3 p1=3D101 = p2=3D166148 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D165788 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166562 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166565 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 4 p1=3D101 = p2=3D166566 p3=3D2

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166352 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166355 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 0 p1=3D101 = p2=3D166201 p3=3D1

WAIT #5: nam=3D'direct path read' ela=3D 8 p1=3D101 = p2=3D166204 p3=3D1

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH = #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

WAIT #5: nam=3D'SQL*Net message to client' ela=3D 0 p1=3D1111838976 p2=3D1 p3=3D0

FETCH #5:c=3D0,e=3D0,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D2,dep=3D0,og=3D2,tim=3D28= 537720

WAIT #5: nam=3D'SQL*Net message from client' ela=3D = 0 p1=3D1111838976 p2=3D1 p3=3D0

 

Query Plan

 

select orgplvee.org_lvl_parent = ,prdplvee.prd_lvl_parent ,

=A0 (NVL(invbalee.on_hand_qty,0)+NVL(to_intrn_qty,0)) = ,

=A0 (NVL(invbalee.on_hand_retl,0)+NVL(to_intrn_retl,0)) = ,

=A0 (NVL(invbalee.on_hand_cost,0)+NVL(to_intrn_cost,0))=A0

from

=A0invbalee = ,orgplvee ,prdplvee where (orgplvee.org_lvl_child=3D

=A0 invbalee.org_lvl_child and prdplvee.prd_lvl_child=3Dinvbalee.prd_lvl_child) =

=A0 order by orgplvee.org_lvl_parent,prdplvee.prd_lvl_parent=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 =

 

 

call=A0=A0=A0=A0 = count=A0=A0=A0=A0=A0=A0 cpu=A0=A0=A0 elapsed=A0=A0=A0=A0=A0=A0 = disk=A0=A0=A0=A0=A0 query=A0=A0=A0 current=A0 =A0=A0=A0=A0=A0=A0rows

------- ------=A0 -------- ---------- ---------- ---------- ----------=A0 = ----------

Parse=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 = 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = 0

Execute=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 = 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = 0

Fetch=A0=A0 = 1073155=A0=A0=A0 383.55=A0=A0=A0=A0 401.00=A0=A0=A0=A0=A0=A0 = 5501=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0 2146310

------- ------=A0 -------- ---------- ---------- ---------- ----------=A0 = ----------

total=A0=A0 = 1073155=A0=A0=A0 383.55=A0=A0=A0=A0 401.00=A0=A0=A0=A0=A0=A0 = 5501=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0 2146310

 

Misses in library cache during parse: = 0

Parsing user id: 20=A0

 

Execution Plan

Id=A0 = Par=A0 Pos=A0 Ins Plan

--- ---- ---- ---- ------------------------------------------------------------------------= --------

=A0 0=A0=A0=A0=A0=A0 ####=A0=A0=A0=A0=A0=A0=A0 SELECT = STATEMENT (choose)=A0=A0=A0=A0 Cost = (48836,5333714,170678848)

=A0 1=A0=A0=A0 0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0=A0=A0 = SORT=A0=A0=A0 (order by)=A0 Cost (48836,5333714,170678848)

=A0 2=A0=A0=A0 1=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = HASH JOIN=A0=A0=A0=A0 Cost = (1705,5333714,170678848)

=A0 3=A0=A0=A0 2=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = INDEX (analyzed) UNIQUE JDAPROD ORGPLVEEP1 (fast full scan)=A0 Cost (1,1073,5365)

=A0 4=A0=A0=A0 2=A0=A0=A0 2=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = HASH JOIN=A0=A0=A0=A0 Cost = (1690,1357040,36640080)

=A0 5=A0=A0=A0 4=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= INDEX (analyzed) UNIQUE JDAPROD PRDPLVEEP1 (fast full scan)=A0 Cost (16,100070,8005

=A0 6=A0=A0=A0 4=A0=A0=A0 2=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 TABLE = ACCESS (analyzed)=A0 JDAPROD INVBALEE (full)=A0 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

------_=_NextPart_001_01C1F492.C9B6AF80-- -- Please see the official ORACLE-L FAQ: http://www.orafaq.com -- Author: Suhen Pather INET: Suhen.Pather@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@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).