Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Post Upgrade SQL Performance Issue

Sky13Jul 30 2012 — edited Aug 2 2012
Hello,
I Just Upgraded/Migrated my database from 11.1.0.6 SE to 11.2.0.3 EE. I did this with datapump export/import out of the 11.1.0.6 and into a new 11.2.0.3 database. Both the old and the new database are on the same Linux server. The new database has 2GB more RAM assigned to its SGA then the old one. Both DB are using AMM.

The strange part is I have a SQL statement that completes in 1 second in the Old DB and takes 30 seconds in the new one. I even moved the SQL Plan from the Old DB into the New DB so they are using the same plan.

To sum up the issue. I have one SQL statement using the same SQL Plan running at dramatically different speeds on two different databases on the same server. The databases are 11.1.0.7 SE and 11.2.0.3 EE.

Not sure what is going on or how to fix it, Any help would be great!

I have included Explains and Auto Traces from both NEW and OLD databases.

NEW DB Explain Plan (Slow)
Plan hash value: 1046170788

-------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 94861 | 193M| | 74043 (1)| 00:18:52 |
| 1 | SORT ORDER BY | | 94861 | 193M| 247M| 74043 (1)| 00:18:52 |
| 2 | VIEW | PBM_MEMBER_INTAKE_VW | 94861 | 193M| | 31803 (1)| 00:08:07 |
| 3 | UNION-ALL | | | | | | |
| 4 | NESTED LOOPS OUTER | | 1889 | 173K| | 455 (1)| 00:00:07 |
|* 5 | HASH JOIN | | 1889 | 164K| | 454 (1)| 00:00:07 |
| 6 | TABLE ACCESS FULL| PBM_CODES | 2138 | 21380 | | 8 (0)| 00:00:01 |
|* 7 | TABLE ACCESS FULL| PBM_MEMBER_INTAKE | 1889 | 145K| | 446 (1)| 00:00:07 |
|* 8 | INDEX UNIQUE SCAN | ADJ_PK | 1 | 5 | | 1 (0)| 00:00:01 |
| 9 | NESTED LOOPS | | 92972 | 9987K| | 31347 (1)| 00:08:00 |
| 10 | NESTED LOOPS OUTER| | 92972 | 8443K| | 31346 (1)| 00:08:00 |
|* 11 | TABLE ACCESS FULL| PBM_MEMBERS | 92972 | 7989K| | 31344 (1)| 00:08:00 |
|* 12 | INDEX UNIQUE SCAN| ADJ_PK | 1 | 5 | | 1 (0)| 00:00:01 |
|* 13 | INDEX UNIQUE SCAN | PBM_EMPLOYER_UK1 | 1 | 17 | | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

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

5 - access("C"."CODE_ID"="MI"."STATUS_ID")
7 - filter("MI"."CLAIM_NUMBER" LIKE '%A0000250%' AND "MI"."CLAIM_NUMBER" IS NOT NULL)
8 - access("MI"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
11 - filter("M"."THEIR_GROUP_ID" LIKE '%A0000250%' AND "M"."THEIR_GROUP_ID" IS NOT NULL)
12 - access("M"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
13 - access("M"."GROUP_CODE"="E"."GROUP_CODE" AND "M"."EMPLOYER_CODE"="E"."EMPLOYER_CODE")

Note
-----
- SQL plan baseline "SYS_SQL_PLAN_a3c20fdcecd98dfe" used for this statement

OLD DB Explain Plan (Fast)
Plan hash value: 1046170788

-------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 95201 | 193M| | 74262 (1)| 00:14:52 |
| 1 | SORT ORDER BY | | 95201 | 193M| 495M| 74262 (1)| 00:14:52 |
| 2 | VIEW | PBM_MEMBER_INTAKE_VW | 95201 | 193M| | 31853 (1)| 00:06:23 |
| 3 | UNION-ALL | | | | | | |
| 4 | NESTED LOOPS OUTER | | 1943 | 178K| | 486 (1)| 00:00:06 |
|* 5 | HASH JOIN | | 1943 | 168K| | 486 (1)| 00:00:06 |
| 6 | TABLE ACCESS FULL| PBM_CODES | 2105 | 21050 | | 7 (0)| 00:00:01 |
|* 7 | TABLE ACCESS FULL| PBM_MEMBER_INTAKE | 1943 | 149K| | 479 (1)| 00:00:06 |
|* 8 | INDEX UNIQUE SCAN | ADJ_PK | 1 | 5 | | 0 (0)| 00:00:01 |
| 9 | NESTED LOOPS | | 93258 | 9M| | 31367 (1)| 00:06:17 |
| 10 | NESTED LOOPS OUTER| | 93258 | 8469K| | 31358 (1)| 00:06:17 |
|* 11 | TABLE ACCESS FULL| PBM_MEMBERS | 93258 | 8014K| | 31352 (1)| 00:06:17 |
|* 12 | INDEX UNIQUE SCAN| ADJ_PK | 1 | 5 | | 0 (0)| 00:00:01 |
|* 13 | INDEX UNIQUE SCAN | PBM_EMPLOYER_UK1 | 1 | 17 | | 0 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

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

5 - access("C"."CODE_ID"="MI"."STATUS_ID")
7 - filter("MI"."CLAIM_NUMBER" LIKE '%A0000250%')
8 - access("MI"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
11 - filter("M"."THEIR_GROUP_ID" LIKE '%A0000250%')
12 - access("M"."ADJUSTER_ID"="A"."ADJUSTER_ID"(+))
13 - access("M"."GROUP_CODE"="E"."GROUP_CODE" AND "M"."EMPLOYER_CODE"="E"."EMPLOYER_CODE")

NEW DB Auto trace (Slow)
active txn count during cleanout 0
blocks decrypted 0
buffer is not pinned count 664129
buffer is pinned count 3061793
bytes received via SQL*Net from client 3339
bytes sent via SQL*Net to client 28758
Cached Commit SCN referenced 662366
calls to get snapshot scn: kcmgss 3
calls to kcmgas 0
calls to kcmgcs 8
CCursor + sql area evicted 0
cell physical IO interconnect bytes 0
cleanout - number of ktugct calls 0
cleanouts only - consistent read gets 0
cluster key scan block gets 0
cluster key scans 0
commit cleanout failures: block lost 0
commit cleanout failures: callback failure 0
commit cleanouts 0
commit cleanouts successfully completed 0
Commit SCN cached 0
commit txn count during cleanout 0
concurrency wait time 0
consistent changes 0
consistent gets 985371
consistent gets - examination 2993
consistent gets direct 0
consistent gets from cache 985371
consistent gets from cache (fastpath) 982093
CPU used by this session 3551
CPU used when call started 3551
CR blocks created 0
cursor authentications 1
data blocks consistent reads - undo records applied 0
db block changes 0
db block gets 0
db block gets direct 0
db block gets from cache 0
db block gets from cache (fastpath) 0
DB time 3553
deferred (CURRENT) block cleanout applications 0
dirty buffers inspected 0
Effective IO time 0
enqueue releases 0
enqueue requests 0
execute count 3
file io wait time 0
free buffer inspected 0
free buffer requested 0
heap block compress 0
Heap Segment Array Updates 0
hot buffers moved to head of LRU 0
HSC Heap Segment Block Changes 0
immediate (CR) block cleanout applications 0
immediate (CURRENT) block cleanout applications 0
IMU Flushes 0
IMU ktichg flush 0
IMU Redo allocation size 0
IMU undo allocation size 0
index fast full scans (full) 2
index fetch by key 0
index scans kdiixs1 12944
lob reads 0
LOB table id lookup cache misses 0
lob writes 0
lob writes unaligned 0
logical read bytes from cache -517775360
logons cumulative 0
logons current 0
messages sent 0
no buffer to keep pinned count 10
no work - consistent read gets 982086
non-idle wait count 6
non-idle wait time 0
Number of read IOs issued 0
opened cursors cumulative 4
opened cursors current 1
OS Involuntary context switches 853
OS Maximum resident set size 0
OS Page faults 0
OS Page reclaims 2453
OS System time used 9
OS User time used 3549
OS Voluntary context switches 238
parse count (failures) 0
parse count (hard) 0
parse count (total) 1
parse time cpu 0
parse time elapsed 0
physical read bytes 0
physical read IO requests 0
physical read total bytes 0
physical read total IO requests 0
physical read total multi block requests 0
physical reads 0
physical reads cache 0
physical reads cache prefetch 0
physical reads direct 0
physical reads direct (lob) 0
physical write bytes 0
physical write IO requests 0
physical write total bytes 0
physical write total IO requests 0
physical writes 0
physical writes direct 0
physical writes direct (lob) 0
physical writes non checkpoint 0
pinned buffers inspected 0
pinned cursors current 0
process last non-idle time 0
recursive calls 0
recursive cpu usage 0
redo entries 0
redo size 0
redo size for direct writes 0
redo subscn max counts 0
redo synch time 0
redo synch time (usec) 0
redo synch writes 0
Requests to/from client 3
rollbacks only - consistent read gets 0
RowCR - row contention 0
RowCR attempts 0
rows fetched via callback 0
session connect time 0
session cursor cache count 1
session cursor cache hits 3
session logical reads 985371
session pga memory 131072
session pga memory max 0
session uga memory 392928
session uga memory max 0
shared hash latch upgrades - no wait 284
shared hash latch upgrades - wait 0
sorts (memory) 3
sorts (rows) 243
sql area evicted 0
sql area purged 0
SQL*Net roundtrips to/from client 4
switch current to new buffer 0
table fetch by rowid 1861456
table fetch continued row 9
table scan blocks gotten 0
table scan rows gotten 0
table scans (short tables) 0
temp space allocated (bytes) 0
undo change vector size 0
user calls 7
user commits 0
user I/O wait time 0
workarea executions - optimal 10
workarea memory allocated 342

OLD DB Auto trace (Fast)
active txn count during cleanout 0
buffer is not pinned count 4
buffer is pinned count 101
bytes received via SQL*Net from client 1322
bytes sent via SQL*Net to client 9560
calls to get snapshot scn: kcmgss 15
calls to kcmgas 0
calls to kcmgcs 0
calls to kcmgrs 1
cleanout - number of ktugct calls 0
cluster key scan block gets 0
cluster key scans 0
commit cleanouts 0
commit cleanouts successfully completed 0
concurrency wait time 0
consistent changes 0
consistent gets 117149
consistent gets - examination 56
consistent gets direct 115301
consistent gets from cache 1848
consistent gets from cache (fastpath) 1792
CPU used by this session 118
CPU used when call started 119
cursor authentications 1
db block changes 0
db block gets 0
db block gets from cache 0
db block gets from cache (fastpath) 0
DB time 123
deferred (CURRENT) block cleanout applications 0
Effective IO time 2012
enqueue conversions 3
enqueue releases 2
enqueue requests 2
enqueue waits 1
execute count 2
free buffer requested 0
HSC Heap Segment Block Changes 0
IMU Flushes 0
IMU ktichg flush 0
index fast full scans (full) 0
index fetch by key 101
index scans kdiixs1 0
lob writes 0
lob writes unaligned 0
logons cumulative 0
logons current 0
messages sent 0
no work - consistent read gets 117080
Number of read IOs issued 1019
opened cursors cumulative 3
opened cursors current 1
OS Involuntary context switches 54
OS Maximum resident set size 7868
OS Page faults 12
OS Page reclaims 2911
OS System time used 57
OS User time used 71
OS Voluntary context switches 25
parse count (failures) 0
parse count (hard) 0
parse count (total) 3
parse time cpu 0
parse time elapsed 0
physical read bytes 944545792
physical read IO requests 1019
physical read total bytes 944545792
physical read total IO requests 1019
physical read total multi block requests 905
physical reads 115301
physical reads cache 0
physical reads cache prefetch 0
physical reads direct 115301
physical reads prefetch warmup 0
process last non-idle time 0
recursive calls 0
recursive cpu usage 0
redo entries 0
redo size 0
redo synch writes 0
rows fetched via callback 0
session connect time 0
session cursor cache count 1
session cursor cache hits 2
session logical reads 117149
session pga memory -983040
session pga memory max 0
session uga memory 0
session uga memory max 0
shared hash latch upgrades - no wait 0
sorts (memory) 2
sorts (rows) 157
sql area purged 0
SQL*Net roundtrips to/from client 3
table fetch by rowid 0
table fetch continued row 0
table scan blocks gotten 117077
table scan rows gotten 1972604
table scans (direct read) 1
table scans (long tables) 1
table scans (short tables) 2
undo change vector size 0
user calls 5
user I/O wait time 0
workarea executions - optimal 4
Comments
Locked Post
New comments cannot be posted to this locked post.
Post Details
Locked on Aug 30 2012
Added on Jul 30 2012
7 comments
587 views