RE: Recursive CPU larger than total CPU used by the database
Date: Fri, 22 May 2015 16:54:06 +0000
Message-ID: <CE70217733273F49A8A162EE074F64D92828F238_at_EXMBX01.thus.corp>
Tim,
DB time can reach (sessions - few) * Elapsed time You're thinking of the limit of DB CPU being CPU Count * Elapsed time.
The manual page for v$sys_time_model doesn't really say much about recursive CPU, but whatever else, we should expect (recursive CPU) <= (DB CPU + background CPU), and it would be alittle surprising to see background CPU becoming extremely large unless, I suppose but can never remember, dbms_job/dbms_scheduler makes all of the jobs report as background work.
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
_at_jloracle
From: oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] on behalf of Tim Gorman [tim_at_evdbt.com] Sent: 22 May 2015 16:17
To: Ls Cheng
Cc: Oracle Mailinglist
Subject: Re: Recursive CPU larger than total CPU used by the database
Interesting concept: how can "DB Time" be infinite? Does that also mean that we will all live forever? :-)
Thought exercise: what might cause "DB Time" to exceed "ElapsedTime * #CPUs"?
As far as "recursive CPU time" exceeding "DB CPU" being shocking, please note that those two particular metrics come from different sources within Oracle, thus are captured differently, which is one reason they're not reported in the same section of an AWR report. Please also note that "recursive CPU time" is not a component of "DB CPU", according to Oracle 11g documentation found online here<http://docs.oracle.com/cd/E18283_01/server.112/e17110/dynviews_3015.htm#G2030340>. One thing to consider as well is that measuring recursion could reasonably lead to double- and triple-counting.
From a practical standpoint, please bear in mind that statistics like "recursive CPU time" (visible in V$SYSSTAT) are updated only at the conclusion of an operation, while metrics like "DB CPU" (visible in V$SYS_TIME_MODEL) are updated every few seconds. Comparing info from V$SYSSTAT against V$SYS_TIME_MODEL can yield different outcomes depending on when one queries and also whether operations have completed or not.
On 5/22/15 1:18, Ls Cheng wrote:
Hi Tim
There are 2 CPU in the server, it's a dedicated server so only the database is running.
You mean maximum DB CPU is 1800*CPU_COUNT and not DB Time right? Because DB Time can be infinite.
What it is shocking to me is total cpu time is less than recursive cpu time. I noticed this because I was graphing AWR data and noticed strange spikes.
Thanks!
On Fri, May 22, 2015 at 1:02 AM, Tim Gorman <tim_at_evdbt.com<mailto:tim_at_evdbt.com>> wrote: LS,
Think "resource time" not "elapsed time".
How many CPU cores were available during the 1800 seconds (30 minutes)?
The maximum theoretical amount of available "DB Time" in seconds for that 30 minute period is "CPU_COUNT * 1800".
Hope this helps...
-Tim
On 5/21/15 16:27, Ls Cheng wrote:
Hi
This is today's 30 minutes AWR, it reported 1961 DB CPU seconds and 2519 recursive CPU seconds
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 17166 21-May-15 22:00:12 206 30.9
End Snap: 17167 21-May-15 22:30:19 201 29.5
Elapsed: 30.11 (mins)
DB Time: 32.42 (mins)
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 1,961 100.8
db file sequential read 204,583 356 2 18.3 User I/O
Datapump dump file I/O 173,270 206 1 10.6 User I/O
db file scattered read 69,775 172 2 8.8 User I/O
log file parallel write 3,045 9 3 0.5 System I/O
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session 116,102 64.3 46.0
parse time cpu 1,362 0.8 0.5
recursive calls 2,346,502 1,299.0 929.7
recursive cpu usage 251,943 139.5 99.8
ASH DBTime:
SELECT session_id, session_state, event,
count(*) DBTime,
sum(count(*)) over () total_dbtime
FROM v$active_session_history
WHERE sample_time >= to_date('20150521 2200', 'yyyymmdd hh24mi') AND sample_time < to_date('20150521 2230', 'yyyymmdd hh24mi') GROUP BY session_id, session_state, event ORDER BY count(*) desc;
SESSION_ID SESSION EVENT DBTIME TOTAL_DBTIME
---------- ------- ------------------------------ ---------- ------------
314 ON CPU 683 950 --> DBMS_STATS JOB
313 ON CPU 38 950
470 ON CPU 30 950
346 ON CPU 25 950
551 WAITING log file parallel write 13 950
524 ON CPU 10 950
400 ON CPU 9 950
408 ON CPU 9 950
364 ON CPU 9 950
552 WAITING db file parallel write 8 950
439 ON CPU 7 950
494 ON CPU 4 950
.................................
ASH Top SQL:
SELECT sql_id,
count(*) DBTime,
sum(count(*)) over () total_dbtime
FROM v$active_session_history
WHERE sample_time >= to_date('20150521 2200', 'yyyymmdd hh24mi') AND sample_time < to_date('20150521 2230', 'yyyymmdd hh24mi') AND session_id = 314
GROUP BY sql_id
ORDER BY count(*) desc;
SQL_ID DBTIME TOTAL_DBTIME
------------- ---------- ------------
ayqtcdfc0j2jq 294 685 g3wqa8fkdrsh0 76 685 b1zwcs9bjfdx3 54 685 ga4ca5u6v2yzc 34 685 1a5xk5qrznhpd 30 685 696n8nucg003x 21 685 d8p6spwhn2uy3 21 685 4m18tcchz46tp 16 685 5k3uu413rnrqr 13 685 5mss4v7zkx4ny 8 685 6fp83b3yxdk8t 6 685 azsp79mtbt2ns 5 685 .................................
This from last week where it reported 866 DB CPU and 1967 recursive CPU seconds
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 16734 12-May-15 22:00:38 187 31.6
End Snap: 16735 12-May-15 22:30:45 181 30.0
Elapsed: 30.11 (mins)
DB Time: 14.20 (mins)
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time 866 101.7
db file sequential read 203,877 365 2 42.8 User I/O
Datapump dump file I/O 166,829 218 1 25.6 User I/O
db file scattered read 26,079 91 3 10.7 User I/O
log file parallel write 2,792 10 4 1.2 System I/O
Statistic Total per Second per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session 62,592 34.7 27.2
parse time cpu 1,396 0.8 0.6
recursive calls 1,317,943 729.5 572.0
recursive cpu usage 196,759 108.9 85.4
Thanks
-- http://www.freelists.org/webpage/oracle-lReceived on Fri May 22 2015 - 18:54:06 CEST