Re: SQL causing 100% CPU utilization
From: ddf <oratune_at_msn.com>
Date: Wed, 4 May 2011 11:39:30 -0700 (PDT)
Message-ID: <9358502a-b7bb-41dc-bb1e-bfa1f6255217_at_34g2000pru.googlegroups.com>
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
Date: Wed, 4 May 2011 11:39:30 -0700 (PDT)
Message-ID: <9358502a-b7bb-41dc-bb1e-bfa1f6255217_at_34g2000pru.googlegroups.com>
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? Received on Wed May 04 2011 - 13:39:30 CDT