On DB Time, DB CPU and Utilization

DB Time/DB CPU

The "Load Section" of an AWR Report has two interesting lines

• DB Time(s)
• DB CPU(s)

Load Profile

This "Load Profile" is an AWR snapshot of 1h (60m/3600s). Look at the definitions of those metrics.

• DB Time is a time model statistic that is the sum of Oracle process CPU consumption and non-idle wait time
• DB CPU is Oracle server/foreground/shadow process CPU consumption  

(the above definitions are taken from an Orapub's Blog). Both of them are divided by "Elapsed Time" so they are an average on the snapshot interval.

Because of the definition of "DB Time", the "DB Time(s)" represent the Average Active Session on just one second.

"DB CPU(s)" tell us how many CPU are used in one second. You can compare this value with the number of CPU on your system, in order to understand if you are CPU bound.

In my example (from production system), the database is doing.....nothing: 1 active session each 2 seconds and a half (0.4 in 1s + 0,4 in 1s + 0.2 in 1/2s).

Also each 1s only 0.3 CPUs are used on 120 CPUs of the system (see next picture).

Utilization

How you can see from this Orapub post, the utilization is calculated as

• Utilization = Requirement / Capacity (a)

(a) capacity: the maximum amount that can be contained or accommodated

From our point of view

• The requirement is the time used 
• The capacity is the time available

so the previous formula became

• Utilization = time used / time available

You can calculate the utilization using two different methods. These methods are taken from Craig Shallahamer's Video Lessons.

1. Core method
2. Busy:Idle method

In order to explain these methods, I post another picture from AWR report

Operating System Statistics

Core method

With this method, requirement and capacity are:

Requirement =>  (v$osstat.)BUSY_TIME
Capacity => #CPU * Elapsed (Time)

In AWR report, the "BUSY_TIME" came from V$OSSTAT, while "Elapsed" is the "Elapsed Time" of snapshot and #CPU is the number of CPU on the system (the NUM_CPU column of V$OSSTAT)

Remember to normalize the numbers

Utilization = BUSY_TIME / Elapsed = (3336707/100) / (120*60*60)
Utilization = 33367.07 / 432000
Utilization = 0,077
Utilization = 7,7%

Because BUSY_TIME is in hundredths of seconds, I had divided the BUSY_TIME by 100. Also, the "Elapsed Time" in AWR report is in minutes, I multiplicated it for 60.


Busy:Idle method

With this method, requirement and capacity are:

Requirement =>  (v$osstat.)BUSY_TIME
Capacity => (v$osstat.)BUSY_TIME + (v$osstat.)IDLE_TIME

In this case, all information comes from the "Operating System Statistics" section of AWR Report.

Utilization = BUSY_TIME / (BUSY_TIME + IDLE_TIME)
Utilization = 3336707 / (3336707 + 39244501)
Utilization = 3336707 / 42581208
Utilization = 0,078
Utilization = 7,8%

In this case, all measurement was in hundredths of seconds so no further operations are needed.

The low utilization is a confirm of the very low Average Active Section shown in firs part of this post.

Reference

* http://blog.orapub.com/20130228/how-many-cpu-cores-do-i-really-have-in-my-oracle-database-server.html
* http://www.toadworld.com/platforms/oracle/b/weblog/archive/2014/05/26/understanding-cpu-utilization-amp-cpu-capacity
* http://blog.orapub.com/20140805/what-is-oracle-db-time-db-cpu-wall-time-and-non-idle-wait-time.html
* https://docs.oracle.com/database/122/REFRN/V-OSSTAT.htm#REFRN30321

SQL Profile: Case 3 - Part 1: Create/Execute/Report/Accept

Case 3: The statement is in AWR repository

In this scenario there are following steps:

(a) Find out the SQL_ID from DBA_HIST_SQLTEXT
(b) Check the execution plan
(c) Find out of the snapshot interval from DBA_HIST_SQLSTAT
(d) Create a task using the SQL_ID found in the previous step
(e) Run the task
(f) Show the recommendations
(g) Accept the recommendations

These steps are similar to the previous two (Case 1 and Case 2). The difference is that you have to look for the sql_id into DBA_HIST* tables.


Step a) Find out the SQL_ID into DBA_HIST_SQLTEXT table

set long 999999
set pages 99
SELECT 
      sql_id 
    , sql_text 
FROM 
      dba_hist_sqltext 
WHERE 
      regexp_like (SQL_TEXT, 'af_t_obj_spec','i') 
AND   regexp_like (SQL_TEXT, 'AF_T_OBJ t3','i');


SQL_ID
-------------
SQL_TEXT
--------------------------------------------------------------------------------
57fbbndr8f1r0
SELECT  AF_T_OBJ_SPEC.OBJ_SPEC_ID, AF_T_OBJ_SPEC.SHORT_NAME, AF_T_OBJ_SPEC.DESCR
IPTION, AF_T_OBJ_SPEC.DELETED, AF_T_OBJ_SPEC.LAST_VERSION, AF_T_OBJ_SPEC.OBJ_TYP
E_NAME, AF_T_OBJ_SPEC.LOCK_USER, AF_T_OBJ_SPEC.LOCK_LEASE_DATE, AF_T_OBJ_SPEC.LO
CK_SESSION, AF_T_OBJ_SPEC.LOCK_INSTANCE, AF_T_OBJ_SPEC.LIFECYCLE_UUID, AF_T_OBJ_
SPEC.INHERIT_PARENT_PRIVS, AF_T_OBJ_SPEC.OBJ_SPEC_UUID, AF_T_OBJ_SPEC.CREATED_BY
, AF_T_OBJ_SPEC.CREATED_DATE, AF_T_OBJ_SPEC.MODIFIED_BY, AF_T_OBJ_SPEC.MODIFIED_
DATE, AF_T_OBJ_SPEC.OWNER, AF_T_OBJ_SPEC.FEATURE_NAME, AF_T_OBJ_SPEC.CHECKSUM, A
F_T_OBJ_SPEC.INACTIVE, AF_T_OBJ_SPEC.SYSTEM_MANAGED, AF_T_OBJ_SPEC.FINAL_VERSION
, AF_T_OBJ_SPEC.SOURCE_ID, AF_T_OBJ.OBJ_ID, AF_T_OBJ.CHANGENUMBER, AF_T_OBJ.VERS
ION, AF_T_OBJ.INITIAL_COMMENT, AF_T_OBJ.STATUS_UUID, AF_T_OBJ.OBJ_UUID, AF_T_OBJ
.OBJ_SPEC_UUID AF_T_OBJ_OBJ_SPEC_UUID, AF_T_OBJ.CREATED_BY AF_T_OBJ_CREATED_BY,
AF_T_OBJ.CREATED_DATE AF_T_OBJ_CREATED_DATE, AF_T_OBJ.MODIFIED_BY AF_T_OBJ_MODIF
IED_BY, AF_T_OBJ.MODIFIED_DATE AF_T_OBJ_MODIFIED_DATE, AF_T_OBJ.OBJ_DEFINITION ,
 rownum FROM AF_T_OBJ_SPEC, AF_T_OBJ WHERE AF_T_OBJ_SPEC.OBJ_SPEC_UUID =AF_T_OBJ
.OBJ_SPEC_UUID  AND   AF_T_OBJ_SPEC.DELETED = 0   AND  AF_T_OBJ.VERSION = (SELEC
T MAX(VERSION) FROM AF_T_OBJ t3 where AF_T_OBJ.OBJ_SPEC_UUID = T3.OBJ_SPEC_UUID)
  AND  EXISTS (SELECT 0 FROM AF_L_LIFECYCLE_STATUS WHERE AF_L_LIFECYCLE_STATUS.S
TATUS_UUID = AF_T_OBJ.STATUS_UUID AND AF_L_LIFECYCLE_STATUS.LIFECYCLE_UUID = AF_
T_OBJ_SPEC.LIFECYCLE_UUID AND AF_L_LIFECYCLE_STATUS.STATUS_NAME  in (:1 ,:2 ))
AND  AF_T_OBJ.VERSION = (SELECT MAX(VERSION) FROM AF_T_OBJ t3 where AF_T_OBJ.OBJ
_SPEC_UUID = T3.OBJ_SPEC_UUID)  AND  AF_T_OBJ_SPEC.OBJ_TYPE_NAME in (:3 ) ORDER
BY  AF_T_OBJ_SPEC.DESCRIPTION

Step b) Check the execution plan

SELECT * FROM TABLE (DBMS_XPLAN.DISPLAY_AWR('&sqlid'));

Enter value for sqlid: 57fbbndr8f1r0
old   1: SELECT * FROM TABLE (DBMS_XPLAN.DISPLAY_AWR('&sqlid'))
new   1: SELECT * FROM TABLE (DBMS_XPLAN.DISPLAY_AWR('57fbbndr8f1r0'))

You can find the output here (the database I using, is a two node RAC and I run the commands on the first instance (*)). For this sql_id there are 4 execution plans (*):

Plan hash value: 333756168
Plan hash value: 934906073
Plan hash value: 2303425470
Plan hash value: 2773806998

If you want, at this point, you could choose one of the previous plan_hash_value and you could set it for the SQL Profile. 

But what I want is that SQL Advisor analyze the statement for me, so I go to the "Step c"


Step c) Find out a snapshot interval from DBA_HIST_SQLSTAT

set lines 210 
set pages 99 
SELECT min(snap_id), max(snap_id) FROM DBA_HIST_SQLSTAT WHERE sql_id ='&sqlid';

Enter value for sqlid: 57fbbndr8f1r0
old   1: SELECT min(snap_id), max(snap_id) FROM DBA_HIST_SQLSTAT WHERE sql_id ='&sqlid'
new   1: SELECT min(snap_id), max(snap_id) FROM DBA_HIST_SQLSTAT WHERE sql_id ='57fbbndr8f1r0'
MIN(SNAP_ID) MAX(SNAP_ID)
------------ ------------
        4944         5118

The details about sql_id into DBA_HIST_SQLSTAT are:

select 
      snap_id
    , sql_id
    , plan_hash_value 
from 
      dba_hist_sqlstat 
where 
      sql_id='57fbbndr8f1r0' 
order by 
      snap_id;

   SNAP_ID SQL_ID        PLAN_HASH_VALUE
---------- ------------- ---------------
      4944 57fbbndr8f1r0      2303425470
      4944 57fbbndr8f1r0       333756168
      4944 57fbbndr8f1r0      2773806998
      5117 57fbbndr8f1r0      2303425470
      5117 57fbbndr8f1r0       333756168
      5117 57fbbndr8f1r0      2773806998
      5118 57fbbndr8f1r0       333756168
      5118 57fbbndr8f1r0       934906073  <<< see (*) <<<
      5118 57fbbndr8f1r0      2773806998



Step d) Create the task, using the SQL_ID 


With these snap_id, I can create a task and get recommendations

DECLARE
   task_name VARCHAR2(30);
BEGIN
    task_name := DBMS_SQLTUNE.CREATE_TUNING_TASK(
      begin_snap=> &s_snapid
    , end_snap=> &e_snapid
    , sql_id => '&sqlid'
    , scope => 'COMPREHENSIVE'
    , time_limit => 90 -- nr of seconds of analysis 
    , task_name => 'task_&sqlid'
    , description => 'Task to tune a query on a specified table');
END;
/

Enter value for s_snapid: 4944
old   5:       begin_snap=> &s_snapid
new   5:       begin_snap=> 4944
Enter value for e_snapid: 5118
old   6:     , end_snap=> &e_snapid
new   6:     , end_snap=> 5118+1
Enter value for sqlid: 57fbbndr8f1r0
old   7:     , sql_id => '&sqlid'
new   7:     , sql_id => '57fbbndr8f1r0'
old  10:     , task_name => 'task_&sqlid'
new  10:     , task_name => 'task_57fbbndr8f1r0'

In this case, I chose to analyze the whole range, but I could choose just a part of it.


Step e) Run the task in order to analyze the statement

BEGIN
    DBMS_SQLTUNE.EXECUTE_TUNING_TASK(task_name =>'task_57fbbndr8f1r0');
END;
/


Step f) Show the recommendations

set long 40000
set longchunksize 1000
set linesize 210
set heading off
set pages 0
SELECT DBMS_SQLTUNE.REPORT_TUNING_TASK('task_57fbbndr8f1r0') from DUAL;
set heading on
set pages 99


The output is here. The Advisor found 3 improvements:

1- SQL Profile Finding
2- Index Finding
3- Alternative Plan Finding (*)

Also, you could query the data dictionary to get information:

SELECT
    finding_id
  , message
FROM
    dba_advisor_findings 
WHERE
    task_name='task_57fbbndr8f1r0';

FINDING_ID MESSAGE
---------- -----------------------------------------------------------------------------------------------
         1 A potentially better execution plan was found for this statement.
         2 The execution plan of this statement can be improved by creating one or more indices.
         3 Some alternative execution plans for this statement were found by searching the system's 
           real-time and historical performance data.


For the 3th point, the "Alternative Plan Findings" see below notes.

Step g) Accept the recommendations 

If you want to accept the profile, then you have to run (see the log):

execute dbms_sqltune.accept_sql_profile( - 
    task_name =>'task_57fbbndr8f1r0' -
  , task_owner => 'SYS' -
  , replace => TRUE);

Step h) Optionally, you can drop the TASK

exec DBMS_SQLTUNE.DROP_TUNING_TASK ('&task_name')


Step i) Optionally, you can drop the SQL Profile


exec DBMS_SQLTUNE.DROP_SQL_PROFILE ('&sqlprofile_name')


(*) Notes

From AWR repository (DBA_HIST_SQLSTAT), you can see that there are 4 palns hash value for the 57fbbndr8f1r0 statement. They are

333756168
934906073
2303425470
2773806998

Anyway, SQL Advisor, in its analysis, doesn't consider the plan value nr 934906073. In the log, in the "Alternative Plan Finding" section, in fact, you see:

3- Alternative Plan Finding
---------------------------
  Some alternative execution plans for this statement were found by searching the system's real-time and historical performance data.

  The following table lists these plans ranked by their average elapsed time.
  See section "ALTERNATIVE PLANS SECTION" for detailed information on each plan.

  id plan hash  last seen            elapsed (s)  origin          note
  -- ---------- -------------------- ------------ --------------- ----------------
   1 2303425470  2017-05-09/16:41:30        0.096 Cursor Cache
   2  333756168  2017-05-09/16:41:30        0.122 Cursor Cache
   3 2773806998  2017-05-09/16:41:29        0.132 Cursor Cache

All statements are taken from the memory (Cursor Cache). This is why the plan 934906073 is not found: it is in the second instance:

select 
      inst_id
    , plan_hash_value
from 
      gv$sql 
where 
      sql_id='57fbbndr8f1r0' 
order by inst_id;

   INST_ID PLAN_HASH_VALUE
---------- ---------------
         1       333756168
         1      2303425470
         1      2773806998
         2       333756168
         2       934906073 <<< instance nr 2
         2      2773806998

If you want to find suggestions about plan hash value 934906073, you have to run DBMS_SQLTUNE.EXECUTE_TUNING_TASK, (Step e), on the second instance. Here is the log. This is the section about "Alternative Plan Finding":

  id plan hash  last seen            elapsed (s)  origin          note

  -- ---------- -------------------- ------------ --------------- ----------------

   1 2773806998  2017-05-09/17:06:12        0.064 Cursor Cache

   2  934906073  2017-05-09/17:06:12        0.120 Cursor Cache <<< here

   3  333756168  2017-05-09/17:01:38        0.123 Cursor Cache

Well. This is how "SQL Tuning Advisor" works. I opened a SR for this and the support told me:

If plans are cached in memory the STA Tuning Task will take the info from cursor cache for performance.

So. The behavior of SQL Tuning Advisor, if used against AWR repository is:

* Providing SQL Profile suggestion: "Finding Section" (1st finding)
* Providing suggestion with index: "Index Finding" (2nd finding)
* Providing alternative solutions: "Alternative Plan Finding" (3rd finding)

About the last point (the 3rd), the alternative solutions are took form memory.