One of the problems in poorly written pl/sql batch processing is commiting inside a loop. Usually this is done keeping in mind that if the program aborts in while processing it can start from the point of failure.
The basic algorithm for this type of processing is like this
Begin
Loop
Do some processing
Do some DML (insert/update/delete)
Commit
End loop
End
Now what happens if you commit? The redo buffer is flushed into the redo log files. Disk I/O occurs. Commit is a costly operation. So if you look at the wait interface of the session doing this batch processing, the foremost non-idle event becomes “log file sync”. This means that the session waited mostly on the commit processing. As of pre-10g release 2, commit is a synchronous action and the client has to wait until the commit process finishes. So even if a loop the application is not generating enough redo and commits every time in a loop, the entire content of the redo log buffer gets flushed out to the log files. The two workarounds were doing a commit outside the loop (preferred one) or to do the commit in a batch.
Not any more! In Oracle 10G release 2, Oracle introduced a concept of asynchronous commit. Instead of commit just do “COMMIT WORK WRITE BATCH NOWAIT”, and it should be faster with less “log file sync” wait.
To test this statement I will modify Thomas Kyte’s Runstats package to incorporate the session wait statistics. The modified package and the table/view definations are as follows.
This table will store statistics data.
CREATE GLOBAL TEMPORARY TABLE RUN_STATS
( runid VARCHAR2(15),
NAME VARCHAR2(80),
VALUE INT )
ON COMMIT PRESERVE ROWS;
This table (New addition) will store wait statistics data.
CREATE GLOBAL TEMPORARY TABLE RUN_WAITS
( runid VARCHAR2(15),
NAME VARCHAR2(100),
VALUE INT )
ON COMMIT PRESERVE ROWS;
This view will give the statistics data for the current session
CREATE OR REPLACE VIEW stats
AS SELECT 'STAT...' || a.NAME NAME, b.VALUE
FROM v$statname a, v$mystat b
WHERE a.statistic# = b.statistic#
UNION ALL
SELECT 'LATCH.' || NAME, gets
FROM v$latch
UNION ALL
SELECT 'STAT...Elapsed Time', hsecs FROM v$timer;
This view (new addition) will give the wait statistics data for the current session
CREATE OR REPLACE VIEW waits
AS SELECT a.WAIT_CLASS ||'...'||a.EVENT NAME, a.TIME_WAITED_micro VALUE
FROM v$session_event a, (SELECT DISTINCT SID FROM v$mystat) b
WHERE
a.SID = b.SID
AND a.WAIT_CLASS <> 'Idle'
Modified package
CREATE OR REPLACE PACKAGE Runstats_Pkg
AS
PROCEDURE rs_start;
PROCEDURE rs_middle;
PROCEDURE rs_stop( p_difference_threshold IN NUMBER DEFAULT 0 );
END;
/
CREATE OR REPLACE PACKAGE BODY Runstats_Pkg
AS
g_start NUMBER;
g_run1 NUMBER;
g_run2 NUMBER;
PROCEDURE rs_start
IS
BEGIN
DELETE FROM RUN_STATS;
INSERT INTO RUN_STATS
SELECT 'before', stats.* FROM stats;
INSERT INTO RUN_WAITS
SELECT 'before', waits.* FROM waits;
g_start := DBMS_UTILITY.GET_TIME;
END;
PROCEDURE rs_middle
IS
BEGIN
g_run1 := (DBMS_UTILITY.GET_TIME-g_start);
INSERT INTO RUN_STATS
SELECT 'after 1', stats.* FROM stats;
INSERT INTO RUN_WAITS
SELECT 'after 1', waits.* FROM waits;
g_start := DBMS_UTILITY.GET_TIME;
END;
PROCEDURE rs_stop(p_difference_threshold IN NUMBER DEFAULT 0)
IS
BEGIN
g_run2 := (DBMS_UTILITY.GET_TIME-g_start);
DBMS_OUTPUT.PUT_LINE
( 'Run1 ran in ' || g_run1 || ' hsecs' );
DBMS_OUTPUT.PUT_LINE
( 'Run2 ran in ' || g_run2 || ' hsecs' );
DBMS_OUTPUT.PUT_LINE
( 'run 1 ran in ' || ROUND(g_run1/g_run2*100,2) ||
'% of the time' );
DBMS_OUTPUT.PUT_LINE( CHR(9) );
INSERT INTO RUN_STATS
SELECT 'after 2', stats.* FROM stats;
INSERT INTO RUN_WAITS
SELECT 'after 2', waits.* FROM waits;
DBMS_OUTPUT.PUT_LINE
( RPAD( 'Name', 30 ) || LPAD( 'Run1', 12 ) ||
LPAD( 'Run2', 12 ) || LPAD( 'Diff', 12 ) );
FOR x IN
( SELECT RPAD( a.NAME, 50 ) ||
TO_CHAR( b.VALUE-a.VALUE, '999,999,999' ) ||
TO_CHAR( c.VALUE-b.VALUE, '999,999,999' ) ||
TO_CHAR( ( (c.VALUE-b.VALUE)-(b.VALUE-a.VALUE)), '999,999,999' ) DATA
FROM RUN_STATS a, RUN_STATS b, RUN_STATS c
WHERE a.NAME = b.NAME
AND b.NAME = c.NAME
AND a.runid = 'before'
AND b.runid = 'after 1'
AND c.runid = 'after 2'
-- and (c.value-a.value) > 0
AND ABS( (c.VALUE-b.VALUE) - (b.VALUE-a.VALUE) )
> p_difference_threshold
ORDER BY ABS( (c.VALUE-b.VALUE)-(b.VALUE-a.VALUE))
) LOOP
DBMS_OUTPUT.PUT_LINE( x.DATA );
END LOOP;
DBMS_OUTPUT.PUT_LINE( CHR(9) );
DBMS_OUTPUT.PUT_LINE
( 'Run1 latches total versus runs -- difference and pct' );
DBMS_OUTPUT.PUT_LINE
( LPAD( 'Run1', 12 ) || LPAD( 'Run2', 12 ) ||
LPAD( 'Diff', 12 ) || LPAD( 'Pct', 10 ) );
FOR x IN
( SELECT TO_CHAR( run1, '999,999,999' ) ||
TO_CHAR( run2, '999,999,999' ) ||
TO_CHAR( diff, '999,999,999' ) ||
TO_CHAR( ROUND( run1/run2*100,2 ), '99,999.99' ) || '%' DATA
FROM ( SELECT SUM(b.VALUE-a.VALUE) run1, SUM(c.VALUE-b.VALUE) run2,
SUM( (c.VALUE-b.VALUE)-(b.VALUE-a.VALUE)) diff
FROM RUN_STATS a, RUN_STATS b, RUN_STATS c
WHERE a.NAME = b.NAME
AND b.NAME = c.NAME
AND a.runid = 'before'
AND b.runid = 'after 1'
AND c.runid = 'after 2'
AND a.NAME LIKE 'LATCH%'
)
) LOOP
DBMS_OUTPUT.PUT_LINE( x.DATA );
END LOOP;
DBMS_OUTPUT.PUT_LINE
( RPAD( 'Name', 50 ) || LPAD( 'Run1', 12 ) ||
LPAD( 'Run2', 12 ) || LPAD( 'Diff', 12 ) );
FOR x IN
( SELECT RPAD( a.NAME, 50 ) ||
TO_CHAR( b.VALUE-a.VALUE, '999,999,999' ) ||
TO_CHAR( c.VALUE-b.VALUE, '999,999,999' ) ||
TO_CHAR( ( (c.VALUE-b.VALUE)-(b.VALUE-a.VALUE)), '999,999,999' ) DATA
FROM RUN_WAITS a, RUN_WAITS b, RUN_WAITS c
WHERE a.NAME = b.NAME
AND b.NAME = c.NAME
AND a.runid = 'before'
AND b.runid = 'after 1'
AND c.runid = 'after 2'
-- and (c.value-a.value) > 0
AND ABS( (c.VALUE-b.VALUE) - (b.VALUE-a.VALUE) )
> p_difference_threshold
ORDER BY ABS( (c.VALUE-b.VALUE)-(b.VALUE-a.VALUE))
) LOOP
DBMS_OUTPUT.PUT_LINE( x.DATA );
END LOOP;
END;
END;
/
Once all the base table/view/packages have been created, let’s setup the actual test table. We create an empty table.
CREATE TABLE T AS
SELECT object_id,owner ,object_name
FROM all_objects
WHERE 1=2;
We then run a set of SQL, PL/SQL scripts and in between the scripts capture the statistics.
-- First we cleanup the tables
DELETE FROM RUN_STATS;
DELETE FROM RUN_WAITS;
DELETE FROM T;
COMMIT;
-- Capture the initial statistics to form the base line
BEGIN
Runstats_Pkg.rs_start;
END;
/
-- Run the first procedure with synchronous commit
BEGIN
FOR c IN (SELECT OBJECT_ID, OWNER, OBJECT_NAME
FROM all_objects
WHERE ROWNUM <= 50000)
LOOP
INSERT INTO T
VALUES (c.OBJECT_ID, c.OWNER, c.OBJECT_NAME);
COMMIT;
END LOOP;
EXCEPTION
WHEN OTHERS THEN
NULL;
END;
/
-- Capture the statistics data after the first run
EXEC Runstats_Pkg.rs_middle;
-- The second run with asynchronous commit.
BEGIN
FOR c IN (SELECT OBJECT_ID, OWNER, OBJECT_NAME
FROM all_objects
WHERE ROWNUM <= 50000)
LOOP
INSERT INTO T
VALUES (c.OBJECT_ID, c.OWNER, c.OBJECT_NAME);
COMMIT WORK WRITE batch NOWAIT;
END LOOP;
EXCEPTION
WHEN OTHERS THEN
NULL;
END;
/
-- Capture the statistics data after the second run and print the difference.
EXEC Runstats_Pkg.rs_stop();
Although the process is repeated a number of times ( I also swapped the order of the PL/SQL scripts), the results are consistent and one sample is given here.
Run1 ran in 1300 hsecs
Run2 ran in 1120 hsecs
run 1 ran in 116.07% of the time
Name Run1 Run2 Diff
STAT...redo synch writes 1 0 -1
STAT...heap block compress 277 278 1
LATCH.OS process: request allocation 1 0 -1
LATCH.channel handle pool latch 1 0 -1
LATCH.event group latch 1 0 -1
LATCH.parameter table allocation management 1 0 -1
LATCH.ksuosstats global area 1 0 -1
LATCH.process group creation 1 0 -1
LATCH.session switching 1 0 -1
LATCH.process allocation 1 0 -1
LATCH.kwqbsn:qsga 1 0 -1
LATCH.ncodef allocation latch 1 0 -1
LATCH.SQL memory manager latch 4 3 -1
STAT...auto extends on undo tablespace 2 1 -1
LATCH.JS slv state obj latch 1 0 -1
LATCH.transaction branch allocation 1 0 -1
LATCH.sort extent pool 1 0 -1
LATCH.resmgr:actses change group 1 0 -1
LATCH.Shared B-Tree 1 0 -1
STAT...parse time elapsed 8 6 -2
LATCH.user lock 2 0 -2
LATCH.kks stats 2 0 -2
LATCH.job_queue_processes parameter latch 2 0 -2
LATCH.SGA IO buffer pool latch 2 0 -2
LATCH.list of block allocation 2 0 -2
STAT...physical reads cache prefetch 2 0 -2
STAT...shared hash latch upgrades - no wait 29,540 29,538 -2
STAT...physical read total multi block requests 2 0 -2
LATCH.resmgr:free threads list 3 0 -3
LATCH.PL/SQL warning settings 6 3 -3
LATCH.resmgr:actses active list 3 0 -3
LATCH.dummy allocation 3 0 -3
STAT...write clones created in foreground 2 6 4
LATCH.parallel query alloc buffer 0 4 4
LATCH.session state list latch 4 0 -4
LATCH.FOB s.o list latch 8 4 -4
LATCH.FIB s.o chain latch 8 4 -4
STAT...commit txn count during cleanout 0 4 4
STAT...active txn count during cleanout 0 4 4
LATCH.resmgr group change latch 5 0 -5
STAT...physical write total multi block requests 10 5 -5
LATCH.OS process allocation 9 4 -5
STAT...parse time cpu 7 2 -5
STAT...consistent changes 17 23 6
STAT...bytes received via SQL*Net from client 1,027 1,033 6
STAT...cleanout - number of ktugct calls 0 6 6
LATCH.OS process 6 0 -6
LATCH.library cache pin allocation 8 2 -6
LATCH.qmn task queue latch 6 0 -6
STAT...consistent gets - examination 17,572 17,580 8
LATCH.post/wait queue 9 0 -9
LATCH.dml lock allocation 99,779 99,768 -11
LATCH.library cache lock allocation 14 0 -14
STAT...hot buffers moved to head of LRU 190 204 14
LATCH.active service list 35 20 -15
STAT...physical write total IO requests 32 16 -16
LATCH.client/application info 25 0 -25
LATCH.active checkpoint queue latch 76 50 -26
LATCH.JS queue state obj latch 108 72 -36
LATCH.shared pool 8,052 8,015 -37
LATCH.multiblock read objects 44 0 -44
STAT...change write time 97 52 -45
STAT...recursive cpu usage 999 897 -102
STAT...physical read total IO requests 114 216 102
STAT...free buffer requested 913 1,034 121
STAT...physical reads cache 74 195 121
STAT...physical reads 74 195 121
STAT...physical read IO requests 72 195 123
STAT...CPU used when call started 1,149 1,012 -137
STAT...CPU used by this session 1,149 1,012 -137
LATCH.library cache lock 2,916 2,768 -148
STAT...DB time 1,298 1,122 -176
STAT...Elapsed Time 1,300 1,123 -177
LATCH.SQL memory manager workarea list latch 613 410 -203
STAT...deferred (CURRENT) block cleanout applicati 25,570 25,276 -294
STAT...dirty buffers inspected 1,311 1,001 -310
STAT...IMU undo allocation size 18,271,452 18,271,136 -316
STAT...free buffer inspected 1,410 1,077 -333
LATCH.object queue header operation 5,555 5,184 -371
LATCH.checkpoint queue latch 1,752 1,238 -514
STAT...IMU commits 48,236 48,807 571
STAT...IMU Flushes 1,646 1,075 -571
LATCH.compile environment latch 50,549 49,952 -597
LATCH.session idle bit 50,578 49,974 -604
STAT...calls to kcmgas 50,501 49,889 -612
STAT...calls to kcmgcs 997 373 -624
LATCH.In memory undo latch 200,702 200,062 -640
LATCH.cache buffers lru chain 5,119 4,007 -1,112
LATCH.transaction allocation 1,150 2 -1,148
LATCH.file cache latch 1,272 19 -1,253
LATCH.Consistent RBA 1,617 27 -1,590
LATCH.lgwr LWN SCN 1,620 27 -1,593
LATCH.mostly latch-free SCN 1,620 27 -1,593
STAT...session cursor cache hits 3,219 1,350 -1,869
STAT...parse count (total) 3,221 1,352 -1,869
STAT...execute count 54,481 52,612 -1,869
STAT...table scans (short tables) 1,943 74 -1,869
STAT...opened cursors cumulative 3,221 1,352 -1,869
STAT...enqueue conversions 2,004 9 -1,995
STAT...messages sent 2,239 30 -2,209
LATCH.channel operations parent latch 2,830 42 -2,788
STAT...no work - consistent read gets 38,576 35,454 -3,122
STAT...table scan blocks gotten 4,946 1,824 -3,122
LATCH.redo allocation 103,019 99,824 -3,195
LATCH.simulator lru latch 22,958 19,376 -3,582
LATCH.simulator hash latch 23,125 19,535 -3,590
LATCH.redo writing 4,940 139 -4,801
STAT...redo entries 60,006 52,603 -7,403
LATCH.library cache pin 118,440 110,862 -7,578
STAT...db block changes 209,312 201,246 -8,066
LATCH.messages 8,455 255 -8,200
LATCH.library cache 171,893 163,604 -8,289
STAT...consistent gets 91,524 82,807 -8,717
STAT...consistent gets from cache 91,524 82,807 -8,717
STAT...calls to get snapshot scn: kcmgss 70,838 62,113 -8,725
STAT...enqueue requests 110,225 99,858 -10,367
STAT...enqueue releases 110,225 99,858 -10,367
STAT...recursive calls 171,893 155,688 -16,205
STAT...db block gets 219,452 201,096 -18,356
STAT...db block gets from cache 219,452 201,096 -18,356
LATCH.undo global data 268,262 249,041 -19,221
LATCH.enqueues 70,429 50,268 -20,161
LATCH.enqueue hash chains 223,981 199,896 -24,085
STAT...table scan rows gotten 120,891 95,425 -25,466
STAT...session logical reads 310,976 283,903 -27,073
LATCH.session allocation 143,171 110,834 -32,337
STAT...commit nowait requested 0 49,882 49,882
STAT...commit batch performed 0 49,882 49,882
STAT...commit nowait performed 0 49,882 49,882
STAT...commit batch/immediate requested 0 49,882 49,882
STAT...commit batch requested 0 49,882 49,882
STAT...commit batch/immediate performed 0 49,882 49,882
STAT...commit wait/nowait performed 0 49,882 49,882
STAT...commit wait/nowait requested 0 49,882 49,882
LATCH.row cache objects 103,882 36,261 -67,621
LATCH.cache buffers chains 1,322,635 1,252,539 -70,096
STAT...undo change vector size 6,517,676 6,389,556 -128,120
STAT...IMU Redo allocation size 623,552 368,880 -254,672
STAT...physical read total bytes 1,261,568 1,925,120 663,552
STAT...redo size 25,840,908 25,041,776 -799,132
STAT...physical read bytes 606,208 1,597,440 991,232
STAT...physical write total bytes 10,797,056 5,398,528 -5,398,528
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
3,026,635 2,739,434 -287,201 110.48%
Name Run1 Run2 Diff
Network...SQL*Net message to client 11 14 3
Commit...log file sync 383 0 -383
User I/O...db file single write 1,000 527 -473
System I/O...control file parallel write 6,482 3,093 -3,389
User I/O...db file scattered read 12,610 0 -12,610
Other...events in waitclass Other 76,610 2,393 -74,217
User I/O...Data file init write 199,992 99,670 -100,322
User I/O...db file sequential read 587,410 702,299 114,889
System I/O...control file sequential read 214,607 89,121 -125,486
As we can see from the results (important portions are made bold), the asynchronous commit took less time.
Run1 ran in 1300 hsecs
Run2 ran in 1120 hsecs
Also from the wait statistics, we can see that log file sync event disappeared.
Name Run1 Run2 Diff
Commit...log file sync 383 0 -383
Some new statistics appeared as
Name Run1 Run2 Diff
STAT...commit nowait requested 0 49,882 49,882
STAT...commit batch performed 0 49,882 49,882
STAT...commit nowait performed 0 49,882 49,882
STAT...commit batch/immediate requested 0 49,882 49,882
STAT...commit batch requested 0 49,882 49,882
STAT...commit batch/immediate performed 0 49,882 49,882
STAT...commit wait/nowait performed 0 49,882 49,882
STAT...commit wait/nowait requested 0 49,882 49,882
Also the redo writing latch reduced.
Name Run1 Run2 Diff
LATCH.redo writing 4,940 139 -4,801
Evidently it is a helpful addition for batch process but is it a replacement for writing good code? Let’s test out that. We change the script a bit to accommodate the “better” code…the select insert.
-- First we cleanup the tables
DELETE FROM RUN_STATS;
DELETE FROM RUN_WAITS;
DELETE FROM T;
COMMIT;
-- Capture the initial statistics to form the base line
BEGIN
Runstats_Pkg.rs_start;
END;
/
-- Run the first procedure with asynchronous commit
BEGIN
FOR c IN (SELECT OBJECT_ID,OWNER ,OBJECT_NAME
FROM all_objects
WHERE ROWNUM <= 50000)
LOOP
INSERT INTO T
VALUES(c.OBJECT_ID,c.OWNER ,c.OBJECT_NAME);
COMMIT WORK WRITE batch NOWAIT;
END LOOP;
EXCEPTION
WHEN OTHERS THEN
NULL;
END;
/
-- Capture the statistics data after the first run
EXEC Runstats_Pkg.rs_middle;
/
-- The second run with bulk insert
BEGIN
INSERT INTO T
(object_id, owner, object_name)
SELECT object_id, owner, object_name
FROM all_objects
WHERE ROWNUM <= 50000;
COMMIT;
END;
/
-- Capture the statistics data after the second run and print the difference.
EXEC Runstats_Pkg.rs_stop();
And the results are as follows
Run1 ran in 995 hsecs
Run2 ran in 189 hsecs
run 1 ran in 526.46% of the time
Name Run1 Run2 Diff
LATCH.ksuosstats global area 1 0 -1
LATCH.session switching 1 0 -1
STAT...opened cursors cumulative 1,334 1,335 1
LATCH.transaction branch allocation 1 0 -1
LATCH.sort extent pool 1 0 -1
STAT...redo synch writes 0 1 1
LATCH.post/wait queue 0 1 1
STAT...workarea executions - optimal 7 8 1
STAT...cursor authentications 1 0 -1
LATCH.PL/SQL warning settings 3 2 -1
STAT...heap block compress 277 278 1
STAT...table fetch continued row 60 61 1
LATCH.ncodef allocation latch 1 0 -1
STAT...SQL*Net roundtrips to/from client 3 2 -1
LATCH.library cache pin allocation 4 6 2
LATCH.file cache latch 2 0 -2
STAT...table scans (short tables) 56 54 -2
STAT...write clones created in foreground 2 0 -2
STAT...redo synch time 0 2 2
STAT...user calls 6 4 -2
STAT...parse count (hard) 0 2 2
STAT...session cursor cache hits 1,331 1,329 -2
STAT...table fetch by rowid 17,519 17,521 2
LATCH.OS process allocation 3 1 -2
STAT...parse count (total) 1,334 1,331 -3
STAT...commit txn count during cleanout 0 3 3
STAT...parse time cpu 2 6 4
LATCH.session timer 4 0 -4
LATCH.KMG MMAN ready and startup request latch 4 0 -4
LATCH.kks stats 0 4 4
STAT...parse time elapsed 1 6 5
STAT...consistent changes 15 22 7
LATCH.active checkpoint queue latch 12 2 -10
LATCH.active service list 20 2 -18
LATCH.lgwr LWN SCN 27 3 -24
LATCH.mostly latch-free SCN 27 3 -24
LATCH.list of block allocation 0 24 24
LATCH.Consistent RBA 27 3 -24
STAT...messages sent 29 3 -26
LATCH.channel operations parent latch 42 14 -28
STAT...consistent gets from cache 82,710 82,661 -49
STAT...consistent gets 82,710 82,661 -49
STAT...change write time 68 0 -68
LATCH.JS queue state obj latch 72 0 -72
LATCH.library cache lock 2,814 2,888 74
LATCH.redo writing 100 13 -87
STAT...buffer is not pinned count 64,833 64,744 -89
LATCH.shared pool 8,019 8,113 94
STAT...calls to kcmgcs 379 276 -103
STAT...hot buffers moved to head of LRU 122 0 -122
LATCH.SQL memory manager workarea list latch 410 276 -134
LATCH.messages 165 23 -142
STAT...bytes sent via SQL*Net to client 441 262 -179
STAT...active txn count during cleanout 3 275 272
STAT...cleanout - number of ktugct calls 3 276 273
STAT...consistent gets - examination 17,575 17,850 275
LATCH.row cache objects 35,987 36,334 347
STAT...bytes received via SQL*Net from client 945 535 -410
STAT...table scan blocks gotten 1,789 1,295 -494
STAT...buffer is pinned count 52,828 53,412 584
STAT...no work - consistent read gets 35,419 34,834 -585
LATCH.checkpoint queue latch 868 222 -646
STAT...recursive cpu usage 851 188 -663
STAT...dirty buffers inspected 780 0 -780
STAT...CPU used when call started 990 188 -802
STAT...CPU used by this session 990 188 -802
STAT...DB time 994 191 -803
STAT...Elapsed Time 997 190 -807
STAT...free buffer requested 828 17 -811
STAT...free buffer inspected 836 0 -836
STAT...IMU Flushes 1,055 1 -1,054
LATCH.cache buffers lru chain 3,148 612 -2,536
LATCH.object queue header operation 4,040 449 -3,591
LATCH.simulator lru latch 20,412 3,524 -16,888
LATCH.simulator hash latch 20,554 3,527 -17,027
STAT...deferred (CURRENT) block cleanout applicati 25,266 4 -25,262
STAT...table scan rows gotten 95,234 53,580 -41,654
STAT...IMU commits 48,827 0 -48,827
STAT...commit cleanouts successfully completed 49,882 273 -49,609
STAT...commit cleanouts 49,886 277 -49,609
STAT...calls to get snapshot scn: kcmgss 62,023 12,399 -49,624
STAT...user commits 49,882 1 -49,881
STAT...commit batch/immediate requested 49,882 0 -49,882
STAT...commit nowait performed 49,882 0 -49,882
STAT...commit wait/nowait performed 49,882 0 -49,882
STAT...commit nowait requested 49,882 0 -49,882
STAT...commit wait/nowait requested 49,882 0 -49,882
STAT...commit batch requested 49,882 0 -49,882
STAT...commit batch/immediate performed 49,882 0 -49,882
STAT...commit batch performed 49,882 0 -49,882
LATCH.compile environment latch 49,936 54 -49,882
STAT...calls to kcmgas 49,884 1 -49,883
STAT...execute count 52,594 2,710 -49,884
LATCH.session idle bit 49,958 62 -49,896
LATCH.enqueues 50,106 60 -50,046
STAT...redo entries 52,531 1,194 -51,337
LATCH.library cache pin 110,810 11,059 -99,751
LATCH.dml lock allocation 99,769 6 -99,763
STAT...enqueue requests 99,772 6 -99,766
STAT...enqueue releases 99,772 6 -99,766
LATCH.session allocation 110,512 10,730 -99,782
LATCH.redo allocation 99,822 8 -99,814
LATCH.library cache 163,573 14,093 -149,480
STAT...recursive calls 155,527 5,374 -150,153
STAT...db block gets 200,920 2,113 -198,807
STAT...db block gets from cache 200,920 2,113 -198,807
STAT...session logical reads 283,630 84,774 -198,856
STAT...db block changes 201,160 1,760 -199,400
LATCH.enqueue hash chains 199,708 14 -199,694
LATCH.In memory undo latch 200,044 4 -200,040
LATCH.undo global data 248,887 284 -248,603
STAT...IMU Redo allocation size 360,116 11,072 -349,044
LATCH.cache buffers chains 1,250,990 155,353 -1,095,637
STAT...undo change vector size 6,387,356 140,368 -6,246,988
STAT...IMU undo allocation size 18,271,452 880 -18,270,572
STAT...redo size 25,019,912 2,334,704 -22,685,208
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
2,736,191 253,080 -2,483,111 1,081.16%
Name Run1 Run2 Diff
Network...SQL*Net message to client 13 9 -4
Commit...log file sync 0 15,428 15,428
I need not elaborate more; the bulk insert ran 5 times faster than the cursor insert. Although the log file sync wait event returned, it did not matter. So my rule of thumb is, whenever possible, use bulk processing in case of batch jobs.
Also this proves that do whatever you are, bed code is never a substitute to good code and there is no silver bullet in tuning oracle other than removing bad code.