Re: Recursive CPU larger than total CPU used by the database

From: Tim Gorman <tim_at_evdbt.com>
Date: Fri, 22 May 2015 09:17:36 -0600
Message-ID: <555F4890.8030107_at_evdbt.com>

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-l

Received on Fri May 22 2015 - 17:17:36 CEST