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

From: Ls Cheng <exriscer_at_gmail.com>
Date: Fri, 22 May 2015 22:54:38 +0200
Message-ID: <CAJ2-Qb9S==NkLXR=ETCW6vgow+y9uro1MKJCe+_yYeE2t9ETvQ_at_mail.gmail.com>



Hi Tim

What I say indefinite is really it can be huge not as CPU time, CPU time is always (or should be) number of cpu * elapsed time. If I have 600 users waiting for TX enqueue then I would have 2160000 seconds db time in a hour, if 700 users then 2520000, not sure if you know what I mean.

The recursive CPU I mean the one from user pl/sql calls not background processes, in
http://docs.oracle.com/cd/E18283_01/server.112/e17110/dynviews_3015.htm#G2030340 I dont see it say anything about pl/sql recursive cpu :-?

Regards

On Fri, May 22, 2015 at 5:17 PM, Tim Gorman <tim_at_evdbt.com> wrote:

> 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> 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 - 22:54:38 CEST

Original text of this message