Enabling & disabling In-Memory Undo impacts the redo generation in Oracle database

Enabling & disabling In-Memory Undo impacts the redo generation in Oracle database

We all know that Redo is one of the most important component in every Oracle database. While troubleshooting performance related issues we have noticed that sometimes excessive redo generation can cause slowness.

Today I did some experiment on my test database....

I created a very small table TEST_1 with 2 columns X and Y. This table has only one row.  

Scenario -1 (When IMU is disabled) - 

IMU can be enabled or disabled by setting hidden parameter "_in_memory_undo". This parameter value can be TRUE or FALSE. I disabled the IMU for the database.

ALTER SYSTEM SET "_in_memory_undo" = false;

 I performed a simple UPDATE DML and checked how much redo was generated. A simple update on 1 row generated 908 bytes of redo. When I performed another UPDATE statement on same row from same session, the second update generated 756 bytes redo.

After two DMLs, I performed a COMMIT. The COMMIT operation generated 140 bytes of redo. Total REDO generated by two DMLs and one COMMIT operation was 1804 bytes.

Scenario -2 (When IMU is enabled) -

In second scenario, I executed same UPDATE statement to update the same row in same table. But this time, the update statement didn't generate any redo. 
Then I performed another UPDATE statement on same row. But again, it didn't generate any redo. But when I performed a COMMIT, then redo was generated. Before COMMIT operation, my session did not generate any redo.

Note that I did not change the table defnition. Also, I did not use NOLOGGING option. 

In  the second scnenario, I enabled the In Memory Undo.

ALTER SYSTEM SET "_in_memory_undo" = true;

How In-Memory Undo impacts redo generation. We all know that when a buffer is changed, its past image is stored in Undo segments to provide read consistency. It means, a change in buffer also makes a change in undo buffers also. This change in undo also generates redo. Whenever a query requires to access a block in buffer cache and if the block has been modified, it checks the ITL from buffer header and finds the address of related undo segment. This is traditional behavior in Oracle.

But with the launch of In-Memory Undo concept, Oracle performs most of Undo related work in memory only. Most of undo related work is done in IMU nodes. When a block is changed in buffer cache, undo information is stored in IMU nodes and buffer header now contains IMU node information. The read consistency is provided from IMU nodes. Since IMU nodes are not segments, hence any modification in IMU nodes does not generate Redo. When we perform a commit, then consolidated undo information is flushed from multiple IMU nodes to undo segment as a batch operation. The redo generated at COMMIT is lesser than redo generated by same DMLs in traditional behavior. My experiment shows that when IMU was enabled, test generated 1668 bytes of redo. But when IMU was disabled, same test generated 1804 bytes redo.

If the database is configured with RAC configuration, data guard or streams, then IMU will be disabled.

Buffered Read or Direct Path Read? Understand query behavior with the help of "ENQ: KO - FAST OBJECT CHECKPOINT" event.

Today while doing some performance research on wait event "ENQ: KO - FAST OBJECT CHECKPOINT", I experienced that it's not Query Optimizer who decides, whether query will perform Buffered Read or it will perform Direct Path Read operation. Optimizer just decides the access method of operations involved in query execution. For example, Optimizer just decides if query will use FULL TABLE SCAN or INDEX SCAN. But FULL TABLE SCAN will be performed by buffered read operation or direct path read, it is decided at query run time during the execution phase, not in parsing phase.

To demonstrate this, I performed a little experiment. I performed two simple tests.

In the first test case, I forced "ENQ: KO - FAST OBJECT CHECKPOINT" wait event. I updated a single row of a big table, then I performed a full table scan operation and monitored the behavior of SELECT query. In the second test case, I updated 99% rows of a big table, then again performed a full table scan and again I monitored the behavior of SELECT query.

The results were little surprising...

During the first test case, I updated only 1 row of the table TEST_A. When I executed SELECT query,  it performed direct path read because table size is big as compared to buffer cache size. Before direct path read, a wait event ENQ: KO - FAST OBJECT CHECKPOINT was posted. This is because, before reading data blocks from data file directly to PGA,  object level checkpoint was occurred and dirty blocks of the table TEST_A were written from buffer cache to data file. 

In the second test case, I updated 99% rows of the table TEST_A.  During update operation, buffered read operation was performed. But this time, when I performed SELECT query (Full table scan), query did not performed DIRECT PATH READ, but it performed buffered read. This is because, most of table block data (buffers) were already found in buffer cache, so query did not perform DIRECT operation and hence event ENQ: KO - FAST OBJECT CHECKPOINT did not occur.

 Conclusion -

Important to note here is that SQL_ID, HASH VALUE and PLAN HASH VALUE of SELECT query are same in both the cases. So, we can conclude that optimizer has chosen same plan in both cases, but at run time, query performed differently. 

SQL Ordered by Elapsed Time Section of AWR Report Can Mislead your Analysis!!!

Whenever users complains that database is performing slow, most of DBAs immediately generate AWR reports for analysis. SQL Ordered by Elapsed Time is one of the major areas where most of DBAs look when analyzing AWR report.  Most of DBAs just assume that the topmost query in "SQL Ordered by Elapsed Time" section is the slowest query and they start looking for tuning opportunities.

But it is not necessary that Query Elapsed Time is always same what end user experiences. It is possible that Top most query in "SQL Ordered by Elapsed Time" section of AWR Report is NOT the slowest query and your analysis can go in wrong direction. Sometimes, SQL ordered by Elapsed Time section of AWR report can mislead your analysis.

Query Elapsed Time can be different from what end user experiences. To demonstrate this, I executed a simple query 4 times (4 tests). In each test, I increased the elapsed time to 2 times, 3 time and 4 times of actual time taken by the query and Elapsed Time is what is reported in AWR reports.

Test -1  - Elapsed Time of query is same what user experiences.

Test - 2 - Elapsed Time of query is 2 times of what user experiences.


Test - 3 - Elapsed Time of query is 3 times of what user experiences.

Test - 4 - Elapsed Time of query is 4 times of what user experiences.

Finally Interesting part is that, AWR report does not show the actual time taken by the query what user experiences. AWR Report shows Elapsed Time which is 95.2 seconds, not the user experienced time 24.41 seconds.

Does DB CPU Statistic include CPU Time consumed by Oracle background processes?

Does DB CPU Statistic include CPU Time consumed by Oracle background processes? 

When analyzing AWR reports or when troubleshooting performance related issues, all DBAs care about DB CPU statistic. If the CPU utilization of server where the database is hosted is really high, we need to check DB CPU statistic over a period of time. 

We all know that in an Oracle database, there are some background processes e.g. DBWR, LGWR, CKPT, ARCn.... These processes also require some CPU resource to perform their operations. So, a question came to my mind that if DB CPU statistics also include CPU time consumed by Oracle background processes? If not, where CPU time consumed by Oracle background processes is recorded? 

To answer these question, I did a little test on my test database on my system. 

I checked the DB CPU statistic value for background processes DBW0 and LGWR and I found that this parameter values was always zero. 

SQL> alter session set nls_date_format='dd-mm-yyyy hh24:mi:ss';

Session altered.

SQL> select startup_time from v$instance;

STARTUP_TIME

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

08-12-2015 22:53:49

SQL> select current_timestamp from dual;

CURRENT_TIMESTAMP

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

09-DEC-15 12.10.30.759355 AM -05:00

SQL> select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

  2  where a.sid=b.sid and (a.program like '%DBW%' or a.program like '%LGW%' )

  3  and lower(b.stat_name) like '%db cpu%' order by a.program;

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

                               oracle@edndr1p1.us.oracle.com (DBW0)             DB CPU                                            0

                               oracle@edndr1p1.us.oracle.com (LGWR)             DB CPU                                            0

Then I performed a checkpoint to ensure some activity by these processes and again checked statistic value for these processes. 

SQL> alter system checkpoint;

System altered.

SQL>  select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

  2   where a.sid=b.sid and (a.program like '%DBW%' or a.program like '%LGW%' )

  3   and lower(b.stat_name) like '%db cpu%' order by a.program;

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

                               oracle@edndr1p1.us.oracle.com (DBW0)             DB CPU                                            0

                               oracle@edndr1p1.us.oracle.com (LGWR)             DB CPU                                            0

Now it is clear, that DB CPU statistic does not include CPU time consumed by Oracle background processes. But if DB CPU does not include CPU time for background processes, then where it is recorded? Somewhere it should be recorded. So, to answer this question, I performed same test again but this time, I checked all CPU related statistics for these background processes. Here is the result - 

SQL> select startup_time from v$instance;

STARTUP_TIME

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

08-12-2015 22:53:49

SQL> select current_timestamp from dual;

CURRENT_TIMESTAMP

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

09-DEC-15 12.18.02.265650 AM -05:00

SQL> select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

where a.sid=b.sid and (a.program like '%DBW%' or a.program like '%LGW%') and lower(b.stat_name) like '%cpu%' order by a.program;

  2

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

                               oracle@edndr1p1.us.oracle.com (DBW0)             DB CPU                                            0

                               oracle@edndr1p1.us.oracle.com (DBW0)             background cpu time                         6098073

                               oracle@edndr1p1.us.oracle.com (DBW0)             RMAN cpu time (backup/restore)                    0

                               oracle@edndr1p1.us.oracle.com (LGWR)             background cpu time                         9618538

                               oracle@edndr1p1.us.oracle.com (LGWR)             RMAN cpu time (backup/restore)                    0

                               oracle@edndr1p1.us.oracle.com (LGWR)             DB CPU                                            0

6 rows selected.

SQL> alter system checkpoint;

System altered.

SQL> select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

where a.sid=b.sid and (a.program like '%DBW%' or a.program like '%LGW%') and lower(b.stat_name) like '%cpu%' order by a.program;

  2

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

                               oracle@edndr1p1.us.oracle.com (DBW0)             DB CPU                                            0

                               oracle@edndr1p1.us.oracle.com (DBW0)             background cpu time                         6115070

                               oracle@edndr1p1.us.oracle.com (DBW0)             RMAN cpu time (backup/restore)                    0

                               oracle@edndr1p1.us.oracle.com (LGWR)             background cpu time                         9656532

                               oracle@edndr1p1.us.oracle.com (LGWR)             RMAN cpu time (backup/restore)                    0

                               oracle@edndr1p1.us.oracle.com (LGWR)             DB CPU                                            0

6 rows selected.

Again, I checked DB CPU statistic value for a user session (non-background process session). - 

SQL>  select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

  2  where a.sid=b.sid and a.sid=16 and b.stat_name='DB CPU';

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

SYS                            sqlplus@edndr1p1.us.oracle.com (TNS V1-V3)       DB CPU                                        72988

Did some activity by user session and check DB CPU value again for this session - 

SQL> conn / as sysdba

Connected.

SQL> select distinct sid from v$mystat;

       SID

----------

        16

SQL> create table mytable as select * from dba_objects;

Table created.

SQL>  select a.username,a.program,b.stat_name,b.value from v$session a, v$sess_time_model b

  2   where a.sid=b.sid and a.sid=16 and b.stat_name='DB CPU';

USERNAME                       PROGRAM                                          STAT_NAME                                     VALUE

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

SYS                            sqlplus@edndr1p1.us.oracle.com (TNS V1-V3)       DB CPU                                      9542548

The DB CPU statistic value for user session (foreground process) is non-zero and increasing over a period of time.

We can see above that we have another statistic named "background cpu time" which is increasing. This is where CPU time consumed by Oracle background processes is recorded. 

So, we can conclude that DB CPU statistic value only includes CPU time which is consumed by foreground processes. It doesn't include CPU time consumed by Oracle background processes. For Oracle background processes, it is recorded in "background cpu time" statistic.

If we need to calculate total CPU consumption by an Oracle database over a period of time, we should add both these statistics values.

Total CPU consumption by database = DB CPU + background CPU time

What Elapsed Time, DB Time and DB CPU represent in AWR report and how to calculate Wait time (Non-Idle)

What are Elapsed Time, DB Time and DB CPU and how to calculate Wait Time

Time is a very important factor when we look opportunities for tuning database performance. The most important time parameters when we look into AWR reports or V$ views like v$sys_time_model views are DB Time, DB CPU and Elapsed Time. So, we must understand what are the meaning of these time parameters and what are their relationships with each other.

Elapsed Time - Elapsed time is the time what a user experiences when running a query. When looking into AWR report, the Elapsed Time is the wall clock time of duration for which AWR report has been generated. For example, if we generate AWR report for 1 hour then Elapsed Time in AWR report will be 60 mins.

DB CPU - DB CPU is the CPU consumption by all Oracle server processes/foreground processes during snapshot interval time. The name DB CPU has been taken from statistic name which is found in the view v$sys_time_model.

SQL> select stat_name, value from v$sys_time_model where stat_name='DB CPU'
  2  /

STAT_NAME                           VALUE
------------------------------ ----------
DB CPU                          974752790


If we look at any AWR report, we will find DB CPU statistic value in "Time Model Statistics" Section. The value reported in the AWR report represents total CPU consumption by all Oracle server processes during the snapshot interval time. This statistic value is converted into seconds in AWR report.

DB Time - DB time is a statistic which represents CPU time consumed by all Oracle processes over a period of time plus non-idle wait time. The name DB Time which we see in AWR report has been actually derived from v$views like v$sys_time_model and v$sess_time_model. 

SQL>  select stat_name, value from v$sys_time_model where stat_name='DB time';

STAT_NAME                           VALUE

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

DB time                        1.1922E+10

If we look into any AWR report, we will find DB Time in "Time Model Statistics" section of AWR report. The value reported in the AWR report for this parameter represents the sum of DB CPU and non-idle wait time over a period of snaphot interval.

How to calculate Wait Time (Non-Idle) -

When any Oracle process is not consuming CPU, it will be paused. This time, when a process is not consuming CPU is termed as wait time. The wait time can also be categorized in idle wait time and non-idle wait time. If a process is waiting for something to complete, then it is considered as non-idle wait time. There are lots of idle and non-idle wait events in Oracle database. So, as a DBA, to improve the database performance, we need to focus on non-idle wait events. In the following screenshot, we can see that in my system there are 94 idle wait events.

So the DB time is sum of DB CPU and Non-Idle wait time.

DB Time = DB CPU + Non-Idle wait time

so, Non-Idle wait time = DB Time - DB CPU