enq: US - contention and row cache lock waits

High waits on enq: US - contention and row cache lock was seen during a load test on a two node cluster. On the statspack reports these two wait events were among the top 5 wait evetns

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
enq: US - contention                             7,498       4,035    538   21.9
row cache lock                                   8,486       1,240    146    6.7

During normal operation there was no waits on enq: US - contention and row cache lock waits were between 0 - 4. High wait events only appear during the load test when the system is stressed.
The first peaks on the following graphs corresponds to high waits on above events observed during the initial load test.

enq: US - contention

row cache lock waits

Although 1332738.1 suggested this is related to undo segments and could be seen dc_rollback_segments. But there was not much difference between this metric during problem period and a good period. Below is the problem period

Cache                         Requests   Miss    Reqs  Miss     Reqs      Usage
------------------------- ------------ ------ ------- ----- -------- ----------
dc_objects                     105,703    0.1       0              0      5,389
dc_rollback_segments            38,780    0.3       0            250        514
dc_segments                      4,234    5.0       0             12      2,719
dc_tablespaces                 165,248    0.0       0              0         21
dc_users                       178,080    0.0       0              0        222

The good period

Cache                         Requests   Miss    Reqs  Miss     Reqs      Usage
------------------------- ------------ ------ ------- ----- -------- ----------
dc_objects                     284,414    0.5       0              8      2,753
dc_rollback_segments            22,307    0.0       0              0        515
dc_segments                     17,724    7.9       0             10      1,790
dc_tablespaces                 142,346    0.0       0              0         21
dc_users                       158,440    0.0       0              0        116

Comparing the above two there's only a slight difference but comparing GES stats shows following for problem period

Cache                         Requests    Conflicts     Releases
------------------------- ------------ ------------ ------------
dc_objects                          84            2            0
dc_rollback_segments               511          133            0
dc_segments                        352            6            0

and no requests or conflicts for dc_rollback_segments during good period.
Datafile assigned to undo tablespaces has auto extensible on and has enough free space on the disk to extend the datafile. Therefore 420525.1 and 413732.1 wasn't much of a help.
742035.1 and 7291739.8 mentions bug 7291739 which materializes in high contention on above two wait events when autotuned undo retention is in use. Therefore applied the patch for bug 7291739 and set the parameter _first_spare_parameter value to the run length of the longest running query found on v$undostat(as this is 11.1, other version may require HIGHTHRESHOLD_UNDORETENTION refer above mention notes). Running the load test again didn't show any improvement and high waits could still be seen (second peak on the above graphs).


Raised a SR. Oracle couldn't determine why the patch is not effective in reducing the high wait events and suggested another hidden parameter rollback_segment_count(also mentioned as a work around on 1332738.1) It was recommended to set a value of 1.5 times the online undo segments for this parameter.

SQL> select TABLESPACE_NAME,count(*) from DBA_ROLLBACK_SEGS where status='ONLINE' group by tablespace_name;

TABLESPACE_NAME   COUNT(*)
--------------- ----------
UNDOTBS1               323
SYSTEM                   1
UNDOTBS2               300

According to Oracle the value set is for "entire instance not for undo tablespace" which I would imagine means per database and not per instance. This value act as the "lower limit for the number of undo segments online at a given time". Setting this value doesn't result in database proactively online number of undo segments as specified. It is the minimum number of undo segments to kept online and only comes into play if the number of undo segments goes beyond the value specified. So going by the above statistics the value to set would be (323 + 300) x 1.5 = 935. One more thing is that this value is not dynamic and requires a restart (Not an ideal workaround for a busy production system).
After above value is set running the load test did not result in any enq: US - contention waits. It should be noted that patch was still in place even with this parameter set, but highly unlikely that it had contributed to resolve the high waits. It is possible that rollback_segment_count alone is responsible for reducing the high waits. This would be verified once the patch is roll backed later on.

Useful metalink notes
Full UNDO Tablespace In 10gR2 [ID 413732.1]
Contention Under Auto-Tuned Undo Retention [ID 742035.1]
Automatic Tuning of Undo_retention Causes Space Problems [ID 420525.1]
How to correct performance issues with enq: US - contention related to undo segments [ID 1332738.1]
Bug 7291739 - Contention with auto-tuned undo retention or high TUNED_UNDORETENTION [ID 7291739.8]

Guarantee Restore Point Leads to High DB File Sequential Read Waits on Undo Tablespace in 11gR2

Guarantee restore points are useful to have in test environments which allows easy rollback of the database so test could be run again without having to have a new data sets for inserts that can cause primary key violation.
However it seems having a guarantee restore point can cause excessive db file sequential read waits on the undo tablespace for insert statements. This could alter the performance characteristics of test.
Following test case could be used to recreate this behavior. The test environment used here is 11gR2 (11.2.0.3.3).
Create the table for the test case

create table ses_lock (sid varchar2(100) primary key);

Open 3 sql plus session (called 1,2 and 3 from now on) and run the following pl/sql blocks on each one.
On session 1 create and hold a lock to start the concurrent insert process

declare
    i pls_integer;
begin
    i := dbms_lock.request(10);
end;
/

On session 2 run the PL/SQL for the insert statment

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

Run the same on sesison 3

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

and finaly on session 1 release the lock

declare
    j pls_integer;
begin
    j := dbms_lock.release(10);
end;
/

This will start concurrent insert into the table.
Investigating the active session history during this period for the insert sql shows that db file sequential reads are on datafile 14 which is the datafile where the table resides.

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 11:37','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        14  file#  7pj2bbx25m1rf 30                     

SQL> select sql_id,sql_text from v$sql where sql_id='7pj2bbx25m1rf';

SQL_ID        SQL_TEXT
------------- ------------------------------------------------------------
7pj2bbx25m1rf INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

SQL> select file_id,tablespace_name from dba_data_files where file_id=14;

FILE_ID TABLESPACE_NAME
------- -----------------
14      BX2KTBS

Delete the rows in the table and create a guarantee restore point

SQL> delete from ses_lock;
200000 rows deleted.

SQL> commit;

It is possible to create a guarantee restore point in 11gR2 without having flashback on. Before guarantee restore point is created

SQL> select flashback_on from v$database;

FLASHBACK_ON
-------------
NO

After guarantee restore point

SQL> create restore point first_restore guarantee flashback database;

SQL> select flashback_on from v$database;

FLASHBACK_ON
------------------
RESTORE POINT ONLY

Create 3 sql*plus sessions mentioned above and run the insert again.
Querying the active session history afterwards shows that during this test the db file sequential read waits were on the data file used for the undo tablespace and much higher number of waits compared to test without the guarantee restore point.

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 12:02','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        3   file#  7pj2bbx25m1rf 266    

SQL> select file_id,tablespace_name from dba_data_files where file_id in (3,14);

FILE_ID  TABLESPACE_NAME
-------- ---------------
3        UNDOTBS1
14       BX2KTBS

Dropped the restore point and ran the test again and this time there was no db file sequential waits and as soon as the restore point is created and test carried out see lots of db file sequential read waits on undo tablespace data file. Below is the output of querying active session history for the second test with restore point thus confirming that observed behavior is repeatable with the test case

select inst_id,p1,p1text,sql_id,count(*)
from gv$active_session_history
where sample_time >  to_date('2012-09-17 12:20','YYYY-MM-DD HH24:MI')
and event ='db file sequential read'
group by inst_id, p1, p1text, sql_id
order by 5 desc,1 ,2;

INST_ID  P1  P1TEXT SQL_ID        COUNT(*)         
-------- --- ------ ------------- ---------
1        3   file#  7pj2bbx25m1rf 193    

-->


SQL tracing could also be used to demonstrate this problem. This is useful if the database is standard edition where use of active session history view is not an option because of license restrictions.
Enable sql tracing for the session

alter session set max_dump_file_size=UNLIMITED;
alter session set  tracefile_identifier='before_grp';
alter session set events '10046 trace name context forever, level 12';

Run the insert statement, this time only using on session

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

Formatted trace file output shows no waits for db file sequential read wait event

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     14.95      14.77          0       2746     517465      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     14.95      14.77          0       2746     517465      100000

Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=155 pr=5 pw=0 time=35733 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  latch: In memory undo latch                     1        0.00          0.00
  log file switch completion                      2        0.00          0.01
  latch free                                      1        0.00          0.00
********************************************************************************

Delete all rows from the table and create restore point

SQL> delete from ses_lock;
100000 rows deleted.

SQL>commit;
Commit complete.

SQL> create restore point first_restore guarantee flashback database;

Run the test again

alter session set max_dump_file_size=UNLIMITED;
alter session set  tracefile_identifier='after_grp';
alter session set events '10046 trace name context forever, level 12';

declare
    i pls_integer;
begin
    i := dbms_lock.request(10,DBMS_LOCK.S_MODE);

    for i in 1 .. 100000
    loop
     insert into ses_lock values (dbms_random.string('x',36));
     commit;
    end loop;
     i := dbms_lock.release(10);
end;
/

and formatted output of trace file shows high number of db file sequential read waits compared to previous test

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     20.71      22.50       3507        107     513257      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     20.71      22.50       3507        107     513257      100000

Misses in library cache during parse: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=1844 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                      3507        0.11          3.78
  log file switch (checkpoint incomplete)         3        0.00          0.00
  latch: redo allocation                          1        0.00          0.00
  log file switch completion                      1        0.06          0.06
********************************************************************************

Inspecting trace file itself could see details of the wait event and wait is on file#=3

WAIT #46953194410944: nam='db file sequential read' ela= 277 file#=3 block#=16505 blocks=1 obj#=0 tim=1349341486136362
WAIT #46953194410944: nam='db file sequential read' ela= 263 file#=3 block#=17317 blocks=1 obj#=0 tim=1349341486138981
WAIT #46953194410944: nam='db file sequential read' ela= 330 file#=3 block#=16955 blocks=1 obj#=0 tim=1349341486149736
WAIT #46953194410944: nam='db file sequential read' ela= 387 file#=3 block#=17076 blocks=1 obj#=0 tim=1349341486152818
WAIT #46953194410944: nam='db file sequential read' ela= 15 file#=3 block#=16839 blocks=1 obj#=0 tim=1349341486161143

File#=3 is the datafile used with the undo tablespace.
Drop the restore point and the db file sequential read event disappear, output below after restore point is dropped

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK VALUES (DBMS_RANDOM.STRING('x',36))

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     15.44      14.60          0         67     593197      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     15.44      14.60          0         67     593197      100000

Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 84     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=1613 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  log file switch (checkpoint incomplete)         4        0.00          0.01
  latch: cache buffers chains                     1        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
********************************************************************************

SR was raised with Oracle and response was that "this is similar to Bug 12921374 : GURANTEED RESTORE POINT CAUSES MANY PHYSICAL READS." However there has not been any movement on this bug since Feb 2012 and there's no solution or workaround. As a result of this SR a new bug report has been created which is available under "Bug 14671654 : GUARANTEE RESTORE POINT PROVOKES HIGH"
The same test was carried out on 11.1.0.7 (11.1.0.7.12) and it didn't have the same behavior as 11gR2. So the issue is localized to 11gR2.(Update 2014/11/21-11.1 also exhibit the same behavior. Depending on when the table is created and when the restore point is created the location of the wait event on the trace file differ. Looking only at the insert statement may result in missing the high waits shown under the commit. Either way total number of waits for the test case on 11.1 is not different to that of 11.2)

Update 15 July 2013
The issue is also there on 12c (12.1.0.1). Below is the tkprof output after the same test done on a 12c.Before restore point creation

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     41.03      40.49          1       3272     515757      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     41.03      40.50          1       3272     515757      100000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=783 pr=7 pw=0 time=195740 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        6        0.00          0.00
  db file sequential read                         3        0.00          0.00
  latch: shared pool                              8        0.00          0.00
  log file switch (private strand flush incomplete)
                                                  1        0.01          0.01
  control file sequential read                   20        0.00          0.00
  Data file init write                           12        0.00          0.00
  db file single write                            1        0.00          0.00
  control file parallel write                     3        0.00          0.00
  rdbms ipc reply                                 1        0.00          0.00
********************************************************************************

After restore point created

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     43.42      42.15       3484        660     512898      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     43.43      42.16       3484        660     512898      100000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=226 pr=0 pw=0 time=56775 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        2        0.00          0.00
  db file sequential read                      3484        0.28          0.47
  log file switch (checkpoint incomplete)         1        0.01          0.01
  log file switch completion                      1        0.01          0.01
********************************************************************************

All the waits were on the undo tablespace same as before.

Update 14 July 2014
Same behavior is also observed on 11.2.0.4. Before guarantee restore point

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute 100000     72.74      81.65          6       3595     426842      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     72.75      81.66          6       3595     426842      100000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=164 pr=8 pw=0 time=103136 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: IV -  contention                          10        0.00          0.00
  db file sequential read                         6        0.00          0.02
  Disk file operations I/O                        1        0.00          0.00
  row cache lock                                  7        0.00          0.00
  latch: shared pool                              4        0.00          0.00
  latch: enqueue hash chains                      3        0.00          0.00
  latch free                                      3        0.00          0.00
  latch: redo allocation                          1        0.00          0.00
  log file switch (checkpoint incomplete)         1        0.00          0.00
  log file switch completion                      1        0.00          0.00
********************************************************************************

After guarantee restore point created

SQL ID: dqhz25akp92bp Plan Hash: 0

INSERT INTO SES_LOCK
VALUES
 (DBMS_RANDOM.STRING('x',36))


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 100000     82.15      94.40       5143       3615     434964      100000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   100001     82.16      94.41       5143       3615     434964      100000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 50     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=5 pr=3 pw=0 time=13633 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  row cache lock                                  3        0.00          0.00
  Disk file operations I/O                        3        0.00          0.00
  db file sequential read                      5143        0.52          2.31
  KSV master wait                                 2        0.00          0.00
  ASM file metadata operation                     1        0.00          0.00
  latch free                                      1        0.00          0.00
  log file switch (checkpoint incomplete)         2        0.01          0.02
********************************************************************************

Update 21 November 2014
Final reply from Oracle "this is not a bug but expected behavior when restore point is in use".

Log File Sync and Log File Parallel Write Waits

On a routine database health check it was discovered the that the log file sync waits events have increased 10-20 times than the base line values. Graphs generated with ADMon

Log File Sync Waits

Metalink note 34592.1 list the usual causes for high log file sync waits. Assuming all else (meaning hardware related parameters) remains the same and constants the main reason is the high user commit rates. But in this case the user commit rates were consistent throughout the problem period.

User Commits

Same was true for user rollbacks (the drop is due to instance restart) and transaction rollbacks.

User Rollbacks

Transaction Rollback

DB CPU was also consistent throughout the problem period which indicated there was no increase in the system load.

DB CPU

Metalink note 34592.1 show how the log file sync wait time could be broken down. Two metrics related to this case are the "redo write time" metric which is the time taken by lgwr process gathering redo to be written and issuing IO. The second statistic is the log file parallel write (refer 34583.1) wait time which is the "time taken for all the outstanding I/O requests to complete". Log file parallel write wait time graph was similar to the log file sync wait time graph.

Log File Parallel Write

34592.1 also mention several statistics that are related to lgwr performance. These are redo writes,redo blocks written,redo write time,redo wastage and redo size. Definitions of these statistics are from the Oracle Reference guide.
Redo writes is the total number of writes by LGWR to the redo log files and it was also consistent throughout the problem period.

Redo Writes

Redo blocks written is the total number of redo blocks written and it is also consistent and hold the same pattern as before the problem period.

Redo Blocks Written

Redo write time is the total elapsed time of the write from the redo log buffer to the current redo log file in 10s of milliseconds. There a increase in redo write time corresponding to log file sync and log file parallel write graphs indicating more time spent on writing redo to log file.

Redo Write Time

Redo wastage is the number of bytes wasted because redo blocks needed to be written before they are completely full. This statistic was also also consistent throughout the problem period.

Redo Wastage

The last is the redo size which is the total amount of redo generated in bytes. This statistics is also an indication of the system load, if there are more DML then amount of redo size would also increase. However in this case the redo size is also consistent throughout the problem period.

Redo Size

Next redo log space and redo log buffer statistics were looked at. Redo buffer allocation retries are the total number of retries necessary to allocate space in the redo buffer. Though there hasn't been any reduction in redo buffer size the amount of redo buffer allocation retries have gone up indicating lgwr is not clearing the log buffer fast enough.

Redo Buffer Allocation Retries

Redo Buffers

Increase in redo log space requests and redo log space wait time indicates that the wait is not memory bound but IO (or disk) bound. Redo log space requests is the number of times the active log file is full and Oracle must wait for disk space to be allocated for the redo log entries. Increase in this means slow IO. Redo log space wait time is the total elapsed waiting time for "redo log space requests" in 10s of milliseconds. Both these statistics have increased in value over the problem period.

Redo Log Space Requests

Redo Log Space Wait Time

Considering all of the above it seems the traffic is the same (system load, redo generation) but some of the lanes (IO bandwidth) "might be" closed. Looking at the IO time on the OS statistics showed a increased IO time which corresponds with log file sync increase. So the assumption that "all else remains the same" may not be correct.

IO Time

Therefore at this point assumption was that cause for increase in these wait events might be due to "something" in the IO sub system rather than the database or application. The system was a two node cluster using a SAN with RAID 5. Both 34583.1 and 34592.1 advise against placing redo logs on RAID 5 but in this case even with RAID 5 the log file *(sync/parallel write) waits were low. So RAID 5 is not the root cause here.
On further investigating the SAN it was discovered the it had two RAID controllers and battery on one of them has failed (thus closing one lane of traffic).

Replacing the dead battery and bringing the RAID controller online (opening up the lane) made the waits to go back to previous level.

Log File Parallel Write

Below is a different system's log file *(sync/parallel write) waits and in this case the increase in waits is caused by a burst of user commits.

Log File Sync

Log File Parallel Write

User Commits

Increase in these two wait events could happen due to user activity as well as due to change in IO related hardware (partial failure as in this case). Having a base line taken when the performance is optimal, to compare with the problem period could help in diagnosing and identifying the reason for the increase.

Useful metalink notes
WAITEVENT: "log file sync" Reference Note [ID 34592.1]
WAITEVENT: "log file parallel write" Reference Note [ID 34583.1]

enq: TX row lock contention During Inserts due to Bitmap Indexes

Bitmap indexes are not suited on tables that have frequent DML operations. It was shown on an earlier post how the bitmap index locking happens.
enq: TX row lock contention waits happen when multiple sessions try to modify the same row, but could manifest in other areas as well such as inserts on a primary key column and inserts on bitmap index columns. Since insert is effectively creating a new row seeing enq: TX row lock contention on inserts could be bit puzzling.
In the case of inserting into a primary key column subsequent sessions will wait on enq: TX row lock contention event until first session commit or rollback. This is required to identify and raise ORA-00001: unique constraint in cases where duplicate values are being inserted into primary key column. Therefore it is not uncommon to see enq: TX row lock contention waits on inserts when there's a primary key column and a highly concurrent insert rate. To reduce this wait if possible remove the primary key but may not always possible due to application logic.
Second place where enq: TX row lock contention events comes up is when inserting to table with bitmap indexes. enq: TX row lock contention waits happen since bitmap index entries must be updated based on the inserted rows. This has a far worse performance impact than insert on a primary key. Below is a simple test to illustrate the point.
Create a table with primary key

create table abc (id number, a varchar2(1), b number(1), c varchar2(1), primary key (id));

Create bitmap indexes as below

SQL> create bitmap index aidxa on abc(a);
Index created.

SQL> create bitmap index aidxb on abc(b);
Index created.

SQL> create bitmap index aidxc on abc(c);
Index created.

Open two sqlplus sessions and run the following two PL/SQL blocks. On session 1

begin
    for i in 1 .. 100000
    loop
      insert into abc values(i,dbms_random.string('i',1),round(dbms_random.value(1,5)),dbms_random.string('i',1));
      commit;
    end loop;
end;
/

On session 2

begin
    for i in 100000 .. 200000
    loop
      insert into abc values(i,dbms_random.string('i',1),round(dbms_random.value(1,5)),dbms_random.string('i',1));
      commit;
    end loop;
end;
/

Monitor the waits either through em console or active session history view. In this case APConsole has been used and output is given at the end.


Drop the bitmap indexes and truncate the table and run the test again. The image below shows the comparison of the two test cases.

It is apparent that amount of cpu time is high during the test with bitmap index in-place but the point is the enq: TX row lock contention which is none when test was run without bitmap index. Therefore when there are high enq: TX row lock contention waits seen for insert statements it is worth investigating whether the table in question has bitmap indexes.

Related post
Bitmap Index Locking

Metalink Notes
TX Transaction and Enq: Tx - Row Lock Contention - Example wait scenarios [ID 62354.1]

Latch Free Waits

A test development running 11gR1 (11.1.0.7) started to show high number of latch free waits during a load test.

Looking at the AWR report it could be seen that latch free waits is part of the top 5 events.

Going through the latch activity section of the AWR report it could seen Result Cache: Latch and SQL memory manager latch having the large wait times compared to other latch types.

Result Cache latch is used for controlling access to the result cache.

Used GV$RESULT_CACHE_OBJECTS to identify the objects that are being cached. In this case there was only one object which was a function. Remove the caching option from the function and ran the load test again.

In the second test the latch free waits were less and concurrency (cache buffer chains) were predominant.

Top 5 wait events shows that latch free events have decreased compared to previous time.

The high number of cache buffer chains are as a result of multiple sessions running the same sql and accessing same set of blocks (hot blocks). It is this sql that was inside the function that had used result cached feature. Since result caching was removed from the function sql was getting executed rather than result being served from the cache.

Predominant latch in the second period was cache buffer chain.

Comparison AWR report shows DB Time being reduced while DB CPU time increasing.

Wait Event comparison captures the reduction of the latch free and increase of cache buffer chain.

Latch wait time comparison

Mutex Sleep Summary in test 1.

Mutex Sleep Summary in test 2.

Comparison of the above two summaries shows during the second period mutex were obtained much quicker and far less sleeps to get the mutex.

Take home point is even though result cache is expected to reduce the load on the database by preventing the execution of the SQL and serving sessions using the cache, it could have other effects/bottlenecks/issues etc that could negate the gains.

Another event that was predominant in these test was SQL Memory Manager latch. Metalink note 9732503.8 mentions Bug 9732503 with regard to this latch in certain platforms and Oracle versions. More importantly it also states

This issue is often caused when the value of pga_aggregate_target is set too low, ie. when the statistic "over allocation count" is non zero in v$pgastat. When this is the case, increase pga_aggregate_target such that it is set to at least "maximum PGA allocated" in v$pgastat. You can find more information on tuning pga_aggregate_target in the Oracle tuning guide.

Metalink notes useful in diagnosing latch free wait events

WAITEVENT: "latch free" Reference Note [ID 34576.1]
How to Identify Which Latch is Associated with a "latch free" wait [ID 413942.1]

ksfd: async disk io

ksfd: async disk io was appearing from time to time somewhat predominately (compared to other waits events) on standard edition 11gR1 two node cluster.

Monitoring with APConsole showed the following.


Following metalink notes are related to this wait event.

High waits for "ksfd: async disk io" [ID 1326634.1]
Bug 8660422 - "unspecified wait event" and/or "ksfd: async disk IO" after applying patches that include fix for Bug 7510766 [ID 8660422.8]

This database has the PSU 11.1.0.7.6 applied. Blog post will be updated when PSU 11.1.0.7.7 or the patch 8660422 is applied.

Update on 19th November 2011

After October 2011 PSU (11.1.0.7.9) was applied ksfd: async disk io waits disappeared. Graph (generated with ADMon)below shows the waits for two week period. Wait was happening daily on both or at least one instance (this was a two node RAC) but stopped since the applying of the patch (Patch was applied on 17th).

Classes of Wait Events

Administrative
Waits resulting from DBA commands that cause users to wait (for example, an index rebuild)

Application
Waits resulting from user application code (for example, lock waits caused by row level locking or explicit lock commands)

Cluster
Waits related to Real Application Cluster resources (for example, global cache resources such as 'gc cr block busy'

Commit
This wait class only comprises one wait event - wait for redo log write confirmation after a commit (that is, 'log file sync')

Concurrency
Waits for internal database resources (for example, latches)

Configuration
Waits caused by inadequate configuration of database or instance resources (for example, undersized log file sizes, shared pool size)

Idle
Waits that signify the session is inactive, waiting for work (for example, 'SQL*Net message from client')

Network
Waits related to network messaging (for example, 'SQL*Net more data to dblink')

Other
Waits which should not typically occur on a system (for example, 'wait for EMON to spawn')

Scheduler
Resource Manager related waits (for example, 'resmgr: become active')

System I/O
Waits for background process IO (for example, DBWR wait for 'db file parallel write')

User I/O
Waits for user IO (for example 'db file sequential read')