WORKLOAD REPOSITORY report for
DB Name DB Id Instance Inst num Release RAC Host
IDWSTGDV 425809231 IDWSTGDV 1 10.2.0.5.0 NO istdwdev
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 8699 03-May-11 09:19:26 47 14.6
End Snap: 8700 03-May-11 10:00:11 47 14.7
Elapsed: 40.76 (mins)
DB Time: 32.45 (mins)
Report Summary
Cache Sizes
Begin End
Buffer Cache: 38,624M 38,624M Std Block Size: 8K
Shared Pool Size: 2,128M 2,128M Log Buffer: 14,296K
Load Profile
Per Second Per Transaction
Redo size: 1,181,075.52 3,670,144.90
Logical reads: 140,785.03 437,483.85
Block changes: 4,692.96 14,583.19
Physical reads: 315.76 981.23
Physical writes: 297.97 925.93
User calls: 7.83 24.34
Parses: 18.20 56.57
Hard parses: 0.24 0.76
Sorts: 3.63 11.27
Logons: 0.25 0.78
Executes: 50.53 157.01
Transactions: 0.32
% Blocks changed per Read: 3.33 Recursive Call %: 98.01
Rollback per transaction %: 17.92 Rows per Sort: 2519.37
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.90 In-memory Sort %: 100.00
Library Hit %: 99.73 Soft Parse %: 98.65
Execute to Parse %: 63.97 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 92.00 % Non-Parse CPU: 99.69
Shared Pool Statistics
Begin End
Memory Usage %: 44.24 44.94
% SQL with executions>1: 92.75 92.92
% Memory for SQL w/exec>1: 86.11 84.31
Top 5 Timed Events
event waits time(s) avg wait(ms) % total call time wait class
cpu time 1,726 88.6
px deq credit: send blkd 225,491 184 1 9.4 other
db file scattered read 21,794 43 2 2.2 user i/o
db file sequential read 23,846 35 1 1.8 user i/o
direct path read 13,426 33 2 1.7 user i/o
Time Model Statistics
Statistic Name Time (s) % of DB Time
sql execute elapsed time 1,885.03 96.82
DB CPU 1,725.78 88.64
parse time elapsed 7.04 0.36
hard parse elapsed time 6.25 0.32
PL/SQL execution elapsed time 3.33 0.17
sequence load elapsed time 3.05 0.16
PL/SQL compilation elapsed time 2.32 0.12
failed parse elapsed time 0.16 0.01
repeated bind elapsed time 0.14 0.01
hard parse (sharing criteria) elapsed time 0.10 0.00
connection management call elapsed time 0.09 0.00
hard parse (bind mismatch) elapsed time 0.01 0.00
DB time 1,946.93
background elapsed time 72.59
background cpu time 11.95
Wait Class
Wait Class Waits %Time -outs Total Wait Time (s) Avg wait (ms) %Total
Call Time
CPU time 1,726 88.64
Other 227,788 0 184 1 9.45
User I/O 74,227 135 2 6.93
System I/O 8,768 43 5 2.23
Network 533,130 19 0 0.97
Application 293 0 4 14 0.22
Concurrency 167 2 12 0.10
Commit 252 5 2 8 0.10
Configuration 17 1 43 0.04
Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
PX Deq Credit: send blkd 225,491 0 184 1 286.52
db file scattered read 21,794 43 2 27.69
db file sequential read 23,846 35 1 30.30
direct path read 13,426 33 2 17.06
log file parallel write 5,223 30 6 6.64
SQL*Net more data from dblink 516,271 15 0 656.00
control file sequential read 2,387 12 5 3.03
direct path read temp 6,958 12 2 8.84
direct path write temp 7,921 11 1 10.06
enq: RO - fast object reuse 67 1 4 61 0.09
SQL*Net message from dblink 532 3 6 0.68
log file sync 252 5 2 8 0.32
os thread startup 63 2 28 0.08
control file parallel write 1,061 1 1 1.35
SQL*Net more data from client 370 1 2 0.47
log buffer space 13 1 49 0.02
read by other session 100 0 3 0.13
row cache lock 1 0 220 0.00
PX Deq: Table Q Get Keys 247 0 1 0.31
direct path write 160 0 1 0.20
PX Deq: Signal ACK 490 10 0 0 0.62
enq: KO - fast object checkpoint 4 0 30 0.01
log file switch completion 4 0 26 0.01
local write wait 22 0 2 0.03
SQL*Net more data to client 2,750 0 0 3.49
control file single write 81 0 1 0.10
rdbms ipc reply 27 0 1 0.03
CSS initialization 4 0 7 0.01
log file sequential read 8 0 3 0.01
SQL*Net break/reset to client 220 0 0 0.28
latch free 280 0 0 0.36
CSS operation: query 24 0 1 0.03
SQL*Net message to client 12,669 0 0 16.10
enq: PS - contention 146 0 0 0.19
LGWR wait for redo copy 617 0 0 0.78
CSS operation: action 4 0 1 0.01
reliable message 73 0 0 0.09
PX Deq: Table Q qref 53 0 0 0.07
log file single write 8 0 0 0.01
latch: cache buffers chains 103 0 0 0.13
PX qref latch 319 49 0 0 0.41
SQL*Net more data to dblink 12 0 0 0.02
SQL*Net message to dblink 526 0 0 0.67
latch: session allocation 13 0 0 0.02
SQL*Net break/reset to dblink 2 0 0 0.00
SQL*Net message from client 12,694 28,232 2224 16.13
PX Idle Wait 5,496 91 9,976 1815 6.98
Streams AQ: waiting for time management or cleanup tasks 28 57
3,028 108141 0.04
Streams AQ: waiting for messages in the queue 490 99 2,389 4875
0.62
wait for unread message on broadcast channel 2,443 100 2,388 977
3.10
Streams AQ: qmn slave idle wait 87 2,387 27437 0.11
Streams AQ: qmn coordinator idle wait 178 51 2,387 13410 0.23
ASM background timer 494 2,385 4829 0.63
virtual circuit status 81 100 2,373 29300 0.10
class slave wait 124 94 2,372 19131 0.16
jobq slave wait 424 99 1,238 2919 0.54
PX Deq: Table Q Normal 28,893 0 213 7 36.71
i/o slave wait 60,263 168 3 76.57
PX Deq: Execute Reply 5,650 0 36 6 7.18
PX Deq: Execution Msg 7,839 30 4 9.96
PX Deq: Table Q Sample 504 0 1 0.64
PX Deq Credit: need buffer 6,063 0 0 7.70
single-task message 4 0 36 0.01
PX Deq: Join ACK 277 0 0 0.35
PX Deq: Parse Reply 203 0 0 0.26
KSV master wait 2 0 18 0.00
PX Deq: Msg Fragment 883 0 0 1.12
Congratulations!
If it's too big for "this", maybe it's too big for your system too. Where did I leave my
crystal balls?
Could you possisbly post the query and the plan?
OK, you have a 38G cache...
> Top 5 Timed Events
>
> event waits time(s) avg wait(ms) % total call time wait class
> cpu time 1,726 88.6
> px deq credit: send blkd 225,491 184 1 9.4 other
> db file scattered read 21,794 43 2 2.2 user i/o
And you are waiting on parallel, cpu and full table scans.
As David said, post the sql and plan. I smell full table scans
thrashing through the sga, hogging the cpu. If those are elements of
a parallel query each doing a full table scan, yikes. Some things
work better serially.
Also, don't forget in a complex multiuser system, something other than
the problem sql may be taking up cpu, so cast a critical eye upon all
your top sql. It is even possible that making one thing faster may
bottleneck something else worse. Has anything changed since the
problem started? Has it ever run better?
jg
--
@home.com is bogus.
http://www.theinquirer.net/inquirer/news/2068531/oracle-toss-129-patent-infringement-claims-google-lawsuit
Don't trust your nose, Gary, full table scans don't get into the SGA.
CPU is most often wasted by using PL/SQL functions in a where clause. That is a sure kill.
That is the conventional wisdom, but I think I see that when a small
(relative to the sga size) table is being full scanned and it is all
in there. But I have no proof that I can post and it wouldn't be
unusual for me to get this wrong. All I can do is point to the 11gR2
direct read scan that copies dirty blocks from the sga to the pga and
mumble something about later patches of 10g maybe trying to do
something similar. Speculation, yes, could be something more
straightforward like copying CR blocks in the SGA for non-full scans.
Only some seriously deep analysis could tell.
>
> CPU is most often wasted by using PL/SQL functions in a where clause. That is a sure kill.
Not what I see, but my system may not be the most often.
jg
--
@home.com is bogus.
http://www.signonsandiego.com/news/2011/may/05/new-website-explores-impact-2050-transportation-pl/
May have nothing to do with the OP, but http://jonathanlewis.wordpress.com/2011/03/24/small-tables/
and related links is the kind of thing I had in mind.
Taking a quick gander at one of my systems, I see an index fast full
scan, only getting rowid for 5 rows out of 200K, cpu cost 44670240, I/
O cost 427, briefly pounding the hell out of a cpu. Before I changed
the code, it did a full table scan, pounding the cpu harder for a
shorter time, IIRC. It's the type of query that has a nullable column
in the middle of a five column key that is not part of the query and
the last column is a date and I'm getting > an arbitrary date and the
rest of the key is specified. I'm wondering if it would make a
difference if I specified it as a primary key. (Other priorities is
why I haven't simply tried it yet, load testing is problematic).
jg
--
@home.com is bogus.
If you thought breaking up by text message was bad...
http://www.signonsandiego.com/news/2011/may/06/motorola-mobility-keep-headquarters-illinois/
Sorry for the amiguity. It's the AWR that is to big to post here. I
wanted to show everything that was happening at the time the SQL was
running. I thought for sure the sql statement was in there but it's
not.
Is there a way to attach a document to a post? I appreciate your help.
I left that out of the AWR report did'nt I :(
Here's the SQL but it's really a mess.
MERGE INTO PIN.DRV_CBRM_USAGE_CS DRV USING PIN.TMP_CBRM_USAGE_STEP200
TMP ON ( DRV.E_POID_ID0 = TMP.OBJ_ID0 ) WHEN MATCHED THEN UPDATE SET
-- DRV.EBIPP_ACCOUNT_OBJ_DB = TMP.ACCOUNT_OBJ_DB --,
DRV.EBIPP_ACCOUNT_OBJ_ID0 = TMP.ACCOUNT_OBJ_ID0 --,
DRV.EBIPP_ACCOUNT_OBJ_TYPE = TMP.ACCOUNT_OBJ_TYPE --,
DRV.EBIPP_ACCOUNT_OBJ_REV = TMP.ACCOUNT_OBJ_REV
-------------------------------------------------
DRV.EBIPP_OFFERING_OBJ_DB = TMP.OFFERING_OBJ_DB ,
DRV.EBIPP_OFFERING_OBJ_ID0 = TMP.OFFERING_OBJ_ID0 ,
DRV.EBIPP_OFFERING_OBJ_TYPE = TMP.OFFERING_OBJ_TYPE ,
DRV.EBIPP_OFFERING_OBJ_REV = TMP.OFFERING_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_PRODUCT_OBJ_DB = TMP.PRODUCT_OBJ_DB ,
DRV.EBIPP_PRODUCT_OBJ_ID0 = TMP.PRODUCT_OBJ_ID0 ,
DRV.EBIPP_PRODUCT_OBJ_TYPE = TMP.PRODUCT_OBJ_TYPE ,
DRV.EBIPP_PRODUCT_OBJ_REV = TMP.PRODUCT_OBJ_REV
------------------------------------------------- --,
DRV.EBIPP_ITEM_OBJ_DB = TMP.ITEM_OBJ_DB --, DRV.EBIPP_ITEM_OBJ_ID0 =
TMP.ITEM_OBJ_ID0 --, DRV.EBIPP_ITEM_OBJ_TYPE = TMP.ITEM_OBJ_TYPE --,
DRV.EBIPP_ITEM_OBJ_REV = TMP.ITEM_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_BAL_GRP_OBJ_DB = TMP.BAL_GRP_OBJ_DB ,
DRV.EBIPP_BAL_GRP_OBJ_ID0 = TMP.BAL_GRP_OBJ_ID0 ,
DRV.EBIPP_BAL_GRP_OBJ_TYPE = TMP.BAL_GRP_OBJ_TYPE ,
DRV.EBIPP_BAL_GRP_OBJ_REV = TMP.BAL_GRP_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_RATE_OBJ_DB = TMP.RATE_OBJ_DB , DRV.EBIPP_RATE_OBJ_ID0 =
TMP.RATE_OBJ_ID0 , DRV.EBIPP_RATE_OBJ_TYPE = TMP.RATE_OBJ_TYPE ,
DRV.EBIPP_RATE_OBJ_REV = TMP.RATE_OBJ_REV
------------------------------------------------- , DRV.EBIPP_R EC_ID
= TMP.REC_ID ------------------------------------------------- ,
DRV.EBIPP_AMOUNT = TMP.AMOUNT , DRV.EBIPP_AMOUNT_DEFERRED =
TMP.AMOUNT_DEFERRED , DRV.EBIPP_AMOUNT_ORIG = TMP.AMOUNT_ORIG ,
DRV.EBIPP_DISCOUNT = TMP.DISCOUNT , DRV.EBIPP_GL_ID = TMP.GL_ID ,
DRV.EBIPP_IMPACT_CATEGORY = TMP.IMPACT_CATEGORY ,
DRV.EBIPP_IMPACT_TYPE = TMP.IMPACT_TYPE , DRV.EBIPP_PERCENT =
TMP.PERCENT , DRV.EBIPP_QUANTITY = TMP.QUANTITY , DRV.EBIPP_RATE_TAG =
TMP.RATE_TAG , DRV.EBIPP_RESOURCE_ID = TMP.RESOURCE_ID ,
DRV.EBIPP_RESOURCE_ID_ORIG = TMP.RESOURCE_ID_ORIG , DRV.EBIPP_TAX_CODE
= TMP.TAX_CODE , DRV.EBIPP_LINEAGE = TMP.LINEAGE ,
DRV.EBIPP_DISCOUNT_INFO = TMP.DISCOUNT_INFO , DRV.EBIPP_RUM_ID =
TMP.RUM_ID MERGE INTO PIN.DRV_CBRM_USAGE_CS DRV USING
PIN.TMP_CBRM_USAGE_STEP200 TMP ON ( DRV.E_POID_ID0 = TMP.OBJ_ID0 )
WHEN MATCHED THEN UPDATE SET -- DRV.EBIPP_ACCOUNT_OBJ_DB =
TMP.ACCOUNT_OBJ_DB --, DRV.EBIPP_ACCOUNT_OBJ_ID0 = TMP.ACCOUNT_OBJ_ID0
--, DRV.EBIPP_ACCOUNT_OBJ_TYPE = TMP.ACCOUNT_OBJ_TYPE --,
DRV.EBIPP_ACCOUNT_OBJ_REV = TMP.ACCOUNT_OBJ_REV
-------------------------------------------------
DRV.EBIPP_OFFERING_OBJ_DB = TMP.OFFERING_OBJ_DB ,
DRV.EBIPP_OFFERING_OBJ_ID0 = TMP.OFFERING_OBJ_ID0 ,
DRV.EBIPP_OFFERING_OBJ_TYPE = TMP.OFFERING_OBJ_TYPE ,
DRV.EBIPP_OFFERING_OBJ_REV = TMP.OFFERING_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_PRODUCT_OBJ_DB = TMP.PRODUCT_OBJ_DB ,
DRV.EBIPP_PRODUCT_OBJ_ID0 = TMP.PRODUCT_OBJ_ID0 ,
DRV.EBIPP_PRODUCT_OBJ_TYPE = TMP.PRODUCT_OBJ_TYPE ,
DRV.EBIPP_PRODUCT_OBJ_REV = TMP.PRODUCT_OBJ_REV
------------------------------------------------- --,
DRV.EBIPP_ITEM_OBJ_DB = TMP.ITEM_OBJ_DB --, DRV.EBIPP_ITEM_OBJ_ID0 =
TMP.ITEM_OBJ_ID0 --, DRV.EBIPP_ITEM_OBJ_TYPE = TMP.ITEM_OBJ_TYPE --,
DRV.EBIPP_ITEM_OBJ_REV = TMP.ITEM_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_BAL_GRP_OBJ_DB = TMP.BAL_GRP_OBJ_DB ,
DRV.EBIPP_BAL_GRP_OBJ_ID0 = TMP.BAL_GRP_OBJ_ID0 ,
DRV.EBIPP_BAL_GRP_OBJ_TYPE = TMP.BAL_GRP_OBJ_TYPE ,
DRV.EBIPP_BAL_GRP_OBJ_REV = TMP.BAL_GRP_OBJ_REV
------------------------------------------------- ,
DRV.EBIPP_RATE_OBJ_DB = TMP.RATE_OBJ_DB , DRV.EBIPP_RATE_OBJ_ID0 =
TMP.RATE_OBJ_ID0 , DRV.EBIPP_RATE_OBJ_TYPE = TMP.RATE_OBJ_TYPE ,
DRV.EBIPP_RATE_OBJ_REV = TMP.RATE_OBJ_REV
------------------------------------------------- , DRV.EBIPP_R EC_ID
= TMP.REC_ID ------------------------------------------------- ,
DRV.EBIPP_AMOUNT = TMP.AMOUNT , DRV.EBIPP_AMOUNT_DEFERRED =
TMP.AMOUNT_DEFERRED , DRV.EBIPP_AMOUNT_ORIG = TMP.AMOUNT_ORIG ,
DRV.EBIPP_DISCOUNT = TMP.DISCOUNT , DRV.EBIPP_GL_ID = TMP.GL_ID ,
DRV.EBIPP_IMPACT_CATEGORY = TMP.IMPACT_CATEGORY ,
DRV.EBIPP_IMPACT_TYPE = TMP.IMPACT_TYPE , DRV.EBIPP_PERCENT =
TMP.PERCENT , DRV.EBIPP_QUANTITY = TMP.QUANTITY , DRV.EBIPP_RATE_TAG =
TMP.RATE_TAG , DRV.EBIPP_RESOURCE_ID = TMP.RESOURCE_ID ,
DRV.EBIPP_RESOURCE_ID_ORIG = TMP.RESOURCE_ID_ORIG , DRV.EBIPP_TAX_CODE
= TMP.TAX_CODE , DRV.EBIPP_LINEAGE = TMP.LINEAGE ,
DRV.EBIPP_DISCOUNT_INFO = TMP.DISCOUNT_INFO , DRV.EBIPP_RUM_ID =
TMP.RUM_ID .
I somehow misplaced the explain plan. Sorry, I shouldn't have posted
this. I'm asking you guys to fly a plane without windows which isn't
very smart on my end.
You guys are right. Here's what I found out.
Looking at the AWR report closer I noticed a back ground wait event
that caught my eye that I missed before. The 'rdbms ipc message'
metric was too high. The event rdbms ipc message indicates that a
process is waiting for a message to arrive on his message queue. The
number of message blocks parameter was set too small. If a process
needs a message it will get the latch, search a linked list for a free
message block, unlink this message block , put this message on the
message queue for the intended process and then release this latch.
indicated If a process needs a message it will get the latch, search a
linked list for a free message block, unlink this message block , put
this message on the message queue for the intended process and then
release the latch. The event rdbms ipc message indicates that a
process is waiting for a message to arrive on his message queue. The
event rdbms ipc message reply is used to indicate that a message is
expected back by the sending process."
So....The process was pegging the CPU requesting a message block from
the LRU list in the SGA but ran into latch contention. The latch
contention also caused contention with the rollback process.
Steven, you really have to take it easy with acid. You should read your own messages once
you're clean, you'll see what I mean.