Following on from yesterday’s post on consistent reads, I thought I’d make the point that the way you work can make an enormous difference to the amount of work you do. Here’s a silly little demo (in 10.2.0.3):
drop table t1 purge; create table t1 (id number, n1 number); insert into t1 values (1,0); insert into t1 values (2,0); commit; execute dbms_stats.gather_table_stats(user,'t1') execute snap_my_stats.start_snap begin for i in 1..1000 loop update t1 set n1 = i where id = 1; end loop; end; / execute snap_my_stats.end_snap set doc off doc Output - 10.2.0.3 (some rows deleted) Name Value ---- ----- opened cursors cumulative 11 user calls 6 recursive calls 1,068 recursive cpu usage 7 session logical reads 4,041 CPU used when call started 7 CPU used by this session 7 DB time 6 db block gets 1,030 db block gets from cache 1,030 consistent gets 3,011 consistent gets from cache 3,011 consistent gets - examination 4 db block changes 2,015 change write time 4 free buffer requested 1,014 switch current to new buffer 1,000 calls to kcmgas 1,014 calls to get snapshot scn: kcmgss 3,009 redo entries 960 redo size 295,160 undo change vector size 111,584 no work - consistent read gets 1,004 table scans (short tables) 1,001 table scan rows gotten 2,002 table scan blocks gotten 1,001 buffer is pinned count 1,000 execute count 1,009 #
I’ve created two rows in a table, then updated one of them 1,000 times – using a table scan to do the update. I haven’t yet committed my transaction. At this point I’m going to use a second session to run the same update loop on the second row in the table:
begin for i in 1..1000 loop update t1 set n1 = i where id = 2; end loop; end; / Name Value ---- ----- opened cursors cumulative 8 user calls 6 recursive calls 1,009 recursive cpu usage 170 session logical reads 965,999 CPU used when call started 172 CPU used by this session 172 DB time 173 db block gets 1,030 db block gets from cache 1,030 consistent gets 964,969 consistent gets from cache 964,969 consistent gets - examination 961,965 db block changes 3,016 consistent changes 1,001,000 free buffer requested 1,015 CR blocks created 1,001 calls to kcmgas 1,015 calls to get snapshot scn: kcmgss 3,008 redo entries 1,936 redo size 358,652 undo change vector size 111,608 data blocks consistent reads - undo records applied 1,001,000 cleanouts and rollbacks - consistent read gets 1,001 immediate (CR) block cleanout applications 1,001 active txn count during cleanout 2,000 cleanout - number of ktugct calls 1,001 IMU CR rollbacks 41,041 table scans (short tables) 1,001 table scan rows gotten 2,002 table scan blocks gotten 1,001 execute count 1,006
Many of the statistics are (virtually) identical (e.g. “execute count”, “db block gets”, “free buffer requested”); some show an increase by 1,000 (often from zero) – largely because we have to worry 1,000 times about cleaning out the current block and creating a read-consistent version so that we can check if it can be updated.
But the most noticeable changes are in the “CPU time” and “consistent gets” because of the 1,000 times we have to apply 1,000 undo records to the block as we create the read-consistent version of the block. The CPU time has gone from 7 (hundredths of a second) to 172 because of (roughly) 1,000,000 “consistent gets – examination”. As I mentioned yesterday, this matches closely to “data blocks consistent reads – undo records applied” so we know why they are happening. Watch out in your batch jobs – if you have a lot of concurrent update activity going on a significant fraction of the workload may be the constant re-creation of CR clones.
However, there is another interesting detail to watch out for – what happens if I change the update execution path from a tablescan to an indexed access path:
create table t1 (id number, n1 number); insert into t1 values (1,0); insert into t1 values (2,0); commit; execute dbms_stats.gather_table_stats(user,'t1') create index t1_i1 on t1(id); -- Make indexed access path available.
Then with an index hint in my update code, I get the following effects (having done the same update loop on row 1 in the first session, of course):
begin for i in 1..1000 loop update /*+ index(t1) */ t1 set n1 = i where id = 2; -- indexed access path hinted end loop; end; / Name Value ---- ----- opened cursors cumulative 7 user calls 6 recursive calls 1,006 recursive cpu usage 11 session logical reads 2,036 CPU used when call started 11 CPU used by this session 11 DB time 11 db block gets 1,030 db block gets from cache 1,030 consistent gets 1,006 consistent gets from cache 1,006 consistent gets - examination 6 db block changes 2,015 free buffer requested 14 shared hash latch upgrades - no wait 1,000 calls to kcmgas 14 calls to get snapshot scn: kcmgss 1,004 redo entries 960 redo size 295,144 undo change vector size 111,608 index crx upgrade (positioned) 1,000 index scans kdiixs1 1,000 execute count 1,005
The difference is astonishing – where did all the ‘create CR copy’ activity go ?
I’ve pointed out before now that choosing a different execution plan for an update can have a big impact on performance – this is just another example demonstrating the point.