User Commits, Log File Parallel Write and Log File Sync

I ran this example on Oracle 11.2. If an application spends too much time waiting on log file parallel write and/or log file sync, it may be doing too many user commits. To illustrate this, I created the SQL*Plus script below. It accepts a parameter and uses this to create a unique SPOOL file name and table name. It then sees how many user commits the database has done and looks to see the total time which has been spent waiting on the log file parallel write and log file sync events. After that, it inserts and deletes a row in the table 10,000 times. Each insert and delete is committed immediately. Once this has finished, the script counts the user commits and records the time spent waiting on log file parallel write and log file sync again. Finally, it waits 60 seconds before logging out. This is probably a bit of overkill but I wanted to be sure that all sessions would still be present in v$session_event while the last one to finish recorded the statistics I was interested in:

 

Oracle 11.2: cat test.sql

spool test&&1

col start_time format a10

set echo on

set lines 55

set termout off

set trimspool on

conn /

select to_char(sysdate,'hh24:mi:ss')

start_time from dual

/

create table tab&&1(col1 number)

/

select value from v$sysstat b

where name = 'user commits'

/

select sum(time_waited/100) from v$session_event

where event = 'log file parallel write'

/

select sum(time_waited/100) from v$session_event

where event = 'log file sync'

/

begin

for a in 1..10000 loop

  begin

  insert into tab&&1 values (a);

  commit;

  delete tab&&1;

  commit;

  end;

end loop;

end;

/

select value from v$sysstat

where name = 'user commits'

/

select sum(time_waited/100) from v$session_event

where event = 'log file parallel write'

/

select sum(time_waited/100) from v$session_event

where event = 'log file sync'

/

drop table tab&&1

/

select to_char(sysdate,'hh24:mi:ss')

end_time from dual

/

exec dbms_lock.sleep(60);

exit

spool off

Oracle 11.2:

 

Then I ran it from the following UNIX shell script. This runs the SQL script in 20 SQL*Plus sessions simultaneously in the background:

 

Oracle 11.2: cat test.ksh

#!/bin/ksh

export ORAENV_ASK=NO

export ORACLE_SID=ORCL

. oraenv

sqlplus  / @test 0 &

sqlplus  / @test 1 &

sqlplus  / @test 2 &

sqlplus  / @test 3 &

sqlplus  / @test 4 &

sqlplus  / @test 5 &

sqlplus  / @test 6 &

sqlplus  / @test 7 &

sqlplus  / @test 8 &

sqlplus  / @test 9 &

sqlplus  / @test 10 &

sqlplus  / @test 11 &

sqlplus  / @test 12 &

sqlplus  / @test 13 &

sqlplus  / @test 14 &

sqlplus  / @test 15 &

sqlplus  / @test 16 &

sqlplus  / @test 17 &

sqlplus  / @test 18 &

sqlplus  / @test 19 &

Oracle 11.2:

 

Once they had all finished, I sorted the output into chronological order:

 

Oracle 11.2: ls -ltr *lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test14.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test1.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test18.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test3.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test12.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test15.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test4.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test19.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test17.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test9.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test6.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test16.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test2.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test8.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test11.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test7.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test10.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test5.lst

-rw-r--r--   1 oracle   dba         1868 Feb 24 18:04 test13.lst

-rw-r--r--   1 oracle   dba         1864 Feb 24 18:04 test0.lst

Oracle 11.2:

 

Then I looked at the last one:

 

Oracle 11.2: cat test0.lst

SQL> set lines 55

SQL> set termout off

SQL> set trimspool on

SQL> conn /

Connected.

SQL> select to_char(sysdate,'hh24:mi:ss')

  2  start_time from dual

  3  /

 

START_TIME

----------

18:01:55

 

SQL> create table tab&&1(col1 number)

  2  /

old   1: create table tab&&1(col1 number)

new   1: create table tab0(col1 number)

 

Table created.

 

SQL> select value from v$sysstat b

  2  where name = 'user commits'

  3  /

 

     VALUE

----------

    206889

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file parallel write'

  3  /

 

SUM(TIME_WAITED/100)

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

             3434.49

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file sync'

  3  /

 

SUM(TIME_WAITED/100)

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

              100.38

 

SQL> begin

  2  for a in 1..10000 loop

  3    begin

  4    insert into tab&&1 values (a);

  5    commit;

  6    delete tab&&1;

  7    commit;

  8    end;

  9  end loop;

10  end;

11  /

old   4:   insert into tab&&1 values (a);

new   4:   insert into tab0 values (a);

old   6:   delete tab&&1;

new   6:   delete tab0;

 

PL/SQL procedure successfully completed.

 

SQL> select value from v$sysstat

  2  where name = 'user commits'

  3  /

 

     VALUE

----------

    605793

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file parallel write'

  3  /

 

SUM(TIME_WAITED/100)

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

             3495.45

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file sync'

  3  /

 

SUM(TIME_WAITED/100)

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

              821.08

 

SQL> drop table tab&&1

  2  /

old   1: drop table tab&&1

new   1: drop table tab0

 

Table dropped.

 

SQL> select to_char(sysdate,'hh24:mi:ss')

  2  end_time from dual

  3  /

 

END_TIME

--------

18:03:04

 

SQL> exec dbms_lock.sleep(60);

 

PL/SQL procedure successfully completed.

 

SQL> exit

Oracle 11.2:

 

The script took 69 seconds to run. In that time, the database did 399,084 user commits. It waited 60 seconds for the log file parallel write event. It waited 721 seconds for the log file sync event.

 

I changed the SQL to do 1 commit at the end and repeated the exercise:

 

Oracle 11.2: cat test16.lst

SQL> set lines 55

SQL> set termout off

SQL> set trimspool on

SQL> conn /

Connected.

SQL> select to_char(sysdate,'hh24:mi:ss')

  2  start_time from dual

  3  /

 

START_TIME

----------

18:14:27

 

SQL> create table tab&&1(col1 number)

  2  /

old   1: create table tab&&1(col1 number)

new   1: create table tab16(col1 number)

 

Table created.

 

SQL> select value from v$sysstat b

  2  where name = 'user commits'

  3  /

 

     VALUE

----------

    605851

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file parallel write'

  3  /

 

SUM(TIME_WAITED/100)

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

              3496.2

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file sync'

  3  /

 

SUM(TIME_WAITED/100)

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

                97.4

 

SQL> begin

  2  for a in 1..10000 loop

  3    begin

  4    insert into tab&&1 values (a);

  5    delete tab&&1;

  6    end;

  7  end loop;

  8  commit;

  9  end;

10  /

old   4:   insert into tab&&1 values (a);

new   4:   insert into tab16 values (a);

old   5:   delete tab&&1;

new   5:   delete tab16;

 

PL/SQL procedure successfully completed.

 

SQL> select value from v$sysstat

  2  where name = 'user commits'

  3  /

 

     VALUE

----------

    605878

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file parallel write'

  3  /

 

SUM(TIME_WAITED/100)

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

             3515.87

 

SQL> select sum(time_waited/100) from v$session_event

  2  where event = 'log file sync'

  3  /

 

SUM(TIME_WAITED/100)

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

              120.89

 

SQL> drop table tab&&1

  2  /

old   1: drop table tab&&1

new   1: drop table tab16

 

Table dropped.

 

SQL> select to_char(sysdate,'hh24:mi:ss')

  2  end_time from dual

  3  /

 

END_TIME

--------

18:14:53

 

SQL> exec dbms_lock.sleep(60);

 

PL/SQL procedure successfully completed.

 

SQL> exit

Oracle 11.2:

 

The script took 26 seconds to run. In that time, the database did 27 user commits. It waited 19 seconds for the log file parallel write event. It waited 23 seconds for the log file sync event. So, by reducing the number of commits, the time spent waiting on these two events was significantly reduced.

Logons Cumulative

The logons cumulative statistic in V$SYSSTAT shows how many sessions have connected since the database was opened. If this value is too high, there could be shell scripts looping round and connecting then disconnecting from the database. This can have a detrimental effect on performance.

SQL> col name format a20
SQL> select * from v$sysstat where name = 'logons cumulative'
  2  /

STATISTIC# NAME                 CLASS      VALUE      STAT_ID
---------- -------------------- ---------- ---------- ----------
0          logons cumulative    1          44         2666645286

SQL>

If you reconnect to the database, the value should increase by 1.

SQL> conn system/manager@adhoc
Connected.
SQL> select * from v$sysstat where name = 'logons cumulative'
  2  /

STATISTIC# NAME                 CLASS      VALUE      STAT_ID
---------- -------------------- ---------- ---------- ----------
0          logons cumulative    1          45         2666645286

SQL>

redo log space wait time, redo buffer allocation retries, redo blocks written and log_buffer

The redo log space wait time statistic records the total amount of time spent (since the instance was started) waiting for space in the redo log buffer. It is recorded in hundredths of a second:

 

SQL> select to_number(value)/100 "Seconds Waited"

  2  from v$sysstat

  3  where name = 'redo log space wait time'

  4  /

 

Seconds Waited

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

         96.63

 

SQL>

 

The redo buffer allocation retries statistic shows the total number of times a user process has had to wait for space in the redo log buffer (since instance startup again):

 

SQL> select value from v$sysstat

  2  where name = 'redo buffer allocation retries'

  3  /

 

VALUE

------

2463

 

SQL>

 

The lower these two statistics are, the better. However, you need to look at them in relation to the length of time the instance has been running. The figures above would be bad in an instance started 10 minutes ago but this Oracle 10.2.0.1.0 one was started in June:

 

SQL> select startup_time from v$instance

  2  /

 

STARTUP_TIME

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

15-JUN-13

 

SQL>

 

…and it is December now so the instance has been up for almost six months:

 

SQL> select sysdate from dual

  2  /

 

SYSDATE

---------

13-DEC-13

 

SQL>

 

You also need to compare them with the amount of redo activity. This instance has had its fair share so the wait statistics start to look even better:

 

SQL> select value from v$sysstat

  2  where name = 'redo blocks written'

  3  /

 

VALUE

----------

167877393

 

SQL>

 

Finally, you need to check whether the statistics are currently increasing. If they are high but stable right now, they may have caused a performance problem in the past but they are not causing one at present.

 

If these statistics caused problems in Oracle 9, you could try increasing the size of the log_buffer initialization parameter. You can check its value as follows:

 

SQL> select value from v$parameter

  2  where name = 'log_buffer'

  3  /

 

VALUE

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

2104320

 

SQL>

 

However, in more recent versions, Oracle calculates the value of this parameter for you. Fortunately, these statistics have never caused a problem in any databases I have had to monitor.

How to Add Conditions After a Where Clause

I went on an Oracle 9i DBA Performance and Tuning course in 2005 and was looking through the course notes recently to find something to blog about. They suggested that if you had conditions after a WHERE clause joined by AND, you should put the test which was most likely to fail first. This would then save Oracle the bother of evaluating the subsequent condition(s). This seemed reasonable so I decided to try it out.

I copied the contents of DBA_TABLES into a table of my own called T1 and duplicated its contents repeatedly until it had over three million rows. Then I checked that every row had TABLE_LOCK set to ENABLED and that no rows had an owner called BLAH.

SQL> create table t1 as select * from dba_tables

  2  /

 

Table created.

 

SQL> begin

  2  for a in 1..11 loop

  3  insert into t1 select * from t1;

  4  end loop;

  5  end;

  6  /

 

PL/SQL procedure successfully completed.

 

SQL> commit

  2  /

 

Commit complete.

 

SQL> select count(*) from t1

  2  /

 

  COUNT(*)

----------

   3217408

 

SQL> select count(*) from t1 where table_lock = 'ENABLED'

  2  /

 

  COUNT(*)

----------

   3217408

 

SQL> select count(*) from t1 where owner = 'BLAH'

  2  /

 

  COUNT(*)

----------

         0

 

SQL>

Then I ran the first SELECT statement as follows. If the course notes were correct, the first condition should reject every row and the second condition should never be evaluated:

SQL> alter system flush shared_pool

  2  /

 

System altered.

 

SQL> conn /

Connected.

SQL> select count(*) from t1

  2  where owner = 'BLAH'

  3  and table_lock = 'ENABLED'

  4  /

 

  COUNT(*)

----------

         0

 

SQL> select a.value/100 "CPU Used"

  2  from v$mystat a, v$sysstat b

  3  where a.statistic# = b.statistic#

  4  and name = 'CPU used by this session'

  5  /

 

  CPU Used

----------

     13.83

 

SQL>

Then I ran the second SELECT statement shown below. It was identical to the first but the conditions were swapped round. If the course notes were correct, the first condition should accept each row, forcing Oracle to evaluate the second condition every time. Notice how the CPU Used figure increased. I repeated this test five times and got similar results each time. So far so good:

SQL> alter system flush shared_pool

  2  /

 

System altered.

 

SQL> conn /

Connected.

SQL> select count(*) from t1

  2  where table_lock = 'ENABLED'

  3  and owner = 'BLAH'

  4  /

 

  COUNT(*)

----------

         0

 

SQL> select a.value/100 "CPU Used"

  2  from v$mystat a, v$sysstat b

  3  where a.statistic# = b.statistic#

  4  and name = 'CPU used by this session'

  5  /

 

  CPU Used

----------

     14.27

 

SQL>

The course notes also suggested that if you had conditions after a WHERE clause joined by OR, you should put the test which was most likely to succeed first. This would then save Oracle the bother of evaluating the subsequent condition(s). I decided to try this out too, using the table T1, which I created above.

I ran the third SELECT statement like this. If the course notes were correct, the first condition should accept every row and the second condition should never be evaluated: 

SQL> alter system flush shared_pool

  2  / 

System altered.

 

SQL> conn /

Connected.

SQL> select count(*) from t1

  2  where table_lock = 'ENABLED'

  3  or owner = 'BLAH'

  4  /

  COUNT(*)

----------

   3217408

SQL> select a.value/100 "CPU Used"

  2  from v$mystat a, v$sysstat b

  3  where a.statistic# = b.statistic#

  4  and name = 'CPU used by this session'

  5  / 

  CPU Used

----------

     14.17 

SQL>

Finally, I ran the fourth SELECT statement. It was identical to the third but the conditions were swapped round. If the course notes were correct, the first condition should reject each row, forcing Oracle to evaluate the second condition every time. Notice how the CPU Used figure increased. I repeated this test five times as well and got similar results each time. I think this demonstrated that the course notes were correct:

SQL> alter system flush shared_pool

  2  /

 

System altered.

 

SQL> conn /

Connected.

SQL> select count(*) from t1

  2  where owner = 'BLAH'

  3  or table_lock = 'ENABLED'

  4  /

 

  COUNT(*)

----------

   3217408

 

SQL> select a.value/100 "CPU Used"

  2  from v$mystat a, v$sysstat b

  3  where a.statistic# = b.statistic#

  4  and name = 'CPU used by this session'

  5  /

 

  CPU Used

----------

     14.79

 

SQL>