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.
That is a really useful demo and I will bookmark the URL and send it to our developers when we see evidence of too high a commit frequency. Of course it does depend on the application and say in a trading system you would want/need a commit after every transaction
ReplyDelete