A Fresh Look at AWR Reports -- 2 : Redo Size

 In my previous blog post, I showed how to interpret CPU Usage from an AWR report.

Here, I take the same 2hour AWR report and help interpret Redo Size -- ie. volume of Redo Generated and Written to Disk.

Here's the header which indicates that this AWR report is for duration of 2hours on 19c on Windows :

These are the first few lines of the Load Profile :

This indicates that the Redo Size (total Redo Generated) is just about 10GB  (multiply Redo Size bytes per Second by the total elapsed seconds (120.71) minutes)

I can confirm that from the Key Instance Activity Stats section :

So, did my database write about 10GB (about 9.8GB actually, if you divide by 1024s) of Redo to disk ?   Is that true ?

Let me go to the IOStat(s) section.  (Please ignore the "average service time" in this table because I've run this test on a PC with a standard Hard-Disk -- not an Enterprise SAN !)

What do I see here ?  The total volume written to Log Files (i.e. Online Redo Logs) is 19GB !

Why is that so ?

Because, in my database, every Redo Log Group is duplexed -- it has 2 members.  So, Redo of approximately 9.8GB actually translates to 19GB (or close to 20GB) of Physical Writes to Online Redo Log files.

Note that there are 10GB of Reads from  the Online Redo Log files.  That is the Log Archiver Process(es) writing out the Online Redo Logs to the Archive Logs -- which you can see is 10GB of Writes to Archive Log !

Thus, the initial "Redo Size" of 10GB is actually 30GB of Physical Writes to Disk (20GB for Duplexed Online Redo Logs  PLUS 10GB of Archive Logs).

If I had defined an additional ArchiveLogDestination on my server (as I have done in previous implementations where dedicated disks or NFS mount points were assigned), there would have been another 10GB of Physical Writes.

For every Standby Database (note how in previous blog posts here and here , I have demonstrated 3 separate Standby Databases for the Primary Database), 10GB of Redo has to be transferred over the Network and then written to the Standby Redo Logs at each Standby Site/Server.

So, my 10GB of Redo could effectively translate to anywhere from 30GB to 70GB of Physical Write of Redo  Plus 10GB to 30GB of transfer over the network !!

When you look at the SAN or underlying storage, you must consider how all those writes get through.  Does the SAN have enough Write-Through Cache ?  Are those Redo Logs and the one or more ArchiveLogDestination(s) on the Primary Server  actually on separate Disks  -- you might have separate FileSystem MountPoints or ASM DiskGroups but how do they translate down to the Disks in the SAN ?

A Fresh Look at AWR Reports -- 1 : CPU Usage

 I have covered AWR Reports (from 10g to 12c, including MultiTenant) in the past.  You could search for "AWR" in the "Search this Blog" in the panel on the right or by specifying :   
site://hemantoracledba.blogspot.com AWR
in the Google Search Window

In this post I present a comparison between OS and Oracle CPU Statistics.

So, I have an AWR Report for 19c on Windows for a duration of 120minutes with 12 CPUs.  That is a total of 86,400 available CPU seconds (120minutes X 12 CPUs X 60seconds_per_minute)

The Load Profile shows 0.4 Oracle CPU seconds per Elapsed Seconds.  This means that, on average, I am consuming less than 1 CPU.

Oracle Database CPU time is 13.5% of total Oracle Time.  This is 1,918 seconds.

Note very carefully that this does NOT mean that the Oracle Database Processes account for 13.5% of Server CPU Usage.

This shows that the Server reports 24% CPU Usage but Oracle used only 2.4% of the total CPU available (approximately 2.4% of 86,400seconds is 2,073seconds close to Oracle's DB CPU figure)

This also translates about 9% of the total actual CPU "busyness" on the Server.

So, if Oracle consumed only 9% of the actual CPU Usage on the server, I would need to look for other processes on the same server that would have been consuming CPU.  

This could be other Oracle Database Instances (my report is for database instance "CDB1" -- was there / were there one or more other Database Instances active on the same server ?).  This could also be non-Oracle programs, Application Server software,  other system / monitoring tools running (I've seen monitoring tools alone consuming 20% of the CPU on a server !).

If this server is hosting only this 1 Database Instance (CDB1), it is excessively provisioned (12 CPUs) for the actual load.  Of course, the load that I have generated here is I/O intensive, but it means that I could have actually reduced the number of CPUs to, say, 4 CPUs and paid much less in Hardware, Oracle Licensing and Oracle Support costs.  (4 CPUs would have allowed for the OS and the other non-Oracle processes that seem to be accounting for 24% user-time of 12 CPUs).

SQL Execution Statistics -- 4 : Adaptive Plans

In the previous 3 blog posts, I have shown how you can use the GATHER_PLAN_STATISTICS Hint or the STATISTICS_LEVEL='ALL' to get sql execution statistics.

This may work with Adaptive Plans as well.

SQL> select /*+ gather_plan_statistics */ count(*)
  2  from tables_list t
  3  where (owner, table_name)
  4  not in
  5  (
  6   select owner, table_name
  7   from indexes_list i
  8  )
  9  /

  COUNT(*)
----------
       593

SQL> select * from table(dbms_xplan.display_cursor('',format=>'ALLSTATS LAST +COST +ADAPTIVE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  g6q8m94krdvz7, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from tables_list t where
(owner, table_name) not in (  select owner, table_name  from
indexes_list i )

Plan hash value: 2460844421

---------------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                | Name               | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT         |                    |      1 |        |    11 (100)|      1 |00:00:00.01 |      37 |       |       |          |
|     1 |  SORT AGGREGATE          |                    |      1 |      1 |            |      1 |00:00:00.01 |      37 |       |       |          |
|  *  2 |   HASH JOIN ANTI         |                    |      1 |     22 |    11   (0)|    593 |00:00:00.01 |      37 |  1335K|  1335K| 1376K (0)|
|-    3 |    NESTED LOOPS ANTI     |                    |      1 |     22 |    11   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|-    4 |     STATISTICS COLLECTOR |                    |      1 |        |            |   2202 |00:00:00.01 |      17 |       |       |          |
|     5 |      INDEX FAST FULL SCAN| TABLES_LIST_NDX    |      1 |   2202 |     5   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|- *  6 |     INDEX RANGE SCAN     | INDEXES_LIST_NDX_1 |      0 |   2918 |     6   (0)|      0 |00:00:00.01 |       0 |       |       |          |
|     7 |    INDEX FAST FULL SCAN  | INDEXES_LIST_NDX_1 |      1 |   2918 |     6   (0)|   2918 |00:00:00.01 |      20 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")
   6 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)


31 rows selected.

SQL>
SQL> alter session set statistics_level='ALL';

Session altered.

SQL> select count(*)
  2  from tables_list t
  3  where (owner, table_name)
  4  not in
  5  (
  6   select owner, table_name
  7   from indexes_list i
  8  )
  9  /

  COUNT(*)
----------
       593

SQL> select * from table(dbms_xplan.display_cursor('',format=>'ALLSTATS LAST +COST +ADAPTIVE'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  c1fdcdxhvjrat, child number 0
-------------------------------------
select count(*) from tables_list t where (owner, table_name) not in (
select owner, table_name  from indexes_list i )

Plan hash value: 2460844421

---------------------------------------------------------------------------------------------------------------------------------------------------
|   Id  | Operation                | Name               | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------
|     0 | SELECT STATEMENT         |                    |      1 |        |    11 (100)|      1 |00:00:00.01 |      37 |       |       |          |
|     1 |  SORT AGGREGATE          |                    |      1 |      1 |            |      1 |00:00:00.01 |      37 |       |       |          |
|  *  2 |   HASH JOIN ANTI         |                    |      1 |     22 |    11   (0)|    593 |00:00:00.01 |      37 |  1335K|  1335K| 1381K (0)|
|-    3 |    NESTED LOOPS ANTI     |                    |      1 |     22 |    11   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|-    4 |     STATISTICS COLLECTOR |                    |      1 |        |            |   2202 |00:00:00.01 |      17 |       |       |          |
|     5 |      INDEX FAST FULL SCAN| TABLES_LIST_NDX    |      1 |   2202 |     5   (0)|   2202 |00:00:00.01 |      17 |       |       |          |
|- *  6 |     INDEX RANGE SCAN     | INDEXES_LIST_NDX_1 |      0 |   2918 |     6   (0)|      0 |00:00:00.01 |       0 |       |       |          |
|     7 |    INDEX FAST FULL SCAN  | INDEXES_LIST_NDX_1 |      1 |   2918 |     6   (0)|   2918 |00:00:00.01 |      20 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")
   6 - access("OWNER"="OWNER" AND "TABLE_NAME"="TABLE_NAME")

Note
-----
   - this is an adaptive plan (rows marked '-' are inactive)


30 rows selected.

SQL>

ote : The two SQL statements, although being the same, have different SQL_IDs because of the presence / absence of the GATHER_PLAN_STATISTICS Hint.

SQL Execution Statistics -- 3 : Using STATISTICS_LEVEL

 In my previous posts here and here, I have shown how to use the GATHER_PLAN_STATISTICS Hint to collect additional information.  But what if you can't modify the SELECT query statement ?

You could set STATISTICS_LEVEL='ALL' at the session, run the query and then reset STATISTICS_LEVEL to the default  'TYPICAL'

SQL> alter session set tracefile_identifier='H2';

Session altered.

SQL> alter session set statistics_level='ALL';

Session altered.

SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>TRUE);  -- just to get the SQL_ID in the trace file

PL/SQL procedure successfully completed.

SQL>
SQL> select
  2  d.department_id, d.department_name, e.first_name, e.last_name
  3  from hr.departments d join hr.employees e
  4  on d.department_id=e.department_id
  5  order by 1,2,4,3
  6  /
....
....
....
106 rows selected.

SQL>
SQL> exec DBMS_SESSION.SET_SQL_TRACE(sql_trace=>FALSE);

PL/SQL procedure successfully completed.

SQL>
QL> select * from table(dbms_xplan.display_cursor('4aa2k5b98ybfr',format=>'ALLSTATS LAST'));  -- SQL_ID identified from the trace file

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  4aa2k5b98ybfr, child number 0
-------------------------------------
select d.department_id, d.department_name, e.first_name, e.last_name
from hr.departments d join hr.employees e on
d.department_id=e.department_id order by 1,2,4,3

Plan hash value: 2209899241

-------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |      1 |        |    106 |00:00:00.10 |      10 |     14 |       |       |          |
|   1 |  SORT ORDER BY                |                   |      1 |    106 |    106 |00:00:00.10 |      10 |     14 | 11264 | 11264 |10240  (0)|
|   2 |   MERGE JOIN                  |                   |      1 |    106 |    106 |00:00:00.10 |      10 |     14 |       |       |          |
|   3 |    TABLE ACCESS BY INDEX ROWID| DEPARTMENTS       |      1 |     27 |     12 |00:00:00.03 |       2 |      2 |       |       |          |
|   4 |     INDEX FULL SCAN           | DEPT_ID_PK        |      1 |     27 |     12 |00:00:00.03 |       1 |      1 |       |       |          |
|*  5 |    SORT JOIN                  |                   |     12 |    107 |    106 |00:00:00.06 |       8 |     12 |  9216 |  9216 | 8192  (0)|
|   6 |     VIEW                      | index$_join$_002  |      1 |    107 |    106 |00:00:00.06 |       8 |     12 |       |       |          |
|*  7 |      HASH JOIN                |                   |      1 |        |    106 |00:00:00.06 |       8 |     12 |  1610K|  1610K| 1658K (0)|
|   8 |       INDEX FAST FULL SCAN    | EMP_DEPARTMENT_IX |      1 |    107 |    106 |00:00:00.06 |       4 |      6 |       |       |          |
|   9 |       INDEX FAST FULL SCAN    | EMP_NAME_IX       |      1 |    107 |    107 |00:00:00.01 |       4 |      6 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
       filter("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
   7 - access(ROWID=ROWID)


30 rows selected.

SQL>

Thus, I was able to get similar execution statistics without the Hint if I set STATISTICS_LEVEL='ALL'.

(Note : The top level operation here is a MERGE JOIN while that in the first example of the first post of this series on 27-January-22 was a HASH JOIN. The result here is 106 rows, not the 108 rows in the first example. The first example was in an HR schema in another database -- e.g. you would see DEPARTMENT_ID=280 'New Department' and Employee 'HEMANT CHITALE' in that listing.  These are two different HR schemas where I have modified some of the data.  Thus, you'll see a difference in the Execution Plan as well between the first example and this one. although the query is similar -- because the databases, patch levels,  possibly optimizer parameters, schema and data are different.)

Even a slight difference in data or parameters or patch levels can result in different execution plans !