Re: SQL causing 100% CPU utilization

From: Steven Holland <smith.h.steven_at_gmail.com>
Date: Tue, 10 May 2011 05:10:18 -0700 (PDT)
Message-ID: <77e313d3-d95f-465d-b286-2940bf894012_at_l14g2000pro.googlegroups.com>



On May 4, 11:39 am, ddf <orat..._at_msn.com> wrote:
> On May 4, 9:53 am, Steven Holland <smith.h.ste..._at_gmail.com> wrote:
>
>
>
>
>
> > I have a problem SQL statement that our DBA's, Orace support nor
> > myselfI cannot fix.  Believe me, I've tried everything. It takes 3
> > hours to run and it's all CPU time.   The offending sqlid is
> > '8m5dd8aqw4ka8'.  Here's part of the AWR report.  It's too big for
> > this but I can email it to anyone who needs it.
>
> > 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.23Physical 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
>
> Could you possisbly post the query and the plan?- Hide quoted text -
>
> - Show quoted text -

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. Received on Tue May 10 2011 - 07:10:18 CDT

Original text of this message