Skip to Main Content

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, John.

Asked: January 09, 2016 - 2:18 pm UTC

Last updated: August 21, 2016 - 8:24 am UTC

Version: 11.2

Viewed 10K+ times! This question is

You Asked

Good Saturday Morning, Gentlemen.

I am getting ready to give a talk to a local Oracle User's group. One item that I plan to discuss with the club is the Time Model. I have a few questions that will help me understand it better.

Where will the following "FOREGROUND EVENTS" times be added to within the Time Model. Will they be added to DB Wait Time or DB CPU TIME?

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Tota Wait % DB
Event Waits Time Avg(ms) time Wait Class
------------------------------ ------------ ---- ------- ------ ----------
DB CPU 228. 80.7
log file sync 72,179 64.9 1 22.9 Commit
Disk file operations I/O 19,227 .2 0 .1 User I/O
SQL*Net message to client 135,169 .1 0 .0 Network
control file sequential read 5,184 0 0 .0 System I/O
buffer busy waits 11 0 0 .0 Concurrenc
latch: In memory undo latch 8 0 0 .0 Concurrenc
latch: cache buffers chains 2 0 0 .0 Concurrenc
ADR block file read 0 0 .0 Other
ADR block file write 0 0 .0 Other


And the second question is this. Here is the formula for DB Time. DB Time = DB CPU + DB WAITS.
I encountered this situation where the math is just way off. 1,045 = 3097!

Statistic Name Time (s) % of DB Time
------------------------------------------ ------------------ ------------
DB CPU 1,040 99.5
sql execute elapsed time 1,041 99.6
parse time elapsed 1,014 97.0
failed parse elapsed time 1,041 99.6
hard parse elapsed time 1,016 97.2
DB time 1,045
background elapsed time 391.9
background cpu time 195.4
------------------------------------------------------

Finally, if DB Time Model only includes foreground activity why did Oracle decide to add "background" information in the Time Model views?

Thanks,

John

and Connor said...

"Where will the following FOREGROUND EVENTS times be added to within the Time Model. Will they be added to DB Wait Time or DB CPU TIME?"

They will be DB Wait Time. If (for example) you run:

select session_state, event, count(*)
from v$active_session_history
where session_type = 'FOREGROUND'
group by session_state, event

You'll see that when something is "ON CPU" there is not an event.

"I encountered this situation where the math is just way off. 1,045 = 3097!"

Sorry - I cant see where the 3097 came from ? I can see that DB Time was 1045, and 1040 of that was CPU.


"if DB Time Model only includes foreground activity why did Oracle decide to add "background" information in the Time Model views"

If my "DB CPU" is 1000 seconds...what does that tell me ? Is it 10% of the total ? or 99% of the total ? I can get that information by having the background info there, ie,

Total = DB + background

thus

DB % = DB / ( DB + background)

There are some subtleties with examining the time model data (some rows are 'children' of others etc). Some good info here - its a touch out of data, but still worth a read:

https://hoopercharles.wordpress.com/2010/01/13/working-with-oracle-time-model-data/



Rating

  (7 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Let me try to make question 2 clear.

John Cantu, January 21, 2016 - 11:05 pm UTC

Thank you for answer the question 1 and 3.
Let me try to make question 2 clear.

The formula for DB Time is:

DB Time = DB CPU + DB WAITS.

The equation then is:

DB Time = DB CPU + (sql execute elapsed time + parse time elapsed + others)

Here I extract the values from the example provided in my first posting:
DB Time = 1,045
DB CPU = 1,040
sql execute elapsed time (wait event 1) = 1,041
parse time elapsed (wait event 2) = 1014

Next, I place the values on the equation:

1,045 != 1040 + (1041 + 1014)

The numbers on both sides of the equation don't add up. Why is that?

Aren't "parse time elapsed" and "SQL execute elapsed time" both wait times that should be summed up?

Thanks for your help!


Connor McDonald
January 22, 2016 - 1:35 am UTC

These are not additive, they are proportions of the total.

For example

SQL> exec dbms_workload_repository.create_snapshot

PL/SQL procedure successfully completed.

SQL> set timing on
SQL> select count(*)
  2  from
  3   ( select 1 from dual connect by level <= 10000 ),
  4   ( select 1 from dual connect by level <= 100000 )
  5  /

  COUNT(*)
----------
1000000000

Elapsed: 00:00:29.53
SQL> host sleep 30

SQL> exec dbms_workload_repository.create_snapshot

PL/SQL procedure successfully completed.


So I have a snapshot spanning a minute, and for 30 seconds I belted the database CPU. The AWR info comes out:

Statistic Name Time(s) % of DB Time
DB time 30.03
DB CPU 29.48 98.17
sql execute elapsed time 29.97 99.79

So you can see

a) almost all of the DB time was DB CPU (as we expected).
b) almost all of the DB time was sql execution (as we expected)

Hope this helps

Perfect! Almost there!

John Cantu, January 22, 2016 - 2:07 pm UTC

Hello Conner,

You have made it quite clear now. The formula provided for DB Time is either wrong or grouping of time model statistics can also include "DB CPU": http://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_3015.htm#REFRN30340

This is the formula that I was provided by Oracle training:

DB Time= DB CPU + NONIDLE Wait Events


They also provide this figure:
#################DB TIME##################
----------------------------------------->|
###DB CPU####|############################|
------------>|############################|
#############|#######DB WAITS#############|
#############|--------------------------->|

As you can see in the figure above, I was given the impression that time can only either be DB CPU or DB WAITS, which is the case. Right?
Also, I was under the impression that "SQL execute elapsed time" was only "DB Waits" and would not contain "DB CPU."

I assumed that Oracle was breaking it up for us. Using your example, if DB CPU= 29.48 and DB TIME= 30.03, that would tell me that "sql execute elapsed time" plus all other statistics must equal less than .51 seconds.

My conclusion is that time model statistics like "SQL execute elapsed time", "SQL Load elapsed time", etc., also contains the DB CPU time in there. This means that Oracle isn't extracting the DB CPU time from this new grouping of wait events called "SQL execute elapsed time" or "parse time elapsed time" or "connection management elapsed time". Is that right, Connor?



Chris Saxon
January 23, 2016 - 3:07 am UTC

db time = db cpu + non idle waits .... YES

'sql elapsed time' = time to run SQL (which will be both CPU and I/O, ie, a wait)

See my other followup - we are presenting things like parse time as *components* of DB Time to assist with diagnosis.

Hope this helps.

not a wait event and not a statistic

John Cantu, January 22, 2016 - 10:38 pm UTC

Hello Connor,

So what do we call these new entries:

"sql execute elapsed time"
"parse time elapsed"

They are not wait events since they are not listed in v$event_name. It is also not a statistic since they are not listed in v$statname;

Thanks!
Connor McDonald
January 23, 2016 - 3:05 am UTC

They are components of DB Time - they are provided in the report to help you diagnose issues.

eg DB Time = 100, parse time elapsed = 100
=> you've got a parsing problem

eg DB Time = 100, parse time elapsed = 1
=> you've NOT got a parsing problem

eg DB Time = 100, sql execute elapsed = 100
=> All of your workload was SQL (might be good thing, might be bad thing)

eg DB Time = 100, sql execute elapsed = 10
=> 90 seconds was burned elsewhere (eg, look for poor PL/SQL code etc)

Hope this helps.

PERFECT UNDERSTANDING NOW!

John Cantu, January 23, 2016 - 5:49 pm UTC

Thanks, Connor. Now I completely understand!
Connor McDonald
January 24, 2016 - 1:34 am UTC

Good luck with the talk - nice to see people contributing to their user groups.

How does plsql and sql execution time relate?

Andy Haack, July 24, 2016 - 1:08 pm UTC

Hi Connor,

the relationship between sql and pl/sql execution time is actually still not clear to me as the Oracle documentation shows following inclusion hierarchy:
1) DB time
    2) connection management call elapsed time
    2) sequence load elapsed time
    2) sql execute elapsed time
    2) parse time elapsed
          3) hard parse elapsed time
                4) hard parse (sharing criteria) elapsed time
                    5) hard parse (bind mismatch) elapsed time
          3) failed parse elapsed time
                4) failed parse (out of shared memory) elapsed time
    2) PL/SQL execution elapsed time
    2) inbound PL/SQL rpc elapsed time
    2) PL/SQL compilation elapsed time
    2) Java execution elapsed time
    2) repeated bind elapsed time

Robin Schumacher's post however, http://www.oracle.com/technetwork/articles/schumacher-analysis-099313.html substracts plsql from sql time "... when 'sql execute elapsed time' then time_secs - plsql_time ..." which would correspond to this hierarchy instead:
1) DB time
    2) connection management call elapsed time
    2) sequence load elapsed time
    2) sql execute elapsed time
          3) PL/SQL execution elapsed time
    2) parse time elapsed
          3) hard parse elapsed time
                4) hard parse (sharing criteria) elapsed time
                    5) hard parse (bind mismatch) elapsed time
          3) failed parse elapsed time
                4) failed parse (out of shared memory) elapsed time
    2) inbound PL/SQL rpc elapsed time
    2) PL/SQL compilation elapsed time
    2) Java execution elapsed time
    2) repeated bind elapsed time

So which one is right? Looking at the figures on our server with significant plsql execution time, the numbers seem to stack up (add up more or less to DB time) in the latter version only.
Or are maybe both right, depending if plsql is called separately or from functions used in sql?

Thanks,

Andy
Connor McDonald
August 19, 2016 - 3:31 am UTC

Apologies for taking so long to respond.

Here's a little test case - we'll burn ~2mins30sec of database cpu, being 90 seconds of PLSQL and 60 seconds of SQL. Then we can take a look at the AWR report

SQL> declare
  2    x int;
  3    y date := sysdate;
  4  begin
  5    dbms_output.put_line(to_char(sysdate,'HH24MISS')||'-block commenced');
  6    while ( sysdate - y ) < 90/86400
  7    loop
  8       for i in 1000 .. 10000 loop
  9          x := sqrt(i);
 10       end loop;
 11    end loop;
 12    dbms_output.put_line(to_char(sysdate,'HH24MISS')||'-nonsql completed');
 13
 14    select count(*)
 15    into x
 16    from dba_objects,
 17      ( select 1 from dual connect by level <= 10000 );
 18    dbms_output.put_line(to_char(sysdate,'HH24MISS')||'-sql completed');
 19  end;
 20  /
112141-block commenced
112311-nonsql completed
112407-sql completed

PL/SQL procedure successfully completed.

Elapsed: 00:02:26.30


I took awr snapshots immediately before and after, and here's snippets of the report

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:      5390 19-Aug-16 11:21:35        46       1.6
  End Snap:      5391 19-Aug-16 11:24:07        46       1.7
   Elapsed:                2.54 (mins)
   DB Time:                2.47 (mins)


                                                                % of  % of Total
Statistic Name                                       Time (s) DB Time   CPU Time
------------------------------------------ ------------------ ------- ----------
sql execute elapsed time                                148.0   100.0
DB CPU                                                  126.1    85.2       99.0
PL/SQL execution elapsed time                            90.0    60.8


Hope this helps.

How does plsql and sql execution time relate?

Rajeshwaran Jeyabal, August 19, 2016 - 7:48 am UTC 

112141-block commenced
112311-nonsql completed
112407-sql completed


Working on this

nonsql execution time is = ( 11:23:11 - 11:21:41 ) = 1min 30sec = 90sec
sql completed is = ( 11:24:07 - 11:23:11 ) = 56sec

the nonsql execution time matches with "PL/SQL execution elapsed time" in AWR
but the sql execution time doesn't match with AWR "sql execute elapsed time" - Is that i am misinterpreting something here ?


% of  % of Total
Statistic Name                                       Time (s) DB Time   CPU Time
------------------------------------------ ------------------ ------- ----------
sql execute elapsed time                                148.0   100.0
DB CPU                                                  126.1    85.2       99.0
PL/SQL execution elapsed time                            90.0    60.8

Connor McDonald
August 20, 2016 - 3:17 am UTC

Even though this is my laptop database, there's presumably a reasonable amount of activity going on in the background...and of course, the taking of the snapshots themselves.

More details

Gh, August 20, 2016 - 7:27 am UTC

Hello
"eg DB Time = 100, sql execute elapsed = 100
=> All of your workload was SQL (might be good thing, might be bad thing) "

When it's good and when it's bad?
Could you explain by one or two examples?
Connor McDonald
August 21, 2016 - 8:24 am UTC

Good thing example:

select /*+ parallel */ fiscal_year, count(*)
from my_warehouse_table
where customer_id = 123
group by fiscal_year

that runs for 15mins, scanning billions of rows to answer an analytics style question, can give you a 15min awr snapshot which is full of sql execution time.

Bad thing example:

update customer_accounts
set balance = 1000
where customer_id = 123

Should be a fast one row update, but it runs for 15mins because its blocked on a lock from another session. Indicative of poor transaction management.


more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.