Tuesday, August 19, 2014

Nologging vs Logging for LOBs and enq: CF - contention

Changing the logging option is one of the possible performance tuning tasks when dealing with LOBs. However use of nologging will make recovery of these lob segments impossible as such use of this will also depends on the nature of the application data. For transient data where recovery is not expected in case of database failure nologging option would be suitable. When the logging option is not explicitly mentioned this results in the tablespace's logging option being inherited by the lob segment. Refer Oracle documentation for more logging related information on basicfile and securefile.
This post presents the result of a simple test carried out comparing the nologging vs logging for both basicfile and securefile LOB segments. The java code used for the test is given at the end of the post. First case is the basicfile. Nologging is not possible if the cache is enable on the lob segment. Therefore nocache option is chosen for both logging and nologging. The table definition is given below.
create table ses(sesid varchar2(100), sesob blob) SEGMENT CREATION IMMEDIATE TABLESPACE users
 LOB
  (
    sesob
  )
  STORE AS object_lob_seg (
  TABLESPACE lob32ktbs
  DISABLE STORAGE IN ROW
        CHUNK 32K
        NOCACHE NOLOGGING
        --NOCACHE LOGGING
        PCTVERSION 0
        STORAGE (MAXEXTENTS UNLIMITED)
        INDEX object_lob_idx (
            TABLESPACE lob32ktbs
            STORAGE (MAXEXTENTS UNLIMITED)
        )
    )
/
The test involves inserting an 800KB LOB into the table 100 times and then later updating it with similar size LOB. Since the LOB is greater than 4K, the table is created with disable in row. Chunk size is set to 32k and the lob segment is stored in a tablespace of 32K block size (lob32ktbs) while the table resides in a different (users) tablespace of 8K block size. Pctversion is set to 0 as no consistent reads are expected. Only option that is changed is the logging option. The test database version is 11.2.0.3
Redo size statistic and the log file sync wait event times are compared for the two test runs as these are directly related to the logging option. Graphs below show the comparison of these for each test run.

There's no surprise that nologging option generates the lowest amount of redo. The logging test case generated around 83-84MB of redo for insert and update which is roughly the same size as the LOB inserted/updated (800KB x 100). There's minimal logging during the nologging test. Since redo is counted for the entire test, the redo seen could be the redo generated for the table data insert (as oppose to lobs) which still is on a tablespace with logging. Nevertheless a clear difference could be observed in the amount of redo generated when nologging is used. This is also reflected in the log file sync time for the two test cases which got reduced from several minutes to under a minute.
Next the same test was executed but this time the lob segment was stored as securefile. The table DDL is given below. Only difference apart from the securefile is Pctversion 0 has been replaced with retention none. All other settings are same as the basic file (tablespaces, database and etc). Chunk size is depreciated in securefile, and when specified is considered only as a guidance.
create table ses(sesid varchar2(100), sesob blob) SEGMENT CREATION IMMEDIATE TABLESPACE users
 LOB
  (
    sesob
  )
  STORE AS securefile object_lob_seg (
  TABLESPACE lob32ktbs
  DISABLE STORAGE IN ROW
        CHUNK 32K
        NOCACHE NOLOGGING
        --NOCACHE LOGGING
        RETENTION NONE
        STORAGE (MAXEXTENTS UNLIMITED)
        INDEX object_lob_idx (
            TABLESPACE lob32ktbs
            STORAGE (MAXEXTENTS UNLIMITED)
        )
    )
/
Similar to the earlier test the nologging generated low amount of redo compared to logging and resulted in short wait on log file sync event.

Comparing redo size and log file sync time for nologging option between the basicfile and securefile shows a mix bag of results. Basicfile has performed well for inserts in reducing redo generated and log file sync while securefile performed well for updates.

Comparing the IO types on OEM console during the nologging test it was noted that securefile uses predominantly large writes while the basicfile uses small writes.
Comparing the test result with logging enabled the securefile out performance basic file for insert and updates in terms of log file sync wait time. Both securefile and basicfile generates roughly the same amount of redo. It must be noted nocache logging is the default for secure file.
The table below shows all the test results.




It seems that when application permits it's best to use nologging for lobs which reduce the amount of redo generated and log file sync waits. However there are some drawbacks to using nologging on LOBs which only comes to light when there are multiple sessions doing LOB related DMLS. Following is an AWR snippet from a load test on pre-production system.
After CPU the top wait event is log file sync and high portion of this wait event is due an basicfile LOB related insert statement that store some transient data. Changing the lob segment option to nologging resulted in lower log file sync time but it also introduced high enq: CF - contention wait times.
According to 1072417.1 enq: CF - contention is normal and expected when doing DML on LOBs with nocache nologging. CF contention occurs as oracle records the unrecoverable system change number (SCN) in the control file. From the application perspective the overall response time degraded after changing to nologging and had to be reverted back to cache logging.

Useful metalink notes
Performance Degradation as a Result of 'enq: CF - contention' [ID 1072417.1]
LOB Performance Guideline [ID 268476.1]
LOBS - Storage, Redo and Performance Issues [ID 66431.1]
LOBS - Storage, Read-consistency and Rollback [ID 162345.1]
Master Note - RDBMS Large Objects (LOBs) [ID 1268771.1]
Performance problems on a table that has hundreds of columns including LOBs [ID 1292685.1]
POOR PERFORMANCE WITH LOB INSERTS [ID 978045.1]
Securefiles Performance Appears Slower Than Basicfile LOB [ID 1323933.1]


Java Code Used for Testing
public class LobLoggingTest {

    final String URL = "jdbc:oracle:thin:@192.168.0.66:1521:ent11g2";
    final String USERNAME = "asanga";
    final String PASSWORD = "asa";

    public static void main(String[] args) {

        LobLoggingTest test = new LobLoggingTest();
        //Insert test
        test.insertTest();

        System.out.println("\n\n************* end of insert test **************\n\n");

        //Update test
        test.updateTest();

    }

    public void insertTest() {
        try {

            OracleDataSource pool = new OracleDataSource();
            pool.setURL(URL);
            pool.setUser(USERNAME);
            pool.setPassword(PASSWORD);

            Connection con = pool.getConnection();
            con.setAutoCommit(false);

            long t1 = System.currentTimeMillis();

            LobStat.displayStats(con);
            LobStat.displayWaits(con);

            byte[] x = new byte[800 * 1024];
            x[1] = 10;
            x[798 * 1024] = 20;

            for (int i = 0; i < 100; i++) {

                OraclePreparedStatement pr = (OraclePreparedStatement) con.prepareStatement("insert into ses values(?,?)");

                String sesid = "abcdefghijklmnopqrstuvwxy" + Math.random();
                pr.setString(1, sesid);
                pr.setBytes(2, x);

                pr.execute();
                con.commit();
                pr.close();

            }

            long t2 = System.currentTimeMillis();

            LobStat.displayStats(con);
            LobStat.displayWaits(con);

            con.close();

            System.out.println("time taken " + (t2 - t1));

        } catch (Exception ex) {
            ex.printStackTrace();
        }
    }

public void updateTest() {
        try {

            OracleDataSource pool = new OracleDataSource();
            pool.setURL(URL);
            pool.setUser(USERNAME);
            pool.setPassword(PASSWORD);

            Connection con = pool.getConnection();
            con.setAutoCommit(false);

            String[] sesids = new String[100];

            PreparedStatement pr1 = con.prepareStatement("select sesid from ses");
            ResultSet rs1 = pr1.executeQuery();
            int i = 0;
            while (rs1.next()) {

                sesids[i] = rs1.getString(1);
                i++;
            }
            rs1.close();
            pr1.close();
            con.close();

            con = pool.getConnection();
            LobStat.displayStats(con);
            LobStat.displayWaits(con);

            OraclePreparedStatement pr = (OraclePreparedStatement) con.prepareStatement("update ses set SESOB=? where sesid=?");

            byte[] xx = new byte[800 * 1024];
            xx[1] = 10;
            xx[798 * 1024] = 20;

            long t1 = System.currentTimeMillis();
            for (String x : sesids) {

                pr.setBytes(1, xx);
                pr.setString(2, x);
                pr.execute();
                con.commit();
            }

            long t2 = System.currentTimeMillis();
            System.out.println("time taken " + (t2 - t1));

            LobStat.displayStats(con);
            LobStat.displayWaits(con);

            pr.close();
            con.close();

        } catch (Exception ex) {
            ex.printStackTrace();
        }
    }
}


public class LobStat {

    public static void displayStats(Connection con) {
        try {
            PreparedStatement pr = con.prepareStatement("select name,value from v$mystat,v$statname where v$mystat.statistic#=v$statname.statistic# "
                    + " and v$statname.name in ('CPU used when call started',"
                    + " 'CPU used by this session','db block gets','db block gets from cache','db block gets from cache (fastpath)',"
                    + " 'db block gets direct','consistent gets','consistent gets from cache','consistent gets from cache (fastpath)',"
                    + " 'consistent gets - examination','consistent gets direct','physical reads','physical reads direct',"
                    + " 'physical read IO requests','physical read bytes','consistent changes','redo size','redo writes',"
                    + " 'lob writes','lob writes unaligned','physical writes direct (lob)','physical writes','physical writes direct','physical writes from cache','physical writes direct temporary tablespace'"
                    + " ,'physical writes direct temporary tablespace','securefile direct read bytes','securefile direct write bytes','securefile direct read ops'"
                    + " ,'securefile direct write ops') order by 1");

            ResultSet rs = pr.executeQuery();


            while(rs.next()){

                System.out.println(rs.getString(1)+" : "+rs.getDouble(2));
            }

            rs.close();
            pr.close();
        } catch (SQLException ex) {
            ex.printStackTrace();
        }

    }

    public static void displayWaits(Connection con){
        try {
            PreparedStatement pr = con.prepareStatement("select event,total_waits,TIME_WAITED_MICRO from  V$SESSION_EVENT where sid=SYS_CONTEXT ('USERENV', 'SID') and event in ('log file sync','enq: CF - contention')");
            ResultSet rs = pr.executeQuery();

            System.out.println("event : total waits : time waited micro");
            while(rs.next()){

                System.out.println(rs.getString(1)+" : "+rs.getLong(2)+" : "+rs.getLong(3));

            }

            rs.close();
            pr.close();
        } catch (SQLException ex) {
            ex.printStackTrace();
        }

    }
}