I had similar problem when migrate from Oracle 8i (8.1.7.3) to Oracle 9i (9.2.0).
When we look at statitics (tkprof and statspack) made in Oracle 8i before migration and stats gathered in Oracle 9i by applying test on that database, we realized that execution plans changed from Oracle 8i to Oracle 9i.

We worked hard trying to figure out where the problems can be found.
Trying with new Oracle 9i parameters over and over, I found that changing the parameter OPTIMIZER_FEATURES_ENABLE=9.2.0 (default) to OPTIMIZER_FEATURES_ENABLE=8.1.7, our application ran successfully as in Oracle 8i.
Also next parameters was set to improve performance:
(* usefulness )

*db_cache_size=1500m
*pga_aggregate_target=314572800
*workarea_size_policy=AUTO
undo_management=auto
undo_tablespace=rbs_01
undo_retention=900
shared_pool_size=117440512

I hope this can be useful for you.

Regards,
Ruben

The DBA is wrong in saying that you need to re-write all your code.
If you read the document Oracle9i Database Migration Release 2 (9.2)and follow the recommendations you should not have ANY problems. Pay special attention to the new initialization parameters and understand SPFILE usage. I've seen several DBO's (not real DBA's) still trying to update an init.ora when their database was running from the SPFILE

Here's the link :
</code> http://download-west.oracle.com/docs/cd/B10501_01/server.920/a96530/toc.htm <code>

Tom we had to roll back our upgrade plans from 8.1.7.4 to 9.2.0.3. There were indeed performance problems. The queries were very slow. If you look in metalink at bug # 3090690, 3086748, 2853398..

We have a Siebel Application that took 7 minutes to run. I increased PGA_AGGREGATE_TARGET and the query is now down to two minutes. I'm still trying to improve it. I set PGA_AGGREGATE_TARGET to 1GB. I took an extended trace, statspack, and PGA statistics during the two minutes it ran. My questions are: 1) This is a select statement, and the extended trace shows a lot of 'direct path write'. Statspack says the PGA cache hit is 100%. PGA advisory shows the PGA is probably too big. Direct path writes mean writing to TEMP, right? Doesn't 100% PGA cache hit mean it's being sorted in memory? What are all of the direct path writes and can I cut down on the amount of them? 2) PGA Advisory always shows estimated PGA cache hit at 51%-52%. Shouldn't it being going with each 100% PGA cache hit?
============================================================
Extended trace file(Abbreviated)
============================================================
Dump file /u00/oracle/admin/dibsn/udump/dibsn_ora_2403.trc
Oracle9i Enterprise Edition Release 9.2.0.4.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
ORACLE_HOME = /u00/oracle/product/920/v64
System name: SunOS
Node name:
Release: 5.8
Version: Generic_108528-21
Machine: sun4u
Instance name: dibsn
Redo thread mounted by this instance: 1
Oracle process number: 21
Unix process pid: 2403, image: oracle@nsu251 (TNS V1-V3)

*** 2004-02-24 16:42:15.517
*** SESSION ID:(27.93) 2004-02-24 16:42:15.516
APPNAME mod='siebmtshmw@nsu251 (TNS V1-V3)' mh=0 act='' ah=0
=====================
PARSING IN CURSOR #4 len=3458 dep=0 uid=1070 oct=3 lid=1070 tim=2903412901739 hv=2954447095 ad='c6b8e938'
SELECT
T15.LAST_UPD_BY,
T15.CREATED,
T15.ROW_ID,
T15.CONFLICT_ID,
T15.CREATED_BY,
T15.CREATED,
T15.LAST_UPD,
T15.MODIFICATION_NUM,
T8.ROW_ID,
T15.OU_ADDR_ID,
T1.MAIN_PH_NUM,
T15.ACT_CLOSE_DT,
T15.X_IBSN_CUST_SATISFIED,
T3.NAME,
T1.CUST_STAT_CD,
T15.X_IBSN_IMPACT,
T15.SR_PROD_VERSION,
T2.EMAIL_ADDR,
T8.MODIFICATION_NUM,
T10.FST_NAME,
T15.X_IBSN_CRITICAL_REASON,
T3.INTEGRATION_ID,
T15.X_IBSN_REPT_SUBISS,
T15.OWNER_EMP_ID,
T15.X_IBSN_MAIL_TYPE,
T15.X_IBSN_ORIG_ZIP_ID,
T15.CST_CON_ID,
T8.CREATED,
T10.LAST_NAME,
T8.LAST_UPD_BY,
T4.NAME,
T15.SR_REPRODUCE,
T2.FST_NAME,
T15.SR_SUB_STAT_ID,
T15.ASGN_USR_EXCLD_FLG,
T15.PR_CON_ORG_ID,
T8.CREATED_BY,
T15.CST_OU_ID,
T12.ZIPCODE,
T15.PRI_LST_ID,
T7.X_IBSN_CUSTNAME,
T1.OU_NUM,
T15.X_IBSN_ACCT_TYPE,
T2.WORK_PH_NUM,
T15.OWNER_OU_ID,
T1.OU_TYPE_CD,
T8.PAR_ROW_ID,
T2.LAST_NAME,
T15.SR_SEV_CD,
T15.SR_PRIO_CD,
T11.LOGIN,
T8.ATTRIB_05,
T14.LOGIN,
T10.ROW_ID,
T8.ATTRIB_45,
T13.SERIAL_NUM,
T15.X_IBSN_DEST_ZIP_ID,
T1.DESC_TEXT,
T8.ATTRIB_03,
T10.WORK_PH_NUM,
T9.ZIPCODE,
T15.SR_STAT_ID,
T15.SR_CST_NUM,
T15.BU_ID,
T15.RATE_LST_ID,
T15.X_IBSN_ESCALATION,
T15.ORG_PRDINT_ID,
T1.X_IBSN_ACCT_NAME,
T1.INTEGRATION_ID,
T15.X_IBSN_REPT_ISSUE,
T15.SR_SUB_AREA,
T15.ASGN_MANL_FLG,
T1.ROW_ID,
T8.LAST_UPD,
T1.PR_ADDR_ID,
T15.ASSET_ID,
T1.PR_SYN_ID,
T15.X_IBSN_SR_TYPE,
T1.PR_SRV_AGREE_ID,
T1.LOC,
T15.ROW_STATUS,
T15.SR_TITLE,
T11.LOGIN,
T15.ASGN_SYS_FLG,
T6.LAST_NAME,
T5.SVC_CALENDAR_ID,
T15.SR_NUM,
T15.BILLABLE_FLG,
T15.SR_AREA,
T15.SR_CAT_TYPE_CD,
T1.MAIN_FAX_PH_NUM,
T2.PR_HELD_POSTN_ID,
T15.PRDINT_ID,
T1.NAME,
T15.DESC_TEXT,
T6.FST_NAME,
T3.ROW_ID,
T15.X_IBSN_REPT_CAT,
T15.AGREE_ID,
T15.SR_SUBTYPE_CD,
T15.PR_SYMPTOM_CD,
T10.PR_OU_ADDR_ID,
T8.CONFLICT_ID,
T15.SR_TYPE_CD
FROM
SIEBEL.S_ORG_EXT T1,
SIEBEL.S_CONTACT T2,
SIEBEL.S_ORG_EXT T3,
SIEBEL.S_ORG_EXT T4,
SIEBEL.S_ENTLMNT T5,
SIEBEL.S_CONTACT T6,
SIEBEL.S_ADDR_ORG T7,
SIEBEL.S_SRV_REQ_X T8,
SIEBEL.S_ZIPCODE T9,
SIEBEL.S_CONTACT T10,
SIEBEL.S_USER T11,
SIEBEL.S_ZIPCODE T12,
SIEBEL.S_ASSET T13,
SIEBEL.S_USER T14,
SIEBEL.S_SRV_REQ T15
WHERE
T15.PR_CON_ORG_ID = T3.PAR_ROW_ID (+) AND
T15.CREATED_BY = T14.PAR_ROW_ID (+) AND
T15.X_IBSN_DEST_ZIP_ID = T12.ROW_ID (+) AND
T15.OWNER_EMP_ID = T2.ROW_ID AND
T15.OWNER_EMP_ID = T11.PAR_ROW_ID (+) AND
T8.ATTRIB_03 = T6.PAR_ROW_ID (+) AND
T15.OU_ADDR_ID = T7.ROW_ID (+) AND
T15.ASSET_ID = T13.ROW_ID (+) AND
T15.CST_CON_ID = T10.PAR_ROW_ID (+) AND
T15.AGREE_ID = T5.ROW_ID (+) AND
T15.CST_OU_ID = T1.PAR_ROW_ID (+) AND
T15.OWNER_OU_ID = T4.PAR_ROW_ID (+) AND
T15.X_IBSN_ORIG_ZIP_ID = T9.ROW_ID (+) AND
T15.ROW_ID = T8.PAR_ROW_ID (+) AND
(T15.TEMPLATE_FLG != 'Y')
ORDER BY
T15.CREATED DESC
END OF STMT
PARSE#4:c=0,e=202,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=2903412901731
WAIT #4: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net more data to client' ela= 66 p1=1413697536 p2=2002 p3=0
WAIT #4: nam='SQL*Net more data to client' ela= 54 p1=1413697536 p2=2003 p3=0
WAIT #4: nam='SQL*Net message from client' ela= 2682 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net more data from client' ela= 20 p1=1413697536 p2=2 p3=0
EXEC #4:c=0,e=265,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=2903412908304
*** 2004-02-24 16:42:30.442
WAIT #4: nam='direct path write' ela= 194978 p1=201 p2=39561 p3=31
WAIT #4: nam='direct path write' ela= 198233 p1=201 p2=39592 p3=31
WAIT #4: nam='direct path write' ela= 191796 p1=201 p2=39623 p3=31
WAIT #4: nam='direct path write' ela= 185470 p1=201 p2=39654 p3=31
WAIT #4: nam='direct path write' ela= 27722 p1=201 p2=39685 p3=4
WAIT #4: nam='direct path write' ela= 191402 p1=201 p2=39433 p3=31
WAIT #4: nam='direct path write' ela= 579408 p1=201 p2=39464 p3=31
WAIT #4: nam='direct path write' ela= 24123 p1=201 p2=39557 p3=4
WAIT #4: nam='direct path write' ela= 197607 p1=201 p2=39305 p3=31
WAIT #4: nam='direct path write' ela= 192888 p1=201 p2=39336 p3=31
WAIT #4: nam='direct path write' ela= 191281 p1=201 p2=39367 p3=31
WAIT #4: nam='direct path write' ela= 264295 p1=201 p2=39398 p3=31
WAIT #4: nam='direct path write' ela= 146731 p1=201 p2=39177 p3=31
WAIT #4: nam='direct path write' ela= 201026 p1=201 p2=39208 p3=31
WAIT #4: nam='direct path write' ela= 200723 p1=201 p2=39239 p3=31
WAIT #4: nam='direct path write' ela= 193132 p1=201 p2=39270 p3=31
WAIT #4: nam='direct path write' ela= 31729 p1=201 p2=39301 p3=4
WAIT #4: nam='direct path write' ela= 191503 p1=201 p2=39049 p3=31
WAIT #4: nam='direct path write' ela= 192982 p1=201 p2=39080 p3=31
WAIT #4: nam='direct path write' ela= 185468 p1=201 p2=39111 p3=31
WAIT #4: nam='direct path write' ela= 191698 p1=201 p2=39142 p3=31
WAIT #4: nam='direct path write' ela= 32895 p1=201 p2=39173 p3=4
WAIT #4: nam='direct path write' ela= 209686 p1=201 p2=38921 p3=31
WAIT #4: nam='direct path write' ela= 192669 p1=201 p2=38952 p3=31
WAIT #4: nam='direct path write' ela= 191747 p1=201 p2=38983 p3=31
WAIT #4: nam='direct path write' ela= 191431 p1=201 p2=39014 p3=31
.
.
.
WAIT #4: nam='direct path read' ela= 701 p1=201 p2=37497 p3=16
WAIT #4: nam='direct path read' ela= 464 p1=201 p2=27534 p3=31
WAIT #4: nam='direct path read' ela= 491 p1=201 p2=37781 p3=31
WAIT #4: nam='direct path read' ela= 926 p1=201 p2=39561 p3=31
WAIT #4: nam='direct path read' ela= 47 p1=201 p2=27079 p3=31
WAIT #4: nam='SQL*Net message to client' ela= 12 p1=1413697536 p2=1 p3=0
FETCH #4:c=38750000,e=133384647,p=811,cr=2584398,cu=16,mis=0,r=2,dep=0,og=3,tim=2903546293018
WAIT #4: nam='SQL*Net message from client' ela= 6509 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
FETCH #4:c=0,e=209,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=3,tim=2903546300212
WAIT #4: nam='SQL*Net message from client' ela= 3618 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
FETCH #4:c=0,e=161,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=3,tim=2903546304170
WAIT #4: nam='SQL*Net message from client' ela= 3442 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net more data to client' ela= 56 p1=1413697536 p2=2199 p3=0
FETCH #4:c=0,e=310,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=3,tim=2903546308079
WAIT #4: nam='SQL*Net message from client' ela= 4107 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
FETCH #4:c=0,e=174,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=3,tim=2903546312530
=========================================================
Statspack(Abbreviated)
=========================================================
STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
DIBSN 808090191 dibsn 1 9.2.0.4.0 NO su251

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 23 24-Feb-04 16:42:20 20 5.5
End Snap: 24 24-Feb-04 16:44:39 20 5.5
Elapsed: 2.32 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,024M Std Block Size: 8K
Shared Pool Size: 1,024M Log Buffer: 1,600K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
------

There was also one query before this, to check on privileges before this. I also forgot to mention that we can't go to CBO with Siebel. Below is the output from tkprof, and after that some statspack.


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 5 38.75 133.38 811 2584398 16 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 38.75 133.38 811 2584398 16 10

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 1070

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net more data to client 3 0.00 0.00
SQL*Net message from client 5 0.00 0.02
SQL*Net more data from client 1 0.00 0.00
direct path write 576 0.57 96.33
direct path read 15 0.00 0.01



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 6 38.75 133.38 811 2584431 16 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 38.75 133.38 811 2584431 16 10

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 8 0.00 0.00
SQL*Net message from client 7 0.00 0.02
SQL*Net more data from client 2 0.00 0.00
SQL*Net more data to client 3 0.00 0.00
direct path write 576 0.57 96.33
direct path read 15 0.00 0.01


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: dibsn_ora_2403.trc
Trace file compatibility: 9.00.01
Sort options: default

1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
805 lines in trace file.

============================================================
Statspack - Abbreviated
============================================================
STATSPACK report for

DB Name DB Id Instance Inst Num Release Cluster Host
------------ ----------- ------------ -------- ----------- ------- ------------
DIBSN 808090191 dibsn 1 9.2.0.4.0 NO su251

Snap Id Snap Time Sessions Curs/Sess Comment
------- ------------------ -------- --------- -------------------
Begin Snap: 23 24-Feb-04 16:42:20 20 5.5
End Snap: 24 24-Feb-04 16:44:39 20 5.5
Elapsed: 2.32 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 1,024M Std Block Size: 8K
Shared Pool Size: 1,024M Log Buffer: 1,600K

Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 2,840.23 394,792.00
Logical reads: 14,774.64 2,053,675.00
Block changes: 4.29 597.00
Physical reads: 5.84 812.00
Physical writes: 115.78 16,094.00
User calls: 1.00 139.00
Parses: 0.14 19.00
Hard parses: 0.01 1.00
Sorts: 0.64 89.00
Logons: 0.00 0.00
Executes: 1.20 167.00
Transactions: 0.01

% Blocks changed per Read: 0.03 Recursive Call %: 56.70
Rollback per transaction %: 0.00 Rows per Sort: 1494.17

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 100.00 In-memory Sort %: 98.88
Library Hit %: 99.10 Soft Parse %: 94.74
Execute to Parse %: 88.62 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 100.00 % Non-Parse CPU: 99.98

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 18.40 18.40
% SQL with executions>1: 54.21 54.25
% Memory for SQL w/exec>1: 63.69 63.70

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
direct path write 576 96 65.05
CPU time 46 30.94
control file parallel write 44 4 3.03
log file sync 2 1 .64
db file parallel write 4 0 .34
-------------------------------------------------------------
Wait Events for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> s - second
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
direct path write 576 0 96 167 576.0
control file parallel write 44 0 4 102 44.0
log file sync 2 0 1 472 2.0
db file parallel write 4 0 0 124 4.0
direct path read 15 0 0 1 15.0
db file sequential read 1 0 0 7 1.0
control file sequential read 62 0 0 0 62.0
log file parallel write 6 6 0 0 6.0
SQL*Net more data to client 1 0 0 0 1.0
SQL*Net message from client 135 0 548 4059 135.0
SQL*Net message to client 136 0 0 0 136.0
-------------------------------------------------------------
Background Wait Events for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> ordered by wait time desc, waits desc (idle events last)

Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
control file parallel write 43 0 4 104 43.0
db file parallel write 3 0 0 145 3.0
control file sequential read 12 0 0 0 12.0
log file parallel write 5 5 0 0 5.0
rdbms ipc message 144 142 395 2742 144.0
pmon timer 47 47 135 2876 47.0
smon timer 1 1 45 45155 1.0
-------------------------------------------------------------
SQL ordered by Gets for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> End Buffer Gets Threshold: 10000
-> Note that resources reported for PL/SQL includes the resources used by
all SQL statements called within the PL/SQL code. As individual SQL
statements are also reported, it is possible and valid for the summed
total % to exceed 100

CPU Elapsd
Buffer Gets Executions Gets per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
80,472 12 6,706.0 3.9 1.74 1.71 4126713147
Module: siebmtsh@eagnmnsu251 (TNS V1-V3)
select ROW_ID, PAR_REQ_ID from SIEBEL.S_SRM_REQUEST where
STATUS = 'QUEUED' and EXPIRATION_DT < SYSDATE


Instance Activity Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
CPU used by this session 4,582 33.0 4,582.0
CPU used when call started 4,583 33.0 4,583.0
CR blocks created 0 0.0 0.0
DBWR checkpoint buffers written 7 0.1 7.0
DBWR checkpoints 0 0.0 0.0
DBWR transaction table writes 2 0.0 2.0
DBWR undo block writes 3 0.0 3.0
SQL*Net roundtrips to/from client 128 0.9 128.0
active txn count during cleanout 17 0.1 17.0
background checkpoints completed 0 0.0 0.0
background checkpoints started 0 0.0 0.0
background timeouts 160 1.2 160.0
buffer is not pinned count 1,947,541 14,011.1 1,947,541.0
buffer is pinned count 2,113,922 15,208.1 2,113,922.0
bytes received via SQL*Net from c 6,154 44.3 6,154.0
bytes sent via SQL*Net to client 23,771 171.0 23,771.0
calls to get snapshot scn: kcmgss 282 2.0 282.0
calls to kcmgas 12 0.1 12.0
calls to kcmgcs 10 0.1 10.0
change write time 1 0.0 1.0
cleanout - number of ktugct calls 34 0.2 34.0
cleanouts and rollbacks - consist 0 0.0 0.0
cleanouts only - consistent read 9 0.1 9.0
cluster key scan block gets 12 0.1 12.0
cluster key scans 3 0.0 3.0
commit cleanout failures: callbac 1 0.0 1.0
commit cleanouts 86 0.6 86.0
commit cleanouts successfully com 85 0.6 85.0
commit txn count during cleanout 28 0.2 28.0
consistent changes 0 0.0 0.0
consistent gets 2,053,002 14,769.8 2,053,002.0
consistent gets - examination 1,773,851 12,761.5 1,773,851.0
cursor authentications 1 0.0 1.0
data blocks consistent reads - un 0 0.0 0.0
db block changes 597 4.3 597.0
db block gets 586 4.2 586.0
deferred (CURRENT) block cleanout 37 0.3 37.0
enqueue conversions 25 0.2 25.0
enqueue releases 263 1.9 263.0
enqueue requests 263 1.9 263.0
execute count 167 1.2 167.0
free buffer requested 39 0.3 39.0
immediate (CR) block cleanout app 9 0.1 9.0
immediate (CURRENT) block cleanou 22 0.2 22.0
index fetch by key 842,946 6,064.4 842,946.0
index scans kdiixs1 100,245 721.2 100,245.0
leaf node 90-10 splits 1 0.0 1.0
leaf node splits 10 0.1 10.0
logons cumulative 0 0.0 0.0
messages received 4 0.0 4.0
messages sent 4 0.0 4.0
no buffer to keep pinned count 0 0.0 0.0
no work - consistent read gets 186,722 1,343.3 186,722.0
opened cursors cumulative 18 0.1 18.0
parse count (failures) 0 0.0 0.0
parse count (hard) 1 0.0 1.0
Instance Activity Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24

Statistic Total per Second per Trans
--------------------------------- ------------------ -------------- ------------
parse count (total) 19 0.1 19.0
parse time cpu 1 0.0 1.0
parse time elapsed 1 0.0 1.0
physical reads 812 5.8 812.0
physical reads direct 811 5.8 811.0
physical writes 16,094 115.8 16,094.0
physical writes direct 16,087 115.7 16,087.0
physical writes non checkpoint 16,089 115.8 16,089.0
prefetched blocks 0 0.0 0.0
process last non-idle time 0 0.0 0.0
recursive calls 182 1.3 182.0
recursive cpu usage 486 3.5 486.0
redo blocks written 840 6.0 840.0
redo buffer allocation retries 0 0.0 0.0
redo entries 310 2.2 310.0
redo log space requests 0 0.0 0.0
redo log space wait time 0 0.0 0.0
redo size 394,792 2,840.2 394,792.0
redo synch time 61 0.4 61.0
redo synch writes 1 0.0 1.0
redo wastage 1,504 10.8 1,504.0
redo write time 138 1.0 138.0
redo writes 6 0.0 6.0
rollback changes - undo records a 2 0.0 2.0
rollbacks only - consistent read 0 0.0 0.0
rows fetched via callback 842,458 6,060.9 842,458.0
session connect time 0 0.0 0.0
session logical reads 2,053,675 14,774.6 2,053,675.0
session pga memory max 23,339,416 167,909.5 ############
session uga memory max 22,238,720 159,990.8 ############
shared hash latch upgrades - no w 100,271 721.4 100,271.0
shared hash latch upgrades - wait 0 0.0 0.0
sorts (disk) 1 0.0 1.0
sorts (memory) 88 0.6 88.0
sorts (rows) 132,981 956.7 132,981.0
switch current to new buffer 0 0.0 0.0
table fetch by rowid 1,554,641 11,184.5 1,554,641.0
table fetch continued row 0 0.0 0.0
table scan blocks gotten 9,376 67.5 9,376.0
table scan rows gotten 89,287 642.4 89,287.0
table scans (long tables) 0 0.0 0.0
table scans (short tables) 31 0.2 31.0
transaction rollbacks 1 0.0 1.0
user calls 139 1.0 139.0
user commits 1 0.0 1.0
user rollbacks 0 0.0 0.0
workarea executions - onepass 0 0.0 0.0
workarea executions - optimal 93 0.7 93.0
-------------------------------------------------------------
Tablespace IO Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24
->ordered by IOs (Reads + Writes) desc

Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
TEMP_TS
28 0 0.4 29.0 623 4 0 0.0
UNDO_TS
0 0 0.0 5 0 0 0.0
DATA_TS
0 0 0.0 3 0 0 0.0
INDEX_TS
0 0 0.0 2 0 0 0.0
PERFSTAT
1 0 10.0 1.0 0 0 0 0.0
SYSTEM
0 0 0.0 1 0 0 0.0
-------------------------------------------------------------
File IO Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24
->ordered by Tablespace, File

Tablespace Filename
------------------------ ----------------------------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
DATA_TS /d00/oradata/dibsn/data_ts01.dbf
0 0 3 0 0

INDEX_TS /d00/oradata/dibsn/index_ts01.dbf
0 0 2 0 0

PERFSTAT /d00/oradata/dibsn/perfstat.dbf
1 0 10.0 1.0 0 0 0

SYSTEM /d00/oradata/dibsn/system01.dbf
0 0 1 0 0

TEMP_TS /d00/oradata/dibsn/temp_ts01.dbf
28 0 0.4 29.0 623 4 0

UNDO_TS /d00/oradata/dibsn/undo_ts1.dbf
0 0 5 0 0

-------------------------------------------------------------
Buffer Pool Statistics for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> Standard block size Pools D: default, K: keep, R: recycle
-> Default Pools for other block sizes: 2k, 4k, 8k, 16k, 32k

Free Write Buffer
Number of Cache Buffer Physical Physical Buffer Complete Busy
P Buffers Hit % Gets Reads Writes Waits Waits Waits
--- ---------- ----- ----------- ----------- ---------- ------- -------- ------
D 127,040 100.0 2,368,257 0 11 0 0 0
-------------------------------------------------------------

Instance Recovery Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> B: Begin snapshot, E: End snapshot

Targt Estd Log File Log Ckpt Log Ckpt
MTTR MTTR Recovery Actual Target Size Timeout Interval
(s) (s) Estd IOs Redo Blks Redo Blks Redo Blks Redo Blks Redo Blks
- ----- ----- ---------- ---------- ---------- ---------- ---------- ----------
B 0 18 339 2385 2334 92160 2334 500000
E 0 18 391 3476 3160 92160 3160 500000
-------------------------------------------------------------

Buffer Pool Advisory for DB: DIBSN Instance: dibsn End Snap: 24
-> Only rows with estimated physical reads >0 are displayed
-> ordered by Block Size, Buffers For Estimate

Size for Size Buffers for Est Physical Estimated
P Estimate (M) Factr Estimate Read Factor Physical Reads
--- ------------ ----- ---------------- ------------- ------------------
D 96 .1 11,910 32.67 1,567,666
D 192 .2 23,820 13.94 668,827
D 288 .3 35,730 10.05 482,216
D 384 .4 47,640 1.00 48,117
D 480 .5 59,550 1.00 47,992
D 576 .6 71,460 1.00 47,992
D 672 .7 83,370 1.00 47,992
D 768 .8 95,280 1.00 47,992
D 864 .8 107,190 1.00 47,992
D 960 .9 119,100 1.00 47,992
D 1,024 1.0 127,040 1.00 47,992
D 1,056 1.0 131,010 1.00 47,992
D 1,152 1.1 142,920 1.00 47,992
D 1,248 1.2 154,830 1.00 47,992
D 1,344 1.3 166,740 1.00 47,992
D 1,440 1.4 178,650 1.00 47,992
D 1,536 1.5 190,560 1.00 47,992
D 1,632 1.6 202,470 1.00 47,992
D 1,728 1.7 214,380 1.00 47,992
D 1,824 1.8 226,290 1.00 47,992
D 1,920 1.9 238,200 1.00 47,992
-------------------------------------------------------------
PGA Aggr Target Stats for DB: DIBSN Instance: dibsn Snaps: 23 -24
-> B:

The output of the tkprof for the time period didn't show a plan. I've pasted the plan from a similar run for the same query, just a little bit earlier...

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.01 0.01 0 0 0 0
Fetch 5 38.57 135.02 811 2584364 16 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 38.58 135.03 811 2584364 16 10

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 1040

Rows Row Source Operation
------- ---------------------------------------------------
10 SORT ORDER BY (cr=2584364 r=811 w=16086 time=135027403 us)
116893 NESTED LOOPS OUTER (cr=2584364 r=0 w=0 time=32745795 us)
116893 NESTED LOOPS OUTER (cr=2352085 r=0 w=0 time=30317702 us)
116893 NESTED LOOPS OUTER (cr=2117976 r=0 w=0 time=26138732 us)
116893 NESTED LOOPS (cr=1884188 r=0 w=0 time=23162321 us)
116916 NESTED LOOPS OUTER (cr=1650400 r=0 w=0 time=20527537 us)
116916 NESTED LOOPS OUTER (cr=1417926 r=0 w=0 time=17699311 us)
116916 NESTED LOOPS OUTER (cr=1417926 r=0 w=0 time=17194639 us)
116916 NESTED LOOPS OUTER (cr=1417926 r=0 w=0 time=16621733 us)
116916 NESTED LOOPS OUTER (cr=1068617 r=0 w=0 time=13573507 us)
116916 NESTED LOOPS OUTER (cr=890187 r=0 w=0 time=11759108 us)
116916 NESTED LOOPS OUTER (cr=656540 r=0 w=0 time=8509761 us)
116916 NESTED LOOPS OUTER (cr=422752 r=0 w=0 time=6439045 us)
116916 NESTED LOOPS OUTER (cr=246642 r=0 w=0 time=4434551 us)
116916 NESTED LOOPS OUTER (cr=246642 r=0 w=0 time=3897303 us)
116916 TABLE ACCESS FULL S_SRV_REQ (cr=12814 r=0 w=0 time=1171274 us)
116910 TABLE ACCESS BY INDEX ROWID S_USER (cr=233828 r=0 w=0 time=2142510 us)
116910 INDEX UNIQUE SCAN S_USER_U2 (cr=116918 r=0 w=0 time=1098468 us)(object id 73361)
0 TABLE ACCESS BY INDEX ROWID S_ASSET (cr=0 r=0 w=0 time=159187 us)
0 INDEX UNIQUE SCAN S_ASSET_P1 (cr=0 r=0 w=0 time=43542 us)(object id 64978)
88054 TABLE ACCESS BY INDEX ROWID S_ZIPCODE (cr=176110 r=0 w=0 time=1580226 us)
88054 INDEX UNIQUE SCAN S_ZIPCODE_P1 (cr=88056 r=0 w=0 time=808235 us)(object id 73673)
116893 TABLE ACCESS BY INDEX ROWID S_USER (cr=233788 r=0 w=0 time=1629940 us)
116893 INDEX UNIQUE SCAN S_USER_U2 (cr=116895 r=0 w=0 time=836169 us)(object id 73361)
116822 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=233647 r=0 w=0 time=2777513 us)
116822 INDEX UNIQUE SCAN S_CONTACT_U2 (cr=116825 r=0 w=0 time=1192275 us)(object id 65967)
89214 TABLE ACCESS BY INDEX ROWID S_ZIPCODE (cr=178430 r=0 w=0 time=1368238 us)
89214 INDEX UNIQUE SCAN S_ZIPCODE_P1 (cr=89216 r=0 w=0 time=695398 us)(object id 73673)
116393 TABLE ACCESS BY INDEX ROWID S_ADDR_ORG (cr=349309 r=0 w=0 time=2569253 us)
116393 INDEX UNIQUE SCAN S_ADDR_ORG_P1 (cr=232916 r=0 w=0 time=1388676 us)(object id 64617)
0 TABLE ACCESS BY INDEX ROWID S_ENTLMNT (cr=0 r=0 w=0 time=195184 us)
0 INDEX UNIQUE SCAN S_ENTLMNT_P1 (cr=0 r=0 w=0 time=39297 us)(object id 67667)
0 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=0 r=0 w=0 time=136823 us)
0 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=0 r=0 w=0 time=40472 us)(object id 70193)
115918 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=232474 r=0 w=0 time=2327534 us)
115918 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=116556 r=0 w=0 time=1026256 us)(object id 70193)
116893 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=233788 r=0 w=0 time=2210582 us)
116893 INDEX UNIQUE SCAN S_CONTACT_P1 (cr=116895 r=0 w=0 time=938553 us)(object id 65966)
116893 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=233788 r=0 w=0 time=2448011 us)
116893 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=116895 r=0 w=0 time=827132 us)(object id 70193)
116890 TABLE ACCESS BY INDEX ROWID S_SRV_REQ_X (cr=234109 r=0 w=0 time=3500634 us)
116890 INDEX RANGE SCAN S_SRV_REQ_X_U1 (cr=117219 r=0 w=0 time=1984483 us)(object id 72867)
116138 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=232279 r=0 w=0 time=1900900 us)
116138 INDEX UNIQUE SCAN S_CONTACT_U2 (cr=116141 r=0 w=0 time=1032064 us)(object id 65967)

I saw the Direct IO wait (which I understand is a write to temp and so part of the sort which your suggestion tunes).

Can you clarify whether the sort results in 10 rows, or whether the sort is actually sorting 10 rows?

I curious as to what the actual query is doing, it looks to me like there is a distinct on a join or something like that. ie: processing the 116910 rows and pulling out 10.

Would an indexing strategy that reduced the number of rows that came out of the step:

116910 TABLE ACCESS BY INDEX ROWID S_USER (cr=233828 r=0 w=0
time=2142510 us)

also help?

I am thinking that by reducing the number of rows that get to the sort we might resolve the problem with the sort to disk.

Of course, it all depends on what the query is.

I'm just trying to develop my understanding of query tuning and this caught my eye...
...I've been reading Guy Harrison's book - I am pretty impressed although some of the material seems to be a little dated with respect to 9i.

Regards.

Thanks.

Performance on 9i is not good and everything is related to optimizer_features_enable = 9.2.0.
It is not a good idea to migrate unless ORACLE solves the issue related to this parameter and the hidden params it turns on. maybe a good idea to skip this bug product and wait for 10g

We've been on 9.2.0.4 for 10 weeks, upgrading from 8.1.7.4. After our initial upgrade we too saw some performance problems in the database, queries taking longer to run, disk IO higher, cpu usage nearly maxed out.
Turns out most of the query performance problems were due to stale statistics and query hints that were no longer relevant. We also found an OEM 9.2 bug on HPUX that caused an interminable amount of delete activity from an OEM table that churned up tons of disk IO and cpu usage, not to mention periodic spikes in archived redo log generation.
After recomputing stats on the relevant tables and indexes, removing hints that were not absolutely necessary, and cleaning up the OEM repository manually, our cpu and disk IO dropped to less than HALF the level from 8.1.7.4! And, since we recently doubled the memory on the server, our query performance (data warehouse environment) has increased quite a bit with the larger buffer cache and sort area size.

Tom,

the filter at each level of the Siebel app produced 1k or more rows but at end only 10 rows?

Can following sql shed some light

select t15.*, t2.* from t15, t2
WHERE
T15.OWNER_EMP_ID = T2.ROW_ID AND
(T15.TEMPLATE_FLG != 'Y')
ORDER BY
T15.CREATED DESC

I am just curious as to how 10 rows.

Thanks

I set workarea_size_policy to manual, and sort_area_size to 50000000. The elapsed time was just about the same as before, with workarea_size_policy set to auto, and the plan looks the same. The application returns 10 rows and displays them to the screen. When a '+' is clicked on, then the next 10 rows show, and so on.


TKPROF: Release 9.2.0.1.0 - Production on Fri Feb 27 14:47:43 2004

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.

Trace file: dibsn_ora_21216.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

alter session set sql_trace=true


SELECT
T15.LAST_UPD_BY,
T15.CREATED,
T15.ROW_ID,
T15.CONFLICT_ID,
T15.CREATED_BY,
T15.CREATED,
T15.LAST_UPD,
T15.MODIFICATION_NUM,
T8.ROW_ID,
T15.OU_ADDR_ID,
T1.MAIN_PH_NUM,
T15.ACT_CLOSE_DT,
T15.X_IBSN_CUST_SATISFIED,
T3.NAME,
T1.CUST_STAT_CD,
T15.X_IBSN_IMPACT,
T15.SR_PROD_VERSION,
T2.EMAIL_ADDR,
T8.MODIFICATION_NUM,
T10.FST_NAME,
T15.X_IBSN_CRITICAL_REASON,
T3.INTEGRATION_ID,
T15.X_IBSN_REPT_SUBISS,
T15.OWNER_EMP_ID,
T15.X_IBSN_MAIL_TYPE,
T15.X_IBSN_ORIG_ZIP_ID,
T15.CST_CON_ID,
T8.CREATED,
T10.LAST_NAME,
T8.LAST_UPD_BY,
T4.NAME,
T15.SR_REPRODUCE,
T2.FST_NAME,
T15.SR_SUB_STAT_ID,
T15.ASGN_USR_EXCLD_FLG,
T15.PR_CON_ORG_ID,
T8.CREATED_BY,
T15.CST_OU_ID,
T12.ZIPCODE,
T15.PRI_LST_ID,
T7.X_IBSN_CUSTNAME,
T1.OU_NUM,
T15.X_IBSN_ACCT_TYPE,
T2.WORK_PH_NUM,
T15.OWNER_OU_ID,
T1.OU_TYPE_CD,
T8.PAR_ROW_ID,
T2.LAST_NAME,
T15.SR_SEV_CD,
T15.SR_PRIO_CD,
T11.LOGIN,
T8.ATTRIB_05,
T14.LOGIN,
T10.ROW_ID,
T8.ATTRIB_45,
T13.SERIAL_NUM,
T15.X_IBSN_DEST_ZIP_ID,
T1.DESC_TEXT,
T8.ATTRIB_03,
T10.WORK_PH_NUM,
T9.ZIPCODE,
T15.SR_STAT_ID,
T15.SR_CST_NUM,
T15.BU_ID,
T15.RATE_LST_ID,
T15.X_IBSN_ESCALATION,
T15.ORG_PRDINT_ID,
T1.X_IBSN_ACCT_NAME,
T1.INTEGRATION_ID,
T15.X_IBSN_REPT_ISSUE,
T15.SR_SUB_AREA,
T15.ASGN_MANL_FLG,
T1.ROW_ID,
T8.LAST_UPD,
T1.PR_ADDR_ID,
T15.ASSET_ID,
T1.PR_SYN_ID,
T15.X_IBSN_SR_TYPE,
T1.PR_SRV_AGREE_ID,
T1.LOC,
T15.ROW_STATUS,
T15.SR_TITLE,
T11.LOGIN,
T15.ASGN_SYS_FLG,
T6.LAST_NAME,
T5.SVC_CALENDAR_ID,
T15.SR_NUM,
T15.BILLABLE_FLG,
T15.SR_AREA,
T15.SR_CAT_TYPE_CD,
T1.MAIN_FAX_PH_NUM,
T2.PR_HELD_POSTN_ID,
T15.PRDINT_ID,
T1.NAME,
T15.DESC_TEXT,
T6.FST_NAME,
T3.ROW_ID,
T15.X_IBSN_REPT_CAT,
T15.AGREE_ID,
T15.SR_SUBTYPE_CD,
T15.PR_SYMPTOM_CD,
T10.PR_OU_ADDR_ID,
T8.CONFLICT_ID,
T15.SR_TYPE_CD
FROM
SIEBEL.S_ORG_EXT T1,
SIEBEL.S_CONTACT T2,
SIEBEL.S_ORG_EXT T3,
SIEBEL.S_ORG_EXT T4,
SIEBEL.S_ENTLMNT T5,
SIEBEL.S_CONTACT T6,
SIEBEL.S_ADDR_ORG T7,
SIEBEL.S_SRV_REQ_X T8,
SIEBEL.S_ZIPCODE T9,
SIEBEL.S_CONTACT T10,
SIEBEL.S_USER T11,
SIEBEL.S_ZIPCODE T12,
SIEBEL.S_ASSET T13,
SIEBEL.S_USER T14,
SIEBEL.S_SRV_REQ T15
WHERE
T15.PR_CON_ORG_ID = T3.PAR_ROW_ID (+) AND
T15.CREATED_BY = T14.PAR_ROW_ID (+) AND
T15.X_IBSN_DEST_ZIP_ID = T12.ROW_ID (+) AND
T15.OWNER_EMP_ID = T2.ROW_ID AND
T15.OWNER_EMP_ID = T11.PAR_ROW_ID (+) AND
T8.ATTRIB_03 = T6.PAR_ROW_ID (+) AND
T15.OU_ADDR_ID = T7.ROW_ID (+) AND
T15.ASSET_ID = T13.ROW_ID (+) AND
T15.CST_CON_ID = T10.PAR_ROW_ID (+) AND
T15.AGREE_ID = T5.ROW_ID (+) AND
T15.CST_OU_ID = T1.PAR_ROW_ID (+) AND
T15.OWNER_OU_ID = T4.PAR_ROW_ID (+) AND
T15.X_IBSN_ORIG_ZIP_ID = T9.ROW_ID (+) AND
T15.ROW_ID = T8.PAR_ROW_ID (+) AND
(T15.TEMPLATE_FLG != 'Y')
ORDER BY
T15.CREATED DESC

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.02 0.02 0 0 0 0
Fetch 5 39.11 133.15 190 2584538 4 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 39.13 133.18 190 2584538 4 10

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 1070

Rows Row Source Operation
------- ---------------------------------------------------
10 SORT ORDER BY (cr=2584538 r=190 w=16083 time=133159165 us)
116902 NESTED LOOPS OUTER (cr=2584538 r=0 w=0 time=33450991 us)
116902 NESTED LOOPS OUTER (cr=2352247 r=0 w=0 time=31034499 us)
116902 NESTED LOOPS OUTER (cr=2118120 r=0 w=0 time=26982220 us)
116902 NESTED LOOPS (cr=1884314 r=0 w=0 time=23955279 us)
116925 NESTED LOOPS OUTER (cr=1650508 r=0 w=0 time=21232313 us)
116925 NESTED LOOPS OUTER (cr=1418020 r=0 w=0 time=18381378 us)
116925 NESTED LOOPS OUTER (cr=1418020 r=0 w=0 time=17934260 us)
116925 NESTED LOOPS OUTER (cr=1418020 r=0 w=0 time=17413237 us)
116925 NESTED LOOPS OUTER (cr=1068684 r=0 w=0 time=14271972 us)
116925 NESTED LOOPS OUTER (cr=890248 r=0 w=0 time=12399599 us)
116925 NESTED LOOPS OUTER (cr=656583 r=0 w=0 time=8861286 us)
116925 NESTED LOOPS OUTER (cr=422777 r=0 w=0 time=6722518 us)
116925 NESTED LOOPS OUTER (cr=246661 r=0 w=0 time=4660756 us)
116925 NESTED LOOPS OUTER (cr=246661 r=0 w=0 time=4108752 us)
116925 TABLE ACCESS FULL S_SRV_REQ (cr=12814 r=0 w=0 time=1204769 us)
116919 TABLE ACCESS BY INDEX ROWID S_USER (cr=233847 r=0 w=0 time=2179138 us)
116919 INDEX UNIQUE SCAN S_USER_U2 (cr=116927 r=0 w=0 time=1101627 us)(object id 73361)
0 TABLE ACCESS BY INDEX ROWID S_ASSET (cr=0 r=0 w=0 time=160858 us)
0 INDEX UNIQUE SCAN S_ASSET_P1 (cr=0 r=0 w=0 time=45211 us)(object id 64978)
88057 TABLE ACCESS BY INDEX ROWID S_ZIPCODE (cr=176116 r=0 w=0 time=1620757 us)
88057 INDEX UNIQUE SCAN S_ZIPCODE_P1 (cr=88059 r=0 w=0 time=826905 us)(object id 73673)
116902 TABLE ACCESS BY INDEX ROWID S_USER (cr=233806 r=0 w=0 time=1684509 us)
116902 INDEX UNIQUE SCAN S_USER_U2 (cr=116904 r=0 w=0 time=867956 us)(object id 73361)
116831 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=233665 r=0 w=0 time=3027409 us)
116831 INDEX UNIQUE SCAN S_CONTACT_U2 (cr=116834 r=0 w=0 time=1314118 us)(object id 65967)
89217 TABLE ACCESS BY INDEX ROWID S_ZIPCODE (cr=178436 r=0 w=0 time=1421983 us)
89217 INDEX UNIQUE SCAN S_ZIPCODE_P1 (cr=89219 r=0 w=0 time=716932 us)(object id 73673)
116402 TABLE ACCESS BY INDEX ROWID S_ADDR_ORG (cr=349336 r=0 w=0 time=2616650 us)
116402 INDEX UNIQUE SCAN S_ADDR_ORG_P1 (cr=232934 r=0 w=0 time=1402699 us)(object id 64617)
0 TABLE ACCESS BY INDEX ROWID S_ENTLMNT (cr=0 r=0 w=0 time=147622 us)
0 INDEX UNIQUE SCAN S_ENTLMNT_P1 (cr=0 r=0 w=0 time=39583 us)(object id 67667)
0 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=0 r=0 w=0 time=140892 us)
0 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=0 r=0 w=0 time=40347 us)(object id 70193)
115925 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=232488 r=0 w=0 time=2406276 us)
115925 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=116563 r=0 w=0 time=1099726 us)(object id 70193)
116902 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=233806 r=0 w=0 time=2281919 us)
116902 INDEX UNIQUE SCAN S_CONTACT_P1 (cr=116904 r=0 w=0 time=934200 us)(object id 65966)
116902 TABLE ACCESS BY INDEX ROWID S_ORG_EXT (cr=233806 r=0 w=0 time=2515105 us)
116902 INDEX UNIQUE SCAN S_ORG_EXT_U3 (cr=116904 r=0 w=0 time=846813 us)(object id 70193)
116899 TABLE ACCESS BY INDEX ROWID S_SRV_REQ_X (cr=234127 r=0 w=0 time=3375594 us)
116899 INDEX RANGE SCAN S_SRV_REQ_X_U1 (cr=117228 r=0 w=0 time=1929708 us)(object id 72867)
116144 TABLE ACCESS BY INDEX ROWID S_CONTACT (cr=232291 r=0 w=0 time=1888523 us)
116144 INDEX UNIQUE SCAN S_CONTACT_U2 (cr=116147 r=0 w=0 time=1067857 us)(object id 65967)

50,000,000 is just about what you are using with the pga aggregate target I believe.  try something larger and make sure sort_area_retained_size is set to the *same* value.


and you might find that if you index CREATED and CREATED is NOT NULL:


ops$tkyte@ORA9IR2> create table t1 ( x int primary key, created date NOT NULL, template_flg varchar2(1), y int );
Table created.
 
ops$tkyte@ORA9IR2> create index t1_idx on t1(created);
Index created.
 
ops$tkyte@ORA9IR2> create table t2 ( x int references t1, y int );
Table created.
 
ops$tkyte@ORA9IR2> create index t2_idx on t2(x);
Index created.
 
ops$tkyte@ORA9IR2> create table t3 ( x int references t1, y int );
Table created.
 
ops$tkyte@ORA9IR2> create index t3_idx on t3(x);
Index created.
 
ops$tkyte@ORA9IR2> create table t4 ( x int references t1, y int );
Table created.
 
ops$tkyte@ORA9IR2> create index t4_idx on t4(x);
Index created.
 
ops$tkyte@ORA9IR2> create table t5 ( x int references t1, y int );
Table created.
 
ops$tkyte@ORA9IR2> create index t5_idx on t5(x);
Index created.
 
ops$tkyte@ORA9IR2> set autotrace traceonly explain
ops$tkyte@ORA9IR2> select *
  2    from t1, t2, t3, t4, t5
  3   where t1.x = t2.x(+)
  4     and t1.x = t3.x(+)
  5     and t1.x = t4.x(+)
  6     and t1.x = t5.x(+)
  7     and t1.template_flg <> 'Y'
  8   order by created desc
  9  /
 
Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   NESTED LOOPS (OUTER)
   2    1     NESTED LOOPS (OUTER)
   3    2       NESTED LOOPS (OUTER)
   4    3         NESTED LOOPS (OUTER)
   5    4           TABLE ACCESS (BY INDEX ROWID) OF 'T1'
   6    5             INDEX (FULL SCAN DESCENDING) OF 'T1_IDX' (NON-UNIQUE)
   7    4           TABLE ACCESS (BY INDEX ROWID) OF 'T5'
   8    7             INDEX (RANGE SCAN) OF 'T5_IDX' (NON-UNIQUE)
   9    3         TABLE ACCESS (BY INDEX ROWID) OF 'T4'
  10    9           INDEX (RANGE SCAN) OF 'T4_IDX' (NON-UNIQUE)
  11    2       TABLE ACCESS (BY INDEX ROWID) OF 'T3'
  12   11         INDEX (RANGE SCAN) OF 'T3_IDX' (NON-UNIQUE)
  13    1     TABLE ACCESS (BY INDEX ROWID) OF 'T2'
  14   13       INDEX (RANGE SCAN) OF 'T2_IDX' (NON-UNIQUE)
 
 
 
ops$tkyte@ORA9IR2> set autotrace off


You might find the RBO uses the index to avoid having to get ALL of the rows and then sort as it did in the example above.  That'll return the first 10 rows "asap"  

I forgot to mention in my previous reply that disk fetches went down to 190 from 811, but the elapsed time didn't improve.

We ran into the same situation on our initial upgrade to 9i.

It turned out that we had degree of parallelism (DOP) set on the tables and indexes. With 9i, Oracle deprecated the OPTIMIZER_PERCENT_PARALLEL parameter (actually made it a hidden parameter with _OPTIMIZER_PERCENT_PARALLEL, but set it to 100), which essentially causes the optimizer to favor FTS using PQ.

See my questions to Tom at: </code> http://asktom.oracle.com/pls/ask/f?p=4950:61:12403065903107147593::::P61_ID:1657270217898 <code>

Check the DOP on your tables and index. If it's an OLTP application, make sure you're not getting caught with PQ.

You can use:

select table_name, degree from tabs where degree > 1;
select index_name, degree from ind where degree > 1;

Otherwise, 9i is great! A lot of cool features missing in 8i.

HTH,
-Peter

That was very good. I guess I got trapped in thinking since its driver table you would need all rows of the t15. But it turns out the order by clause and 10 rows is all it cares. Great solution!

Have a great day!

I had pga_aggregate_target set to 250MB, and then increased it to 1GB, with little or no improvement.

I benchmarked values for sort_area_size of 100MB, 200MB, 300MB, 400MB, 500MB, and 250MB, with sort_area_retained_size set to sort_area_size, and settled on an optimum sort_area_size value of 250MB. There is a massive improvement in response for the query, and a drill down from one of the returned records, from 7 minutes, and 4 minutes, to 40 seconds, and 45 seconds respectively.

So, with workarea_size_policy set to manual, and using sort_area_size, a session can use more sort space because if pga_aggregate_target is used, then a session uses only 5% of the pga_aggregate_target. I had pga_aggregate_target set to 1GB, and when I set sort_area_size to 50MB, I noticed about the same performance. 50MB is 5% or 1GB, so this makes sense, unless it was a coincidence.

The test machine I was using had 4GB of memory. Using the 80%-20% rule, Oracle could use 3.2GB. Since the SGA is set to 2.2GB, this leaves about 1GB for sorting. With sort_area_size and sort_area_retained_space set to 250MB, this means only four sessions can be running this large query at the same exact time without the system starting to page and swap, correct?

Once they're done with sorting, they release the sort space, correct?, or do they still have a sort_area_retained_size of 250MB of memory still allocated?

I've read the following paper for more insight on sizing:
</code> http://www.ixora.com.au/newsletter/2000_11.htm <code>

Your example and execution plan of using an index on the created column was really good, and shed a lot of light on what is happening, and how the query may be further tuned. That's the next thing I'll look into. With Siebel, you can't just willy, nilly put an index on the table without using the Siebel object navigator, and I think I read, you have to disable an index and not drop it.

I want to note that that I changed the optimizer_features_enable to 9.2.0 from 8.1.7 and the RBO execution plan remained the same, as was stated in bug 3086748 in metalink.

I want to say that we have been using and upgrading our non-Siebel applications to Oracle9i for the last year or more without any major problems, and have really benefitted using the features of the external tables, undo tablespaces, logical standby, and spfile to name just a few.

I also want to say thanks for your help on this problem. This query has been a thorn in our side so to speak as we learn how to use, and maintain Siebel with an Oracle backend. I have been using AskTom for just under four years, within Oracle and on the outside, and it has been invaluable. AskTom is my first line of defense, and when we get stumped on an Oracle issue, my manager sometimes says, "See what Tom says." -Thanks...

I have the same query running on 9i and 8i.
we are using RBO on both but the query produce different explain plan.
On 9i it takes more than 30 minutes and 2 minutes on 8i.

here is the query (it's based on view of views):

SELECT
0
, natpie
, typensemble1
, ensemble1
, typensemble2
, ensemble2
, typerestitution
, valeurrestitution
, 'C'
, gamme
FROM
(
SELECT
natpie
, typensemble1
, ensemble1
, typensemble2
, ensemble2
, typerestitution
, valeurrestitution
, gamme
FROM V_COMBENSMEMETYPEBYRESTIT
MINUS
SELECT
at93natpie
, at93typensemblecompare
, at93ensemblecompare
, at93typensemblereference
, at93ensemblereference
, at93typegrouperestitution
, at93grouperestitution
, at93gamme
FROM AT93_CNTENSCOM
WHERE at93typecalcul = 'C'
)
;


and the definition of the wiew V_COMBENSMEMETYPEBYRESTIT

select VIEW_NAME,TEXT from dba_views where view_name='V_COMBENSMEMETYPEBYRESTIT';

SELECT
naturepiece.sy01cod
, combens.typeensemble1
, combens.valeurensemble1
, combens.typeensemble2
, combens.valeurensemble2
, 'T'
, 'Total'
, combens.gamme
FROM v_combensmemetype combens
, sy01_param naturepiece
WHERE naturepiece.sy01typ = 'NAT'
UNION ALL
SELECT
naturepiece.sy01cod
, combens.typeensemble1
, combens.valeurensemble1
, combens.typeensemble2
, combens.valeurensemble2
, 'G'
, relationensgfe.gfe
, combens.gamme
FROM v_combensmemetype combens
, v_relationensgfeavecpie relationensgfe
, sy01_param naturepiece
WHERE combens.gamme = relationensgfe.gamme
AND combens.typeensemble1 = relationensgfe.typeensemble
AND combens.valeurensemble1 = relationensgfe.valeurensemble
AND naturepiece.sy01typ = 'NAT'
UNION ALL
SELECT
naturepiece.sy01cod
, combens.typeensemble1
, combens.valeurensemble1
, combens.typeensemble2
, combens.valeurensemble2
, 'D'
, dir.direction
, combens.gamme
FROM v_combensmemetype combens
, v_listedirection dir
, sy01_param naturepiece
WHERE combens.gamme = dir.gamme
AND naturepiece.sy01typ = 'NAT';



v_combensmemetype and v_listedirection are again views.

following from previous:


here is the 8i explain plan:

0 SELECT STATEMENT Optimizer=RULE
1 0 VIEW
2 1 MINUS
3 2 SORT (UNIQUE)
4 3 VIEW OF 'V_COMBENSMEMETYPEBYRESTIT'
5 4 UNION-ALL
6 5 MERGE JOIN
7 6 SORT (JOIN)
8 7 NESTED LOOPS
9 8 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
10 8 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
11 6 SORT (JOIN)
12 11 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
13 5 MERGE JOIN
14 13 SORT (JOIN)
15 14 MERGE JOIN
16 15 SORT (JOIN)
17 16 NESTED LOOPS
18 17 VIEW OF 'V_RELATIONENSGFEAVECPIE'
19 18 SORT (UNIQUE)
20 19 MERGE JOIN
21 20 SORT (JOIN)
22 21 VIEW OF 'V_RELATIONFAMGFE'
23 22 SORT (UNIQUE)
24 23 UNION-ALL
25 24 NESTED LOOPS
26 25 TABLE ACCESS (FULL) OF 'LO04_DECOUP'
27 25 INDEX (RANGE SCAN) OF 'UK_DECOUP' (UNIQUE)
28 24 TABLE ACCESS (FULL) OF 'LO04_DECOUP'
29 20 SORT (JOIN)
30 29 VIEW OF 'V_RELATIONENSFAMAVECPIE'
31 30 SORT (UNIQUE)
32 31 UNION-ALL
33 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
34 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
35 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
36 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
37 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
38 17 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
39 15 SORT (JOIN)
40 39 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
41 13 SORT (JOIN)
42 41 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
43 5 MERGE JOIN
44 43 SORT (JOIN)
45 44 MERGE JOIN
46 45 SORT (JOIN)
47 46 NESTED LOOPS
48 47 VIEW OF 'V_LISTEDIRECTION'
49 48 SORT (UNIQUE)
50 49 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
51 47 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
52 45 SORT (JOIN)
53 52 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
54 43 SORT (JOIN)
55 54 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
56 2 SORT (UNIQUE)
57 56 TABLE ACCESS (FULL) OF 'AT93_CNTENSCOM'


and here is the 9i explain plan:

0 SELECT STATEMENT Optimizer=RULE
1 0 VIEW
2 1 MINUS
3 2 SORT (UNIQUE)
4 3 VIEW OF 'V_COMBENSMEMETYPEBYRESTIT'
5 4 UNION-ALL
6 5 MERGE JOIN
7 6 SORT (JOIN)
8 7 NESTED LOOPS
9 8 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
10 8 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
11 6 SORT (JOIN)
12 11 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
13 5 VIEW
14 13 SORT (UNIQUE)
15 14 MERGE JOIN
16 15 MERGE JOIN
17 16 SORT (JOIN)
18 17 MERGE JOIN
19 18 SORT (JOIN)
20 19 NESTED LOOPS
21 20 VIEW OF 'V_RELATIONFAMGFE'
22 21 SORT (UNIQUE)
23 22 UNION-ALL
24 23 NESTED LOOPS
25 24 TABLE ACCESS (FULL) OF 'LO04_DECOUP'
26 24 INDEX (RANGE SCAN) OF 'UK_DECOUP' (UNIQUE)
27 23 TABLE ACCESS (FULL) OF 'LO04_DECOUP'
28 20 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
29 18 SORT (JOIN)
30 29 VIEW OF 'V_RELATIONENSFAMAVECPIE'
31 30 SORT (UNIQUE)
32 31 UNION-ALL
33 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
34 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
35 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
36 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
37 32 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
38 16 SORT (JOIN)
39 38 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
40 15 SORT (JOIN)
41 40 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
42 5 VIEW
43 42 SORT (UNIQUE)
44 43 MERGE JOIN
45 44 SORT (JOIN)
46 45 MERGE JOIN
47 46 SORT (JOIN)
48 47 NESTED LOOPS
49 48 TABLE ACCESS (FULL) OF 'AT92_PIENSCOM'
50 48 INDEX (RANGE SCAN) OF 'IDX1_SY01' (NON-UNIQUE)
51 46 SORT (JOIN)
52 51 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
53 44 SORT (JOIN)
54 53 TABLE ACCESS (FULL) OF 'AT98_ENSAVECPIE'
55 2 SORT (UNIQUE)
56 55 TABLE ACCESS (FULL) OF 'AT93_CNTENSCOM'



I can't figure ou why they are different... Do you have any ideas?


Thanks

We recently migrated from Oracle 8i(8.1.7.4.5) to ORACLE 9i(9.2.0.6) with oraoledb 9204. Our application run good on 8i. We have big problems of performance after migration. I tried several things, but no sucess.
During test of charge, our application do a lot of updates of a table named xml_persist. the script of this table is :
CREATE TABLE XML_PERSIST
(
SESSION_ID VARCHAR2(36 BYTE) NOT NULL,
CREATION_DT DATE DEFAULT sysdate,
UPDATE_DT DATE DEFAULT sysdate,
XML_TYPE VARCHAR2(12 BYTE) NOT NULL,
XML_STREAM CLOB
)
TABLESPACE EDECLIC_DATA
PCTUSED 40
PCTFREE 10
INITRANS 1
MAXTRANS 255
STORAGE (
INITIAL 256K
NEXT 128K
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
BUFFER_POOL KEEP
)
NOLOGGING
LOB (XML_STREAM) STORE AS LOB_DATA_XML_PERSIST
( TABLESPACE EDECLIC_LOBS
ENABLE STORAGE IN ROW
CHUNK 8192
PCTVERSION 10
CACHE
STORAGE (
INITIAL 256K
NEXT 1M
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
BUFFER_POOL KEEP
)
)
CACHE
NOPARALLEL;


CREATE INDEX SESSION_XML_PERSIST_FK ON XML_PERSIST
(SESSION_ID)
NOLOGGING
TABLESPACE EDECLIC_INDEX
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 256K
NEXT 128K
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
BUFFER_POOL DEFAULT
)
NOPARALLEL;


CREATE UNIQUE INDEX XML_PERSIST_PK ON XML_PERSIST
(SESSION_ID, XML_TYPE)
NOLOGGING
TABLESPACE EDECLIC_INDEX
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 256K
NEXT 128K
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
BUFFER_POOL DEFAULT
)
NOPARALLEL;

Supose query1 is the name of the the query with problems exécution = BEGIN OSTA_CHARGE.pSetXMLPersistType(:1,:2,:3,:4); END;
I notice these things (what changed in 9i):
- The execution plan of the query1 has not changed between 8i and 9i
- Query1 use a lot of physical reads.
- The physical reads seems to be used on the temporary tbs.
- TKprof show that wait time is due to recursive calls
- I tried without success:
- optimizer_features_enable = 8.1.7
- WORKAREA_SIZE_POLICY = MAnual instead of auto
- cursor_sharin=force instead of similar
- ADD RAM (from 384M to 768M)
- resize pga_agregate_target from 100Mo to 300Mo
- resize db_keep_size from 65M to 115Mo
- upgrade from Oracle server 9205 to 9206 (the client is still in 9205).

Perfmon output : it shows :
- cpu waits for disk
- A lot of swap with fault page 600page/s in average.
- usual 480Mo of available memory


Output of statspack :
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
direct path read (lob) 125,094 1,031 34.21
CPU time 1,023 33.96
log file sync 53,212 489 16.24
direct path write 51,663 270 8.97
SQL*Net more data to client 531,544 135 4.48

SQL ordered by Reads for DB: EDECP9I Instance: edecp9i Snaps: 6 -7
-> End Disk Reads Threshold: 1000

CPU Elapsd
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
120,993 49,909 2.4 92.1 253.16 1304.46 1245406446
Module: inetinfo.exe
BEGIN OSTA_CHARGE.pSetXMLPersistType(:1,:2,:3,:4); END;

119,329 49,909 2.4 90.8 127.99 1121.42 2684712530
Module: inetinfo.exe
UPDATE XML_PERSIST SET XML_STREAM = :B3 , UPDATE_DT = SYSDATE WH
ERE SESSION_ID = :B2 AND XML_TYPE = :B1 RETURNING ROWID INTO :B0


1,660 1,660 1.0 1.3 2.46 28.69 1458190275
Module: inetinfo.exe
INSERT INTO XML_PERSIST (SESSION_ID, XML_TYPE, XML_STREAM) VALUE
S (:B3 , :B2 , :B1 )

Tablespace
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
EDECLIC_TEMP_CHARGE
120,995 29 8.4 1.0 51,705 12 0 0.0
EDECLIC_LOBS_CHARGE
21 0 66.7 1.0 19,888 5 67 4.0
UNDOTBS1
9 0 75.6 1.0 16,236 4 6 8.3
EDECLIC_DATA_CHARGE
4,130 1 15.5 2.4 3,028 1 10 8.0
EDECLIC_INDEX_CHARGE
10 0 68.0 1.0 927 0 1 20.0
SYSTEM
83 0 19.2 4.5 153 0 0 0.0

Buffer Pool Statistics for DB: EDECP9I Instance: edecp9i Snaps: 6 -7
-> Standard block size Pools D: default, K: keep, R: recycle
-> Default Pools for other block sizes: 2k, 4k, 8k, 16k, 32k

Free Write Buffer
Number of Cache Buffer Physical Physical Buffer Complete Busy
P Buffers Hit % Gets Reads Writes Waits Waits Waits
--- ---------- ----- ----------- ----------- ---------- ------- -------- ------
D 7,007 100.0 4,279,338 474 17,766 0 0 7
K 15,015 100.0 2,396,370 3 22,545 0 0 77
-------------------------------------------------------------

Dictionary Cache Stats for DB: EDECP9I Instance: edecp9i Snaps: 6 -7
->"Pct Misses" should be very low (< 2% in most cases)
->"Cache Usage" is the number of cache entries being used
->"Pct SGA" is the ratio of usage to allocated size for that cache

Get Pct Scan Pct Mod Final
Cache Requests Miss Reqs Miss Reqs Usage
------------------------- ------------ ------ ------- ----- -------- ----------
dc_histogram_defs 270 7.8 0 0 398
dc_object_ids 93,483 0.0 0 0 442
dc_objects 622 14.8 0 0 656
dc_profiles 171 0.0 0 0 1
dc_rollback_segments 5,364 0.0 0 0 15
dc_segments 35,034 0.1 0 50 250

init.ora Parameters for DB: EDECP9I Instance: edecp9i Snaps: 6 -7

End value
Parameter Name Begin value (if different)
----------------------------- --------------------------------- --------------
background_dump_dest D:\Ora9i_1\admin\EDECP9i\bdump
compatible 9.2.0.0.0
control_files F:\Ora9i_2\database\EDECP9i\contr
core_dump_dest D:\Ora9i_1\admin\EDECP9i\cdump
cursor_sharing FORCE
db_block_size 8192
db_cache_size 58720256
db_domain
db_file_multiblock_read_count 8
db_files 80
db_keep_cache_size 125829120
db_name EDECP9i
fast_start_mttr_target 0
hash_join_enabled TRUE
instance_name EDECP9i
java_pool_size 8388608
job_queue_processes 0
large_pool_size 8388608
log_buffer 1048576
max_dump_file_size unlimited
max_enabled_roles 30
open_cursors 300
parallel_max_servers 5
pga_aggregate_target 314572800
processes 150
query_rewrite_enabled FALSE
remote_login_passwordfile EXCLUSIVE
service_names EDECP9i
session_cached_cursors 100
shared_pool_size 33554432
sql_trace TRUE
star_transformation_enabled FALSE
timed_statistics TRUE
undo_management AUTO
undo_retention 300
undo_tablespace UNDOTBS1
user_dump_dest D:\Ora9i_1\admin\EDECP9i\udump
workarea_size_policy AUTO
-------------------------------------------------------------

End of Report

Tkprof output :
------------------
Trace file: res.trc
Sort options: exedsk
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

UPDATE XML_PERSIST SET XML_STREAM = :B3 , UPDATE_DT = SYSDATE
WHERE
SESSION_ID = :B2 AND XML_TYPE = :B1 RETURNING ROWID INTO :B0


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 174 0.32 0.48 0 0 0 0
Execute 49908 129.60 1192.19 119334 637220 1351150 48248
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 50082 129.92 1192.68 119334 637220 1351150 48248

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 27 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
560 UPDATE
560 INDEX UNIQUE SCAN XML_PERSIST_PK (object id 6567)

********************************************************************************

INSERT INTO XML_PERSIST (SESSION_ID, XML_TYPE, XML_STREAM)
VALUES
(:B3 , :B2 , :B1 )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 145 0.01 0.02 0 0 0 0
Execute 1660 2.26 30.18 1684 5576 21749 1660
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1805 2.27 30.21 1684 5576 21749 1660

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 27 (recursive depth: 1)
********************************************************************************

insert into OSTA_CHARGE.XML_TRANSAC(SESSION_ID, TRANSAC_LEVEL, TRANSAC_NAME,
XML_TYPE, XML_STREAM) select SESSION_ID, :1, :2, XML_TYPE, XML_STREAM from
OSTA_CHARGE.XML_PERSIST where SESSION_ID = :3


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1320 0.13 0.17 0 0 0 0
Execute 1320 9.87 12.95 203 74018 111584 10060
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2640 10.00 13.12 203 74018 111584 10060
....
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 144613 37.82 47.70 0 257 0 0
Execute 143889 181.89 230.11 231 203950 197301 132838
Fetch 28065 85.46 115.02 644 2708919 0 230903
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 316567 305.17 392.84 875 2913126 197301 363741

Misses in library cache during parse: 47


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1810 1.11 1.42 5 64 0 0
Execute 163687 169.49 1268.89 121019 642913 1423019 49998
Fetch 63308 9.88 11.69 36 195577 0 59522
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 228805 180.48 1282.01 121060 838554 1423019 109520

Misses in library cache during parse: 22

145281 user SQL statements in session.
1142 internal SQL statements in session.
146423 SQL statements in session.
********************************************************************************
Trace file: res.trc
Trace file compatibility: 9.02.00
Sort options: exedsk
176 sessions in tracefile.
12944047 user SQL statements in trace file.
118815 internal SQL statements in trace file.
146423 SQL statements in trace file.
108 unique SQL statements in trace file.
1417640 lines in trace file.


Can you give me a diagnostic please. Is the problem related to :
- the use of the buffer KEEP
- Optimiser problem or some init.ora parameter.
- Bugs ?
thanks a lot.

This is an interesting thread......one should see the exact opposite. Things should run significantly faster in 9i, it's been our experience and I believe I saw Tom prove it somewhere with a test case on this site (it might have been 9i vs 10g).

Continuation of the case above.
I compared all with 8i case, except the version of the database and oledb, all things are same.

Our 9i problem was in a call of a procedure pSetXMLPersistType (this procedure doesn't generate any problem in 8i):
Physical Reads Executions Reads per Exec %Total Time (s) Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
120,993 49,909 2.4 92.1 253.16 1304.46 1245406446
Module: inetinfo.exe
BEGIN OSTA_CHARGE.pSetXMLPersistType(:1,:2,:3,:4); END;

119,329 49,909 2.4 90.8 127.99 1121.42 2684712530
Module: inetinfo.exe
UPDATE XML_PERSIST SET XML_STREAM = :B3 , UPDATE_DT = SYSDATE WH
ERE SESSION_ID = :B2 AND XML_TYPE = :B1 RETURNING ROWID INTO :B0

the code of the procedure is :
CREATE OR REPLACE Procedure pSetXMLPersistType (Session_id_in in Varchar2 , Persist_Type in Varchar2, persist_lob in clob, result out varchar2) IS
row_id rowid;
BEGIN
update XML_PERSIST SET XML_STREAM = persist_lob, UPDATE_DT = sysdate
where SESSION_ID = Session_id_in and XML_TYPE = Persist_Type
RETURNING ROWID INTO row_id ;
if row_id is null then
INSERT INTO XML_PERSIST (SESSION_ID, XML_TYPE, XML_STREAM)
VALUES (Session_id_in , Persist_Type, persist_lob);
result:='INSERTED';
else
result:='UPDATED';
end if;
commit;
EXCEPTION
WHEN NO_DATA_FOUND THEN
INSERT INTO XML_PERSIST (SESSION_ID, XML_TYPE, XML_STREAM)
VALUES (Session_id_in , Persist_Type, persist_lob);
result:='INSERTED EXCEPT';
return;
WHEN OTHERS THEN
result:='OTHERS';
return;
END;
/

the call of this procedure cause a lot physical reads, big differences between cpu and elapsed, and waits on 'direct path read (lob)' :
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
direct path read (lob) 125,094 1,031 34.21
CPU time 1,023 33.96
log file sync 53,212 489 16.24
direct path write 51,663 270 8.97
SQL*Net more data to client 531,544 135 4.48

But in 8i, i have no problem and statspack shows some thing like this:
Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
-------------------------------------------- ------------ ------------ -------
log file sync 112,780 52,786 39.82
db file parallel write 5,611 30,647 23.12
SQL*Net more data to client 1,091,753 18,432 13.90
log file parallel write 104,741 15,224 11.48
direct path read (lob) 4,745 4,775 3.60

And the procedure call is fast :
BEGIN OSTA_CHARGE.pSetXMLPersistType(:1, :2, :3, :4); END;


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 30000 19.12 19.73 0 0 0 0
Execute 30000 348.81 365.85 2 90088 510140 30000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 60000 367.93 385.58 2 90088 510140 30000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 74

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 30000 0.01 0.25
log file sync 30028 0.50 82.14
SQL*Net message from client 30000 70.37 8021.44
latch free 3 0.20 0.20

To solve the problem, now i don't use the procedure.
Have you got any adea, why this procedure doesn't scale in 9i ?
any propositions ?

Hi Top,

I have database on version 9i 9.2.0.4, on which optimizer_features_enable = 8.1.7

Which are the main features CBO will not use ?

Thanks

Dilip

Tom could you discuss the optimizer_features_enable parameter briefly. Is it a good idea to set this to a previous version if you notice a performance problem when migrating? Can it also be harmful? In what ways? Thanks.

excerpt from Effective Oracle by Design, chapter on CBO talking about this:

<quote>
Set OPTIMIZER_FEATURES_ENABLE to Control Feature Choices

The OPTIMIZER_FEATURES_ENABLE init.ora setting controls which features and functions the optimizer will consider when optimizing your query. It is designed to allow you to upgrade, but to keep the behavior of the optimizer as it was in the prior release, while you test. It does not guarantee the same plans will result in the new release as those that were chosen in the old release; the optimizer costing will change from release to release. However, it will prevent new functionality from being used.

For example, if you set OPTIMIZER_FEATURES_ENABLE to version 8.1.4, you will discover that your SQL that runs in PL/SQL (user-written recursive SQL) does not use the SESSION optimizer mode, but always uses CHOOSE. It was version 8.1.6 that added the enhancement whereby user-written recursive SQL would inherit the optimizer goal from the session. This sounds like a nice feature, but if you were not prepared, it could have dramatic effects on your query execution. 
Normally, SQL in PL/SQL was optimized using the RBO or an ALL_ROWS approach. The thought behind ALL_ROWS type optimization was that the caller of the PL/SQL routine did not get the control back until the last row had been processed in the PL/SQL routine. Hence, an optimization goal of FIRST_ROWS would not make sense in a stored procedure. Who cares if the stored procedure gets the first row from a result set instantly if it takes 5 hours to get the last row, especially when the alternative is to wait 10 seconds to get the first row and get the last row in 20 seconds. The end user waiting for the procedure to finish is the goal.

Consider this example in Oracle9i Release 2:
ops$tkyte@ORA920> create table t
  2  as
  3  select *
  4    from all_objects;
Table created.

ops$tkyte@ORA920> create or replace function get_row_cnt return number
  2  as
  3          l_cnt   number;
  4  begin
  5          select count(*)
  6            into l_cnt
  7        from t;
  8          return l_cnt;
  9  end;
 10  /
Function created.

ops$tkyte@ORA920> show parameter optimizer_features

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----------
optimizer_features_enable            string      9.2.0

ops$tkyte@ORA920> alter session set sql_trace=true;
Session altered.

ops$tkyte@ORA920> alter session set optimizer_goal=first_rows;
Session altered.

ops$tkyte@ORA920> exec dbms_output.put_line( get_row_cnt );
29578

PL/SQL procedure successfully completed.
Now, the TKPROF utility shows us the following:
SELECT count(*) from t
...
Misses in library cache during parse: 1
Optimizer goal: FIRST_ROWS
Parsing user id: 241     (recursive depth: 1)

That query was optimized using our session settings. Well, that could be disastrous for an application upgrade from version 8.1.5 to 8.1.6 (or above), if you frequently set the optimizer goal to FIRST_ROWS in your session, but you counted on the CHOOSE method for your stored procedures, to let them use the RBO or CBO as they saw fit. So, you could set OPTIMIZER_FEATURES_ENABLE as follows:

ops$tkyte@ORA920> alter system 
  2 set optimizer_features_enable = '8.1.5' scope = spfile;
System altered.
Then restart the database, running the same example:
SELECT count(*)   from t
...
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 241     (recursive depth: 1)

This shows that we have reverted to the old behavior. 

The Oracle Database Reference Guide includes a table showing what behavior you can expect as far as query optimization goes with various settings of the OPTIMIZER_FEATURES_ENABLE parameter. I recommend that you use it only as a temporary stopgap after an upgrade, to revert to old behavior while you fix the underlying problem itself. Ultimately, you would like this parameter to be set to your current database version in order to take advantage of the new features and functions available.
</quote>

 

Very nice. Perhaps we'll give it a try. One more question. What direction would you steer me in if I told you that certain large queries were performing terribly in 9i and eating up insane amounts of temp tablespace quickly. About 10 gig in a minute. Other than tracing, snapshots etc, is there anything you suspect or reccommend to look at for that kind of a problem, or could too many factors cause something like that?

Please disregard the last post.

Is this phenomenon when upgrading considered a bug?

Maybe I don't understand well enough why this sort of thing happens. I would think the newer software would know how to get the best plan for a query. In your book you explore the possibility of changing the optimizer mode from session to session, but I don't see that as a reasonable explanation for application queries running inefficiently.

"Optimizer costing will change from release to release" I guess is what I don't understand. If a query runs great in 8.1.7 by using a full table scan, and you move to 9i with the same data, why would 9i decide that's not a good plan? Maybe for whatever reason 9i assigns a higher costs to that full table scan?

Well, just for the record, we noticed the an improvement in places too...:)

In our case this might be trickier than you might think. Our problems are occurring with Crystal Report queries that I think you cannot edit. I think it's a drag and drop kind of deal and sql is generated by that and sent to the database (More a CR problem than Oracle no doubt).

You said you can change the plans, how? You mean be changing the statements? Hints?

Hey alex, I find it helpful to use views for crystal reports. This allows you to use hints, modify sql, and do the other things cr does not allow you to do. Saves the need to recompile...etc.

Hi Tom,
I strongly feel that "asktom" is the encyclopedia of Oracle,always find the instant answers to most of my doubts. I love the way you deals with a problem, and the way explains it with simple examples.Today I am here with a question related to 8i and 9i optimizer plan differences.

Q1. I have a query for which is executes in around 3 sec with 8i optimizer but 9i optimizer is using different plan and is taking about 377 sec. 9i optimizer is fetching more rows than what i have in the table during nested loop(underlined with ^^^^^^^ in 9i plan below). ME_BR_RPT_RECON_MAIN_SUB:ptn_x is having only 41983 rows but plan shows that index range scan gives 5373824 rows. Could you please help me to find out the secret behind this? 5373824/41983 = 128 rows --> this is equal to the #of rows in the other table taking part in the join(NL). Why the optimizer trying to use NESTED LOOP instead of HASH JOIN as in 8i optimizer?


8i plan
=======
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 3.36 3.23 170792 209415 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 3.37 3.24 170792 209415 0 0

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 45 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
0 SEQUENCE
0 HASH JOIN
0 VIEW
0 MINUS
41901 SORT UNIQUE
41901 TABLE ACCESS BY INDEX ROWID ME_BR_RPT_RECON_SUB_TEMP
41901 INDEX RANGE SCAN IDX1_ME_BR_RPT_RECON_SUB_TEMP (object id 136571)
41901 SORT UNIQUE
41901 HASH JOIN
128 PARTITION RANGE SINGLE PARTITION: KEY KEY
128 INDEX FAST FULL SCAN PK_ME_BR_RPT_PARAM PARTITION: KEY KEY (object id 120708)
41983 PARTITION RANGE SINGLE PARTITION: KEY KEY
41983 TABLE ACCESS FULL ME_BR_RPT_RECON_MAIN_SUB PARTITION: KEY KEY
0 PARTITION RANGE SINGLE PARTITION: KEY KEY
0 INDEX FAST FULL SCAN PK_ME_BR_RPT_REL_MAIN_SUB PARTITION: KEY KEY (object id 120504)


9i plan
=======
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.05 0 6 0 0
Execute 1 377.38 441.96 9368590 10669312 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 377.39 442.02 9368590 10669318 0 0

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 45 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
0 SEQUENCE
0 HASH JOIN
0 VIEW
0 MINUS
41901 SORT UNIQUE
41901 TABLE ACCESS BY INDEX ROWID ME_BR_RPT_RECON_SUB_TEMP
41901 INDEX RANGE SCAN IDX1_ME_BR_RPT_RECON_SUB_TEMP (object id 136571)
41901 SORT UNIQUE
41901 TABLE ACCESS BY LOCAL INDEX ROWID ME_BR_RPT_RECON_MAIN_SUB
5373953 NESTED LOOPS
128 PARTITION RANGE SINGLE PARTITION: KEY KEY
128 INDEX RANGE SCAN PK_ME_BR_RPT_PARAM PARTITION: KEY KEY (object id 120708)
5373824 PARTITION RANGE SINGLE PARTITION: KEY KEY
^^^^^^^
5373824 INDEX RANGE SCAN IDX1_ME_BR_RPT_RECON_MAIN_SUB PARTITION: KEY KEY (object id 138892)
0 PARTITION RANGE SINGLE PARTITION: KEY KEY
0 INDEX FAST FULL SCAN PK_ME_BR_RPT_REL_MAIN_SUB PARTITION: KEY KEY (object id 120504)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 9368590 0.19 168.43
latch free 901 0.07 1.93


Thanks

Hi Tom,
Here are the plans in 8i Optimizer and 9i Optimizer ( readability of the Query plan on this page is affected due to the line size limitations of this webpage) 
Please be informed that both 8i and 9i optimizers plans are  taken in Oracle 9.2.0.5 environment including the previous question.Every time I switch the Optimizer mode I am analyzing all the tables and Indexes with following 
command.
EXECUTE dbms_stats.gather_table_stats(ownname => 'TAB_OWNER',tabname => 
'TABLE_X',partname => NULL, estimate_percent =>DBMS_STATS.AUTO_SAMPLE_SIZE, 
block_sample => FALSE, method_opt => 'FOR ALL COLUMNS SIZE 1',DEGREE => NULL, 
granularity => 'DEFAULT',CASCADE => TRUE ,stattab => NULL,statid => NULL,statown => NULL);

Explain plan with 8i Optimizer 
==============================

SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------

-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        |  Name                          | Rows  | Bytes | Cost  | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                 |                                |     1 |   250 |   267 |       |       |
|   1 |  SEQUENCE                        | SQ_RC_SEQ_NO                   |       |       |       |       |       |
|   2 |   HASH JOIN                      |                                |     1 |   250 |   267 |       |       |
|   3 |    VIEW                          |                                |     1 |   201 |   265 |       |       |
|   4 |     MINUS                        |                                |       |       |       |       |       |
|   5 |      SORT UNIQUE                 |                                |     1 |   162 |       |       |       |
|   6 |       TABLE ACCESS BY INDEX ROWID| ME_BR_RPT_RECON_SUB_TEMP       |     1 |   162 |     1 |       |       |
|   7 |        INDEX RANGE SCAN          | IDX1_ME_BR_RPT_RECON_SUB_TEMP  |     1 |       |       |       |       |
|   8 |      SORT UNIQUE                 |                                |     1 |    86 |       |       |       |
|   9 |       HASH JOIN                  |                                |     1 |    86 |   248 |       |       |
|  10 |        PARTITION RANGE SINGLE    |                                |       |       |       |   KEY |   KEY |
|  11 |         INDEX FAST FULL SCAN     | PK_ME_BR_RPT_PARAM             |     1 |    39 |     1 |   KEY |   KEY |
|  12 |        PARTITION RANGE SINGLE    |                                |       |       |       |   KEY |   KEY |
|  13 |         TABLE ACCESS FULL        | ME_BR_RPT_RECON_MAIN_SUB       |   113K|  5208K|   246 |   KEY |   KEY |
|  14 |    PARTITION RANGE SINGLE        |                                |       |       |       |   KEY |   KEY |
|  15 |     INDEX FAST FULL SCAN         | PK_ME_BR_RPT_REL_MAIN_SUB      |  1588 | 77812 |     1 |   KEY |   KEY |
-------------------------------------------------------------------------------------------------------------------

Note: cpu costing is off, PLAN_TABLE' is old version

23 rows selected.



Explain plan with 9i Optimizer 
==============================

SQL> select * from table(DBMS_XPLAN.DISPLAY);

-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        |  Name                          | Rows  | Bytes | Cost  | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                 |                                |     1 |   259 |  8857 |       |       |
|   1 |  SEQUENCE                        | SQ_RC_SEQ_NO                   |       |       |       |       |       |
|*  2 |   HASH JOIN                      |                                |     1 |   259 |  8857 |       |       |
|   3 |    VIEW                          |                                |     1 |   201 |  8854 |       |       |
|   4 |     MINUS                        |                                |       |       |       |       |       |
|   5 |      SORT UNIQUE                 |                                |     1 |   162 |       |       |       |
|   6 |       TABLE ACCESS BY INDEX ROWID| ME_BR_RPT_RECON_SUB_TEMP       |     1 |   162 |     1 |       |       |
|*  7 |        INDEX RANGE SCAN          | IDX1_ME_BR_RPT_RECON_SUB_TEMP  |     1 |       |       |       |       |
|   8 |      SORT UNIQUE                 |                                |    73 |  6643 |       |       |       |
|*  9 |       HASH JOIN                  |                                |    73 |  6643 |  8836 |       |       |
|  10 |        PARTITION RANGE SINGLE    |                                |       |       |       |   KEY |   KEY |
|* 11 |         INDEX FAST FULL SCAN     | PK_ME_BR_RPT_PARAM             |     2 |    88 |     2 |   KEY |   KEY |
|  12 |        PARTITION RANGE SINGLE    |                                |       |       |       |   KEY |   KEY |
|* 13 |         TABLE ACCESS FULL        | ME_BR_RPT_RECON_MAIN_SUB       |   170K|  7829K|  8833 |   KEY |   KEY |
|  14 |    PARTITION RANGE SINGLE        |                                |       |       |       |   KEY |   KEY |
|* 15 |     INDEX FAST FULL SCAN         | PK_ME_BR_RPT_REL_MAIN_SUB      |  1459 | 84622 |     2 |   KEY |   KEY |
-------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("A"."REPORT_NAME"="B"."SUB_REPORT_NAME" AND "A"."REPORT_ROW"="B"."SUB_REPORT_ROW" AND
              "A"."REPORT_COL"="B"."SUB_REPORT_COL")
   7 - access("ME_BR_RPT_RECON_SUB_TEMP"."BR_CODE"=:Z AND "ME_BR_RPT_RECON_SUB_TEMP"."VERSION_DATE"=:Z AND
              "ME_BR_RPT_RECON_SUB_TEMP"."REPORT_TYPE"=:Z)
   9 - access("ME_BR_RPT_PARAM"."REPORT_NAME"="ME_BR_RPT_RECON_MAIN_SUB"."SUB_REPORT_NAME")
  11 - filter("ME_BR_RPT_PARAM"."BR_CODE"=:Z AND "ME_BR_RPT_PARAM"."VERSION_DATE"=TO_DATE('9999-12-31 00:00:00',
              'yyyy-mm-dd hh24:mi:ss') AND "ME_BR_RPT_PARAM"."REPORT_TYPE"=:Z AND "ME_BR_RPT_PARAM"."REMARKS" LIKE 'MAIN SUB%'
              AND "ME_BR_RPT_PARAM"."USER_ID"=:Z)
  13 - filter("ME_BR_RPT_RECON_MAIN_SUB"."BR_CODE"=:Z AND "ME_BR_RPT_RECON_MAIN_SUB"."VERSION_DATE"=:Z AND
              "ME_BR_RPT_RECON_MAIN_SUB"."REPORT_TYPE"=:Z)
  15 - filter("B"."BR_CODE"=:Z AND "B"."VERSION_DATE"=:Z AND "B"."REPORT_TYPE"=:Z)

Note: cpu costing is off

Thanks
  

Hi Tom,
Here is the autotrace of the Query with bind variables replaced with literals. There is a global temporary table involved in the Query as first part of the set operation (Minus), So statistics may not reflect the actual values as in the tkprof output.

Elapsed: 00:05:08.63

Execution Plan
----------------------------------------------------------
   0      INSERT STATEMENT Optimizer=CHOOSE (Cost=24 Card=1 Bytes=259)
   1    0   SEQUENCE OF 'SQ_RC_SEQ_NO'
   2    1     NESTED LOOPS (Cost=24 Card=1 Bytes=259)
   3    2       VIEW (Cost=22 Card=1 Bytes=201)
   4    3         MINUS
   5    4           SORT (UNIQUE)
   6    5             TABLE ACCESS (BY INDEX ROWID) OF 'ME_BR_RPT_RECO
          N_SUB_TEMP' (Cost=1 Card=1 Bytes=162)

   7    6               INDEX (RANGE SCAN) OF 'IDX1_ME_BR_RPT_RECON_SU
          B_TEMP' (NON-UNIQUE)

   8    4           SORT (UNIQUE)
   9    8             TABLE ACCESS (BY LOCAL INDEX ROWID) OF 'ME_BR_RP
          T_RECON_MAIN_SUB' (Cost=4 Card=1 Bytes=95)

  10    9               NESTED LOOPS (Cost=5 Card=1 Bytes=181)
  11   10                 INDEX (RANGE SCAN) OF 'PK_ME_BR_RPT_PARAM' (
          UNIQUE) (Cost=1 Card=1 Bytes=86)

  12   10                 INDEX (RANGE SCAN) OF 'IDX1_ME_BR_RPT_RECON_
          MAIN_SUB' (NON-UNIQUE) (Cost=3 Card=1)

  13    2       INDEX (RANGE SCAN) OF 'PK_ME_BR_RPT_REL_MAIN_SUB' (UNI
          QUE) (Cost=2 Card=1 Bytes=58)





Statistics
----------------------------------------------------------
          6  recursive calls
          0  db block gets
   10722968  consistent gets
    9688095  physical reads
          0  redo size
        796  bytes sent via SQL*Net to client
       2863  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
          0  rows processed

SQL>

Thanks 

I know that upgrading version of Oracle can result in poor performing queries because of how the costs are evaluated differently. But is the same true for patches? Will applying a patch have any side effects that you know of? Do you ever get questions like "I applied patch xyz and now things run slow"? If so, I was wondering what the top offenders are. Thanks.

Hi Tom,
This time I got some realistic statistics and cardinality values in the autotrace, except in the global temp table.
I analyzed one of the tables in the query (sub query) as the process is populating the data (128 rows) during the batch job and deleting at the end of the job.

Execution Plan
----------------------------------------------------------
0 INSERT STATEMENT Optimizer=CHOOSE (Cost=4280 Card=1 Bytes=25
9)

1 0 SEQUENCE OF 'SQ_RC_SEQ_NO'
2 1 HASH JOIN (Cost=4280 Card=1 Bytes=259)
3 2 VIEW (Cost=4250 Card=1 Bytes=201)
4 3 MINUS
5 4 SORT (UNIQUE)
6 5 TABLE ACCESS (BY INDEX ROWID) OF 'ME_BR_RPT_RECO
N_SUB_TEMP' (Cost=1 Card=1 Bytes=162)

7 6 INDEX (RANGE SCAN) OF 'IDX1_ME_BR_RPT_RECON_SU
B_TEMP' (NON-UNIQUE)

8 4 SORT (UNIQUE)
9 8 TABLE ACCESS (BY LOCAL INDEX ROWID) OF 'ME_BR_RP
T_RECON_MAIN_SUB' (Cost=4216 Card=776 Bytes=73720)

10 9 NESTED LOOPS (Cost=4218 Card=388 Bytes=54708)
11 10 INDEX (RANGE SCAN) OF 'PK_ME_BR_RPT_PARAM' (
UNIQUE) (Cost=2 Card=1 Bytes=46)

12 10 INDEX (RANGE SCAN) OF 'PK_ME_BR_RPT_RECON_MA
IN_SUB' (UNIQUE) (Cost=715 Card=41983)

13 2 INDEX (FAST FULL SCAN) OF 'PK_ME_BR_RPT_REL_MAIN_SUB'
(UNIQUE) (Cost=29 Card=1455 Bytes=84390)





Statistics
----------------------------------------------------------
6 recursive calls
0 db block gets
5442328 consistent gets
5442222 physical reads
0 redo size
800 bytes sent via SQL*Net to client
2876 bytes received via SQL*Net from client
3 SQL*Net roundtrips to/from client
3 sorts (memory)
0 sorts (disk)
0 rows processed


Thanks.

Hi Tom,

<<<<<<<<<<<<<< Extract from your prev followup:>>>>>>>>>>>>

when the optimizer gets the wrong card= values, you get the wrong plan typically.
we need to find the "problem" cardinality and determine "why"

<<<<<<<<<<<<<< Extract from your prev followup:>>>>>>>>>>>>

Query is still doing worst, I request for your advice to understand why the query is doing so?

I have generated autotrace output by replacing bind variables with literals and got the card=value correctly except for one global temp table involved.Autotrace Queryplan is same as in tkprof output.

Can the autotrace output in my last posting be helpful to find the reason behind the slowness of query in 9i optimizer(442 sec) when compare to 8i optimizer (3.24 sec)?
or do I need to gather any other stats?

Thanks,

We have done some preliminary tests with the upgrade from Oracle 9i to Oracle 10G. We have noticed a performance decrease due to the upgrade in our testing environment.
could you tell me the remidies

Thanks for the help

We have a similar issue with a query running on a third party database (meaning that I cannot change indexing, views etc.).

The query is part of a custom application and ran very quickly (<1 sec) on 8i, but takes forever (>10 mins) on 9.2.0.5.0. The EXPLAIN PLAN takes a similar amount of time!

I am afraid I cannot give you CREATE TABLE statements etc., because I have not been able to boil it down to the essence (yet).

Here is what is happening:
I select (amongst other things) as the first column a column that happens to be a unique key on a table. The where clause has an IN clause containing 200 values of the unique key in random order. The query returns 200 rows.
If I "ORDER BY 1" it takes >10 mins, without ORDER BY it takes <2 secs. If I concatenate the empty string to the column and "ORDER BY 1" it runs in <2 secs. This suggests that something is on with unique index, but if I Upper(unique_key) and "ORDER BY 1" it runs in >10 mins! The RULE hint makes it run in about 4 secs.
I can definitely supply EXPLAIN PLANS, but I did not want to clutter the space unnecessarily.

Any clue would help!
Cheers,
Morten

If I modify the IN clause to only contain 60-something keys the query runs fine.

If I create a sub-query for the IN clause to join on the primary key it runs fine:

ORIGINAL:
---------
select uk
from t
where pk in (
200 keys ...
)
order by 1;

Using SUB-QUERY:
----------------
select uk
from t
where pk in (
select pk
from t
where uk in ( 200 keys ... )
)
order by 1;

t has 60000+ rows.

I will try to get it boiled down, but I am not optimistic.

Hi Morten!

This is Kim Anthonisen (used Your flat in CH in 99/2000).
I guess it switches to a full table scan after 61 values in Your IN statement, and the subquery makes it ignore this.
You could try
select /*+ INDEX (t index_name_on_t)
uk
from t
where pk in (
200 keys ...
)
order by 1;

Br
Kim

Hi Tom,

After an upgrade of a database from 8i to 9i, fresh statistics have been gathered but the optimizer_features_enabled was set to 8.1.7. Now, I want to set this parameter to 9.2.0, do I need to re-gather the statistics ?

Regards
VLS

Hi Tom,

We are testing before migrating the development DB's from Windows x64 2003 server to Sun SPARC T3.

But the first results have shown tremendous slowdown.

Note: The other queries show more performance drop as we are loading data volumes.

I have tried Metalink and Oraforums and am aware that when moving from single CPU to SPARC there are performance implications, but as the TKPROF will show below, it is too slow to really believe.

I doubt that there is something that I have missed.
Have exhausted most of my search / help avenues. Can you please help me spot any mistakes that I may have made.

OS Configurations

Windows: 
2003 Server x64 Intel Core 2DUO CPU E7500 2.93GHz with single 250GB HDD 4GB RAM

Solaris:
Operating System : Solaris 5.10/08 
Sun SPARC T3 -1 Server 
CPU : SPARC T3 16-Core 1.65 GHz Processor 
RAM : 16 GB DDR3
HDD : 4*300 GB= 1200 TB

This is the statement:

select * from v_a_rd_data_entry; -- This is a view.

The view query is:
SELECT   1 RN,
      I.RD_TYPE_CODE,
      I.RD_TYPE,
      I.RD_CODE,
      I.TCNT,
      V1.VERSION_ID,
      V1.FLAG_1,
      V1.FLAG_2,
      V1.QUANTITY_1,
      V1.QUANTITY_2,
      V2.IDENTITY_START_DATE,
      V2.IDENTITY_TERMINATION_DATE,
      V1.VERSION_VALID_FROM,
      V1.CRE_USER,
      V1.CRE_DATIM,
      V1.IS_DELETING_VERSION,
      V1.DELETES_VERSION_ID,
      V1.CODE_1,
      V1.CODE_2,
      CAST (NULL AS DATE) AS lc_start,
      CAST (NULL AS DATE) AS lc_end,
      CAST (NULL AS DATE) AS version_valid_till,
      CAST (NULL AS DATE) AS next_lc_start,
      CAST ( MULTISET
      (
         SELECT   RD_TYPE_CODE,
            VERSION_ID,
            LANGUAGE_CODE,
            SHORT_DESCRIPTION,
            LONG_DESCRIPTION
             FROM RD_DATA_ENTRY_T
            WHERE RD_DATA_ENTRY_T.RD_TYPE_CODE = V1.RD_TYPE_CODE
            AND RD_DATA_ENTRY_T.VERSION_ID     = V1.VERSION_ID
      ) AS RD_DATA_ENTRY_T_TAB_TYPE) RD_DATA_ENTRY_T
       FROM RD_DATA_ENTRY_I I,
      RD_DATA_ENTRY_V V1,
      RD_DATA_ENTRY_V V2
      WHERE V1.RD_TYPE_CODE = I.RD_TYPE_CODE
      AND V2.RD_TYPE_CODE   = I.RD_TYPE_CODE
      AND V1.version_id     = get_version_id.RD_DATA_ENTRY (V1.RD_TYPE_CODE, 'CURRENT', V1.VERSION_VALID_FROM)
      AND V2.version_id     = get_version_id.RD_DATA_ENTRY (V2.RD_TYPE_CODE, 'KNOWLEDGE');

SQL> show parameters optimizer

NAME                                 TYPE        VALUE
------------------------------------ ----------- -------------
optimizer_capture_sql_plan_baselines boolean     FALSE
optimizer_dynamic_sampling           integer     2
optimizer_features_enable            string      11.1.0.6
optimizer_index_caching              integer     0
optimizer_index_cost_adj             integer     100
optimizer_mode                       string      ALL_ROWS
optimizer_secure_view_merging        boolean     TRUE
optimizer_use_invisible_indexes      boolean     FALSE
optimizer_use_pending_statistics     boolean     FALSE
optimizer_use_sql_plan_baselines     boolean     TRUE

SQL> show parameter db_file_multi

NAME                                 TYPE        VALUE
------------------------------------ ----------- -------------
db_file_multiblock_read_count        integer     128
SQL> show parameter db_block_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- -------------
db_block_size                        integer     8192
SQL> show parameter cursor_sharing

NAME                                 TYPE        VALUE
------------------------------------ ----------- -------------
cursor_sharing                       string      EXACT


select
       sname
     , pname
     , pval1
     , pval2
from
     sys.aux_stats$;
  
SNAME                          PNAME                          PVAL1                  PVAL2
------------------------------ ------------------------------ ---------------------- ------------------
SYSSTATS_INFO                  STATUS                                                COMPLETED
SYSSTATS_INFO                  DSTART                                                06-13-2011 20:36
SYSSTATS_INFO                  DSTOP                                                 06-13-2011 20:37
SYSSTATS_INFO                  FLAGS                          1
SYSSTATS_MAIN                  CPUSPEEDNW                     2600.213
SYSSTATS_MAIN                  IOSEEKTIM                      11.207
SYSSTATS_MAIN                  IOTFRSPEED                     4096
SYSSTATS_MAIN                  SREADTIM                       3.226
SYSSTATS_MAIN                  MREADTIM
SYSSTATS_MAIN                  CPUSPEED                       2600
SYSSTATS_MAIN                  MBRC
SYSSTATS_MAIN                  MAXTHR
SYSSTATS_MAIN                  SLAVETHR

 13 rows selected  

Solaris:

SQL> show parameters optimizer

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ----------------
optimizer_capture_sql_plan_baselines boolean                          FALSE
optimizer_dynamic_sampling           integer                          2
optimizer_features_enable            string                           11.2.0.1
optimizer_index_caching              integer                          50
optimizer_index_cost_adj             integer                          50
optimizer_mode                       string                           ALL_ROWS
optimizer_secure_view_merging        boolean                          TRUE
optimizer_use_invisible_indexes      boolean                          FALSE
optimizer_use_pending_statistics     boolean                          FALSE
optimizer_use_sql_plan_baselines     boolean                          TRUE
SQL> show parameter db_file_multi

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ----------------
db_file_multiblock_read_count        integer                          256
SQL> show parameter db_block_size

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ----------------
db_block_size                        integer                          8192
SQL> show parameter cursor_sharing

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ----------------
cursor_sharing                       string                           SIMILAR

select
       sname
     , pname
     , pval1
     , pval2
from
     sys.aux_stats$;
  
SNAME                          PNAME                          PVAL1                  PVAL2
------------------------------ ------------------------------ ---------------------- -----------------
SYSSTATS_INFO                  STATUS                                                COMPLETED
SYSSTATS_INFO                  DSTART                                                06-13-2011 20:32
SYSSTATS_INFO                  DSTOP                                                 06-13-2011 20:33
SYSSTATS_INFO                  FLAGS                          1
SYSSTATS_MAIN                  CPUSPEEDNW                     411.566
SYSSTATS_MAIN                  IOSEEKTIM                      6.197
SYSSTATS_MAIN                  IOTFRSPEED                     52653.625
SYSSTATS_MAIN                  SREADTIM                       463.529
SYSSTATS_MAIN                  MREADTIM
SYSSTATS_MAIN                  CPUSPEED                       412
SYSSTATS_MAIN                  MBRC
SYSSTATS_MAIN                  MAXTHR  

Here is the output of EXPLAIN PLAN:

Windows:

SQL> select * from v_a_rd_data_entry;

4434 rows selected.

Elapsed: 00:00:03.26

Execution Plan
----------------------------------------------------------
Plan hash value: 275055418

-------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                      |     1 |   111 |    73   (3)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID   | RD_DATA_ENTRY_T      |     1 |    38 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN             | RD_DE_T_RD_DE_V_FK1X |     1 |       |     1   (0)| 00:00:01 |
|   3 |  NESTED LOOPS                  |                      |       |       |            |          |
|   4 |   NESTED LOOPS                 |                      |     1 |   111 |    73   (3)| 00:00:01 |
|   5 |    NESTED LOOPS                |                      |     1 |    79 |    71   (3)| 00:00:01 |
|*  6 |     TABLE ACCESS FULL          | RD_DATA_ENTRY_V      |     1 |    60 |    70   (3)| 00:00:01 |
|   7 |     TABLE ACCESS BY INDEX ROWID| RD_DATA_ENTRY_I      |     1 |    19 |     1   (0)| 00:00:01 |
|*  8 |      INDEX UNIQUE SCAN         | RD_DATA_ENTRY_I_PKX  |     1 |       |     0   (0)| 00:00:01 |
|*  9 |    INDEX RANGE SCAN            | RD_DATA_ENTRY_V_PKX  |     1 |       |     1   (0)| 00:00:01 |
|  10 |   TABLE ACCESS BY INDEX ROWID  | RD_DATA_ENTRY_V      |     1 |    32 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("RD_DATA_ENTRY_T"."RD_TYPE_CODE"=:B1 AND "RD_DATA_ENTRY_T"."VERSION_ID"=:B2)
   6 - filter("V1"."VERSION_ID"="GET_VERSION_ID"."RD_DATA_ENTRY"("V1"."RD_TYPE_CODE",'CURRENT',
              INTERNAL_FUNCTION("V1"."VERSION_VALID_FROM")))
   8 - access("V1"."RD_TYPE_CODE"="I"."RD_TYPE_CODE")
   9 - access("V2"."RD_TYPE_CODE"="I"."RD_TYPE_CODE")
       filter("V2"."VERSION_ID"="GET_VERSION_ID"."RD_DATA_ENTRY"("V2"."RD_TYPE_CODE",'KNOWLEDGE
              '))


Statistics
----------------------------------------------------------
      53704  recursive calls
          0  db block gets
     197001  consistent gets
          0  physical reads
          0  redo size
     785437  bytes sent via SQL*Net to client
       3747  bytes received via SQL*Net from client
        299  SQL*Net roundtrips to/from client
      26850  sorts (memory)
          0  sorts (disk)
       4434  rows processed

Solaris:

SQL> select * from v_a_rd_data_entry;

4015 rows selected.

Elapsed: 00:00:09.50

Execution Plan
----------------------------------------------------------
Plan hash value: 1399662582

-------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                      |     1 |   135 |    19  (16)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID   | RD_DATA_ENTRY_T      |     1 |    39 |     1   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN             | RD_DE_T_RD_DE_V_FK1X |     1 |       |     1   (0)| 00:00:01 |
|   3 |  NESTED LOOPS                  |                      |       |       |            |          |
|   4 |   NESTED LOOPS                 |                      |     1 |   135 |    19  (16)| 00:00:01 |
|   5 |    NESTED LOOPS                |                      |     1 |    51 |    19  (16)| 00:00:01 |
|*  6 |     TABLE ACCESS FULL          | RD_DATA_ENTRY_V      |     1 |    32 |    18  (17)| 00:00:01 |
|   7 |     TABLE ACCESS BY INDEX ROWID| RD_DATA_ENTRY_I      |     1 |    19 |     1   (0)| 00:00:01 |
|*  8 |      INDEX UNIQUE SCAN         | RD_DATA_ENTRY_I_PKX  |     1 |       |     1   (0)| 00:00:01 |
|*  9 |    INDEX RANGE SCAN            | RD_DE_V_RDE_I_FK1X   |     2 |       |     1   (0)| 00:00:01 |
|* 10 |   TABLE ACCESS BY INDEX ROWID  | RD_DATA_ENTRY_V      |     1 |    84 |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("RD_DATA_ENTRY_T"."RD_TYPE_CODE"=:B1 AND "RD_DATA_ENTRY_T"."VERSION_ID"=:B2)
   6 - filter("V2"."VERSION_ID"="GET_VERSION_ID"."RD_DATA_ENTRY"("V2"."RD_TYPE_CODE",'KNOWLEDGE
              '))
   8 - access("V2"."RD_TYPE_CODE"="I"."RD_TYPE_CODE")
   9 - access("V1"."RD_TYPE_CODE"="I"."RD_TYPE_CODE")
  10 - filter("V1"."VERSION_ID"="GET_VERSION_ID"."RD_DATA_ENTRY"("V1"."RD_TYPE_CODE",'CURRENT',
              INTERNAL_FUNCTION("V1"."VERSION_VALID_FROM")))

Note
-----
   - 'PLAN_TABLE' is old version


Statistics
----------------------------------------------------------
      32000  recursive calls
          0  db block gets
     101816  consistent gets
          0  physical reads
          0  redo size
     631809  bytes sent via SQL*Net to client
       2214  bytes received via SQL*Net from client
        271  SQL*Net roundtrips to/from client
      15998  sorts (memory)
          0  sorts (disk)
       4015  rows processed

TKPROF:

Windows: For top 3 SQl's

TKPROF: Release 11.1.0.6.0 - Production on Mon Jun 27 09:55:40 2011

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: hecr_ora_3300.trc
Sort options: execpu  fchcpu  
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID : cv4dua23db5q4
SELECT V.VERSION_ID 
FROM
 RD_DATA_ENTRY_V V WHERE V.RD_TYPE_CODE = :B3 AND V.VERSION_VALID_FROM <= :B2 
  AND V.CRE_DATIM <= :B1 AND V.DELETES_VERSION_ID IS NULL AND NOT EXISTS 
  (SELECT NULL FROM RD_DATA_ENTRY_V V2 WHERE V.VERSION_ID = 
  V2.DELETES_VERSION_ID AND V2.VERSION_VALID_FROM <= :B2 AND V2.CRE_DATIM <= 
  :B1 ) ORDER BY V.VERSION_VALID_FROM DESC, V.CRE_DATIM DESC


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  13260      2.43       2.45          0          0          0           0
Fetch    13260      0.54       0.57          0     100502          0       13070
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    26521      2.98       3.03          0     100502          0       13070

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT ORDER BY (cr=8 pr=0 pw=0 time=0 us cost=6 size=58 card=1)
      4   NESTED LOOPS ANTI (cr=8 pr=0 pw=0 time=12 us cost=5 size=58 card=1)
      4    TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=6 pr=0 pw=0 time=6 us cost=4 size=111 card=3)
      4     INDEX RANGE SCAN RD_DE_V_RDE_I_FK1X (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=3)(object id 73475)
      0    TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=2 pr=0 pw=0 time=0 us cost=1 size=2289 card=109)
      0     INDEX RANGE SCAN RD_DE_V_RD_DE_V_FK2X (cr=2 pr=0 pw=0 time=0 us cost=0 size=0 card=1)(object id 73476)

********************************************************************************

SQL ID : d2r9j2k1xj4qy
select * 
from
 v_a_rd_data_entry


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.04          0        368          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      296      2.57       2.88          0      20557          0        4423
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      298      2.62       2.92          0      20925          0        4423

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83  

Rows     Row Source Operation
-------  ---------------------------------------------------
   6078  TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_T (cr=9954 pr=0 pw=0 time=863 us cost=2 size=38 card=1)
   6078   INDEX RANGE SCAN RD_DE_T_RD_DE_V_FK1X (cr=5680 pr=0 pw=0 time=375 us cost=1 size=0 card=1)(object id 73469)
   4423  NESTED LOOPS  (cr=185697 pr=0 pw=0 time=28504 us)
   4423   NESTED LOOPS  (cr=185207 pr=0 pw=0 time=116281 us cost=73 size=111 card=1)
   4423    NESTED LOOPS  (cr=106858 pr=0 pw=0 time=98999 us cost=71 size=79 card=1)
   4423     TABLE ACCESS FULL RD_DATA_ENTRY_V (cr=101105 pr=0 pw=0 time=98727 us cost=70 size=60 card=1)
   4423     TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_I (cr=5753 pr=0 pw=0 time=0 us cost=1 size=19 card=1)
   4423      INDEX UNIQUE SCAN RD_DATA_ENTRY_I_PKX (cr=1330 pr=0 pw=0 time=0 us cost=0 size=0 card=1)(object id 73465)
   4423    INDEX RANGE SCAN RD_DATA_ENTRY_V_PKX (cr=78349 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 73473)
   4423   TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=490 pr=0 pw=0 time=0 us cost=2 size=32 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     296        0.00          0.00
  SQL*Net message from client                   296       12.12         20.59
********************************************************************************

SQL ID : aw27jjh96pwrn
SELECT V.VERSION_ID 
FROM
 RD_DATA_ENTRY_V V WHERE V.RD_TYPE_CODE = :B1 ORDER BY CRE_DATIM DESC


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  13523      0.57       0.59          0          0          0           0
Fetch    13523      0.25       0.25          0      76312          0       13523
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    27047      0.82       0.85          0      76312          0       13523

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT ORDER BY (cr=3 pr=0 pw=0 time=0 us cost=5 size=81 card=3)
      2   TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=3 pr=0 pw=0 time=2 us cost=4 size=81 card=3)
      2    INDEX RANGE SCAN RD_DE_V_RDE_I_FK1X (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=3)(object id 73475)

********************************************************************************

Solaris: For top 3 SQl's

TKPROF: Release 11.2.0.1.0 - Development on Mon Jun 27 09:27:16 2011

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: HECRDB_ora_17680.trc
Sort options: execpu  fchcpu  
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: cv4dua23db5q4
Plan Hash: 718270746
SELECT V.VERSION_ID 
FROM
 RD_DATA_ENTRY_V V WHERE V.RD_TYPE_CODE = :B3 AND V.VERSION_VALID_FROM <= :B2 
  AND V.CRE_DATIM <= :B1 AND V.DELETES_VERSION_ID IS NULL AND NOT EXISTS 
  (SELECT NULL FROM RD_DATA_ENTRY_V V2 WHERE V.VERSION_ID = 
  V2.DELETES_VERSION_ID AND V2.VERSION_VALID_FROM <= :B2 AND V2.CRE_DATIM <= 
  :B1 ) ORDER BY V.VERSION_VALID_FROM DESC, V.CRE_DATIM DESC


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute   7998     33.41      33.38          0          0          0           0
Fetch     7998      1.58       1.58          0      47988          0        7998
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    15997     34.99      34.97          0      47988          0        7998

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 86     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT ORDER BY (cr=6 pr=0 pw=0 time=0 us cost=4 size=58 card=1)
      2   NESTED LOOPS ANTI (cr=6 pr=0 pw=0 time=52 us cost=3 size=58 card=1)
      2    TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=4 pr=0 pw=0 time=21 us cost=2 size=74 card=2)
      2     INDEX RANGE SCAN RD_DE_V_RDE_I_FK1X (cr=2 pr=0 pw=0 time=2 us cost=1 size=0 card=2)(object id 85543)
      0    TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=2 pr=0 pw=0 time=0 us cost=1 size=42 card=2)
      0     INDEX RANGE SCAN RD_DE_V_RD_DE_V_FK2X (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 85542)

********************************************************************************

SQL ID: d2r9j2k1xj4qy
Plan Hash: 1399662582
select * 
from
 v_a_rd_data_entry


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.13       0.17          0         27          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      269     12.54      12.50         72      21793          0        4015
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      271     12.67      12.68         72      21820          0        4015

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 86  

Rows     Row Source Operation
-------  ---------------------------------------------------
   4013  TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_T (cr=8204 pr=46 pw=0 time=0 us cost=1 size=39 card=1)
   4013   INDEX RANGE SCAN RD_DE_T_RD_DE_V_FK1X (cr=4191 pr=20 pw=0 time=0 us cost=1 size=0 card=1)(object id 80573)
   4015  NESTED LOOPS  (cr=93654 pr=32 pw=0 time=49476824 us)
   7999   NESTED LOOPS  (cr=37686 pr=32 pw=0 time=8393203 us cost=19 size=135 card=1)
   4012    NESTED LOOPS  (cr=36894 pr=32 pw=0 time=8200740 us cost=19 size=51 card=1)
   4012     TABLE ACCESS FULL RD_DATA_ENTRY_V (cr=32415 pr=12 pw=0 time=8084170 us cost=18 size=32 card=1)
   4012     TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_I (cr=4479 pr=20 pw=0 time=0 us cost=1 size=19 card=1)
   4012      INDEX UNIQUE SCAN RD_DATA_ENTRY_I_PKX (cr=467 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 80571)
   7999    INDEX RANGE SCAN RD_DE_V_RDE_I_FK1X (cr=792 pr=0 pw=0 time=13055 us cost=1 size=0 card=2)(object id 85543)
   4015   TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=55968 pr=0 pw=0 time=0 us cost=1 size=84 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     269        0.00          0.00
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                        11        0.01          0.03
  db file scattered read                         15        0.00          0.00
  SQL*Net message from client                   269        0.02          5.57
********************************************************************************

SQL ID: aw27jjh96pwrn
Plan Hash: 2563221704
SELECT V.VERSION_ID 
FROM
 RD_DATA_ENTRY_V V WHERE V.RD_TYPE_CODE = :B1 ORDER BY CRE_DATIM DESC


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute   7999      9.52       9.52          0          0          0           0
Fetch     7999      0.74       0.81          6      32019          0        7999
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    15999     10.26      10.33          6      32019          0        7999

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 86     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=3 size=54 card=2)
      2   TABLE ACCESS BY INDEX ROWID RD_DATA_ENTRY_V (cr=4 pr=0 pw=0 time=18 us cost=2 size=54 card=2)
      2    INDEX RANGE SCAN RD_DE_V_RDE_I_FK1X (cr=2 pr=0 pw=0 time=5 us cost=1 size=0 card=2)(object id 85543)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         1        0.00          0.00
  db file scattered read                          2        0.00          0.00
********************************************************************************

Hi Tom,

Further to my above post I did IO Analysis using the Oracle 11g provided feature Calibrate I/O.

My understanding of this is that the Solaris I/O service times are much higher than Windows.

Would this also be attributed to the lower CPU?

Note: Sorry about the formatting, but i wanted to include all columns.

Windows

set serveroutput on
declare
l_latency   integer;
l_iops      integer;
l_mbps      integer;
begin
dbms_resource_manager.calibrate_io (
1, /* # of disks */
10, /* max latency */
l_iops, /* I/O Ops/sec */
l_mbps, /* MBytes/sec */
l_latency /* actual latency */
);
dbms_output.put_line ('I/O Ops/sec = '  l_iops);
dbms_output.put_line ('Actual Latency = '  l_latency);
dbms_output.put_line('MB/sec = '  l_mbps);
end;
/

I/O Ops/sec = 89
Actual Latency = 10
MB/sec = 56

select * from DBA_RSRC_IO_CALIBRATE;

START_TIME                END_TIME                  MAX_IOPS               MAX_MBPS               MAX_PMBPS              LATENCY                NUM_PHYSICAL_DISKS
------------------------- ------------------------- ---------------------- ---------------------- ---------------------- ---------------------- ----------------------
30-JUN-2011 10.43.12.6 AM 30-JUN-2011 10.48.14.4 AM 89                     56                     31                     10                     1

Solaris

sys@HECRDEV> set serveroutput on
sys@HECRDEV> declare
2      l_latency   integer;
3       l_iops      integer;
4       l_mbps      integer;
5   begin
6      dbms_resource_manager.calibrate_io (
7           4, /* # of disks */
8           10, /* max latency */
9           l_iops, /* I/O Ops/sec */
10           l_mbps, /* MBytes/sec */
11           l_latency /* actual latency */
12       );
13         dbms_output.put_line ('I/O Ops/sec = ' || l_iops);
14       dbms_output.put_line ('Actual Latency = '||  l_latency);
15       dbms_output.put_line('MB/sec = ' || l_mbps);
16  end;
17  /
I/O Ops/sec = 1222
Actual Latency = 8
MB/sec = 28

select * from DBA_RSRC_IO_CALIBRATE;

START_TIME                END_TIME                  MAX_IOPS               MAX_MBPS               MAX_PMBPS              LATENCY                NUM_PHYSICAL_DISKS
------------------------- ------------------------- ---------------------- ---------------------- ---------------------- ---------------------- ----------------------
30-JUN-2011 10.55.05.7 AM 30-JUN-2011 10.59.08.5 AM 1222                   28                     2                      8                      4

Windows

select small_read_reqs, small_read_servicetime , SMALL_WRITE_REQS, small_write_servicetime 
from v$iostat_file ;

SMALL_READ_REQS        SMALL_READ_SERVICETIME SMALL_WRITE_REQS       SMALL_WRITE_SERVICETIME 
---------------------- ---------------------- ---------------------- ----------------------- 
36                     0                      60                     0                       
773927                 2738                   1603026                656                     
97                     1                      230812                 166                     
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
67309                  775301                 26379                  138218                  
271667                 311                    270950                 1252                    
97888                  1336560                185610                 871909                  
7620                   149856                 48398                  65937                   
237276                 1828635                13787                  38723                   
6112                   81539                  46                     669                     
280                    5552                   46                     232                     
279                    5770                   46                     279                     
274                    6910                   46                     637                     
274                    5612                   46                     356                     
279                    5830                   46                     405                     
275                    5798                   46                     419                     
283                    5749                   46                     451                     

 23 rows selected 

Solaris

select small_read_reqs, small_read_servicetime , SMALL_WRITE_REQS, small_write_servicetime 
from v$iostat_file ;

SMALL_READ_REQS        SMALL_READ_SERVICETIME SMALL_WRITE_REQS       SMALL_WRITE_SERVICETIME 
---------------------- ---------------------- ---------------------- ----------------------- 
30                     9                      50                     279                     
123282                 3315                   66098                  1117272                 
339                    59                     43871                  284817                  
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
35545                  168200                 14447                  435155                  
172                    45                     90                     844                     
29348                  178420                 49132                  2040517                 
8835                   78151                  4858                   183163                  
24570                  244846                 335                    6158                    
38804                  353257                 5127                   120339                  
8572                   80861                  166                    2887                    
8517                   80685                  166                    2882                    
8593                   83033                  166                    3215                    
8491                   81401                  166                    3466                    
8393                   81228                  166                    4022                    

 21 rows selected 
 

Windows

select large_read_reqs, large_read_servicetime , large_WRITE_REQS, large_write_servicetime 
from v$iostat_file ; 

LARGE_READ_REQS        LARGE_READ_SERVICETIME LARGE_WRITE_REQS       LARGE_WRITE_SERVICETIME 
---------------------- ---------------------- ---------------------- ----------------------- 
0                      0                      0                      0                       
0                      0                      0                      0                       
98                     4                      2607                   17                      
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
720                    106190                 49                     952                     
1717                   299                    1019                   35                      
1567                   50616                  377                    2212                    
2994                   314985                 4505                   39938                   
3893                   316937                 68                     0                       
154                    14265                  0                      0                       
7                      889                    0                      0                       
8                      1078                   0                      0                       
8                      717                    0                      0                       
8                      828                    0                      0                       
7                      735                    0                      0                       
14                     1186                   0                      0                       
7                      969                    0                      0                       

 23 rows selected 

Solaris

select large_read_reqs, large_read_servicetime , large_WRITE_REQS, large_write_servicetime 
from v$iostat_file ; 

LARGE_READ_REQS        LARGE_READ_SERVICETIME LARGE_WRITE_REQS       LARGE_WRITE_SERVICETIME 
---------------------- ---------------------- ---------------------- ----------------------- 
0                      0                      0                      0                       
0                      0                      0                      0                       
26                     1216                   1748                   50904                   
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
0                      0                      0                      0                       
924                    154693                 21                     697                     
24                     72                     40                     1740                    
724                    214213                 64                     3632                    
184                    129083                 3049                   90676                   
547                    344002                 0                      0                       
897                    398399                 31                     688                     
192                    102497                 0                      0                       
197                    92515                  0                      0                       
207                    86151                  0                      0                       
199                    121201                 0                      0                       
215                    134375                 0                      0                       

 21 rows selected