RE: AWR reports DB CPU larger than total available CPU Time

  • From: Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
  • To: Oracle Mailinglist <oracle-l@xxxxxxxxxxxxx>
  • Date: Fri, 22 May 2015 07:02:25 +0000



This confirms that there's an accounting problem confusing the issue.

The comment about "pl/sql job" reminds me that there used to be some sort of
bug with the work done by procedures called by dbms_job that resulted in some
odd accounting problems. I don't remember any details, and the only vague
recollection is that it was a long time ago. (But 2 versions OOD is a long
time in Oracle !)

The large numbers for recursive calls is also points the finger towards
accounting problems - though of a different type: a very a large number of very
small activities can lead to a significant statistical error in the way
processes are deemed to have used CPU.


Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
@jloracle
________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx [oracle-l-bounce@xxxxxxxxxxxxx] on behalf
of Ls Cheng [exriscer@xxxxxxxxx]
Sent: 21 May 2015 23:55
To: Oracle Mailinglist
Subject: AWR reports DB CPU larger than total available CPU Time

Hi

I have a 10.2.0.5 database running in HPUX (this is not the one from
yesterday's post). Single instance.

Everyday around same time it reports more CPU consumed by the databsse than the
available CPU. The server has 2 CPU so in a 30 minutes AWR I would have maximum
3600 seconds CPU available but DB CPU reports 4735 seconds (but CPU used by
this session reported 2197 seconds and recursive CPU 3938 seconds). I thought
the server was loaded and the sessions spended time in the runqueue but after
enabling OSW I see the server is not as loaded to cause such problem.

Anyone know any reasons which can cuase such behaviour? There were a heavy
PLSQL job running during this time.


30 minutes AWR:

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 19422 21-May-15 19:00:12 145 34.3
End Snap: 19423 21-May-15 19:30:19 144 34.4
Elapsed: 30.12 (mins)
DB Time: 77.70 (mins)

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 4,664 100.0
--> larger than CPU used by this session
db file scattered read 35,087 128 4 2.7 User I/O
db file sequential read 88,266 68 1 1.5 User I/O
db file parallel write 14,112 11 1 0.2 System I/O
log file parallel write 1,184 5 4 0.1 System I/O

Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session 219,704 121.6 247.4
parse time cpu 503 0.3 0.6
recursive calls 848,316 469.4 955.3
recursive cpu usage 393,853 217.9 443.5

Operating System Statistics DB/Inst: CXS/CXS Snaps: 19422-19423

Statistic Total
-------------------------------- --------------------
AVG_BUSY_TIME 44,221
AVG_IDLE_TIME 136,437
AVG_IOWAIT_TIME 12,047
AVG_SYS_TIME 4,323
AVG_USER_TIME 39,870
BUSY_TIME 88,506
IDLE_TIME 272,945
IOWAIT_TIME 24,156
SYS_TIME 8,702
USER_TIME 79,804
LOAD 0
OS_CPU_WAIT_TIME 77,142,184,000
RSRC_MGR_CPU_WAIT_TIME 184
VM_IN_BYTES 3,133,440
VM_OUT_BYTES 966,656
PHYSICAL_MEMORY_BYTES 38,540,476,416
NUM_CPUS 2
NUM_CPU_SOCKETS 2


60 minutes AWR:

Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 19421 21-May-15 18:30:02 148 33.6
End Snap: 19423 21-May-15 19:30:19 144 34.4
Elapsed: 60.29 (mins)
DB Time: 113.36 (mins)

Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 6,799 100.0
--> larger than CPU used by this session
db file scattered read 52,279 200 4 2.9 User I/O
db file sequential read 121,610 98 1 1.4 User I/O
db file parallel write 19,131 27 1 0.4 System I/O
control file parallel write 1,453 13 9 0.2 System I/O

Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session 422,958 116.9 210.5
parse time cpu 1,071 0.3 0.5
recursive calls 2,861,080 791.0 1,424.1
recursive cpu usage 411,981 113.9 205.1

Operating System Statistics DB/Inst: CXS/CXS Snaps: 19421-19423

Statistic Total
-------------------------------- --------------------
AVG_BUSY_TIME 154,024
AVG_IDLE_TIME 207,367
AVG_IOWAIT_TIME 17,284
AVG_SYS_TIME 8,467
AVG_USER_TIME 145,499
BUSY_TIME 308,171
IDLE_TIME 414,852
IOWAIT_TIME 34,692
SYS_TIME 17,047
USER_TIME 291,124
LOAD 0
OS_CPU_WAIT_TIME 153,633,497,000
RSRC_MGR_CPU_WAIT_TIME 5,174
VM_IN_BYTES 14,221,312
VM_OUT_BYTES 1,642,496
PHYSICAL_MEMORY_BYTES 38,540,476,416
NUM_CPUS 2
NUM_CPU_SOCKETS 2


Thanks


Other related posts: