slow SQL query, diagnosis using 10046 trace event

[Suhen Pather]

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