Oracle Scratchpad

April 19, 2011

More CR

Filed under: Infrastructure,Oracle,Performance,Read Consistency,Troubleshooting,undo — Jonathan Lewis @ 6:32 pm BST Apr 19,2011

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.

10 Comments »

  1. Hello Sir,

    just quick question is below are the typo’s or i miss something?

    consistent changes 1,001,000

    data blocks consistent reads – undo records applied 1,001,000

    Regard’s

    Henish

    Comment by henish — April 19, 2011 @ 7:50 pm BST Apr 19,2011 | Reply

    • Henish,

      Why do you think these might be typo’s ? Some comment about why you’re asking the question might prompt me to clear up your confusion and help other people at the same time.

      As it is, all I can say is that they’re not; which means you’re probably going to have to ask another question about them – which I might not have time to answer for another four of five days.

      Comment by Jonathan Lewis — April 24, 2011 @ 9:20 am BST Apr 24,2011 | Reply

      • Apologies for the confusion on my side

        The number make sense since there is 1000 update iterate in the loop in second session
        and each of the update create its own CR block which in turn needs to apply 1000
        rollback entries to undo the update done by the first sesssion i.e (1000*1000=1,000,000) which match
        with the number shown by “data blocks consistent reads – undo records applied”

        Hope my understanding is correct

        Thanks for your time

        Regards

        Comment by henish — April 26, 2011 @ 1:52 pm BST Apr 26,2011 | Reply

  2. Jonathan,

    I have to admitt I don’t understand where did the create CR copy activity go. If you had created index in the first demo (but used table scan for update), I would have understood the difference. However, there is some difference in updating table blocks, too. I thought Oracle was updating just indexes in “batch” at the end of update

    Comment by Pavol Babel — April 20, 2011 @ 7:38 am BST Apr 20,2011 | Reply

  3. Pavol,


      “I have to admit I don’t understand where did the create CR copy activity go.”

    That makes two of us. I haven’t come up with a good reason why performing an update during a tablescan should do something different from updating the same block in the same way after getting to the block by an indexed access path.

    Still, as I pointed out in “Tuning updates” and along the lines that you hint at in the later part of your comment – there are all sorts of code differences between tablescan updates and index-driven updates.

    Comment by Jonathan Lewis — April 24, 2011 @ 9:28 am BST Apr 24,2011 | Reply

    • I see, i thought you new what is behind. “Tuning updates” is interesting, but it is much more straightforward. Oracle uses somehow SCN from index and so it does not have to recreate CR versions. But it makes me angry, because I do not see more details of this very interesting behavior :)

      Comment by Pavol Babel — May 1, 2011 @ 11:38 am BST May 1,2011 | Reply

      • Pavol.
        There are times when I see an odd performance problem and would dearly love to ask Oracle for the manual page describing the details of some particular operation. But then I remember there are over 1,000 different ways of doing a “session logical read” and realise that there’s no chance.

        Comment by Jonathan Lewis — May 7, 2011 @ 7:57 am BST May 7,2011 | Reply

  4. “I haven’t come up with a good reason why performing an update during a tablescan should do something different from updating the same block in the same way after getting to the block by an indexed access path.”

    What occurs to me, and I’m not sure how it works internally, is where you update a row in block A that forces it to migrate to block Z. With an access from an index, you won’t pick up that row again. In the full scan situation, you will meet that row again when the scan gets to block Z. You need to remember somewhere that that row has already been processed by the statement, but that other rows in block Z haven’t been.

    Updates to chained rows also make my head hurt, when the same statement might need to pull in different values from different parts of the chain to determine whether the row should be updated and which parts of the chained row are affected by the update.

    Comment by Gary — April 25, 2011 @ 1:57 am BST Apr 25,2011 | Reply

    • Gary,

      I thought I’d written a reply to this already. I like your suggestion; whether it’s right or wrong it’s a good hypothesis to float as a possible explanation – now we just have to figure out some tests that prove that either it’s necessary or it’s wrong ;)

      Since I first planned to make that comment, by they way, another thought crossed my mind. In this example we’ve reached the row we want to change by way of an index probe that didn’t need any work to show that the current version was the read-consistent version of the index blocks – so Oracle can infer that the targetted row is the only relevant row in the block and that there are no other rows currently hidden by uncommitted or recently committed transactions. Moreover, by checking the commit SCNs of the committed transactions and start SCNS of the uncommitted transactions listed in the ITL Oracle can infer that the currently visible version of the row is the same as the read consistent version would be – so it doesn’t have to create the read-consistent version of the block.

      Comment by Jonathan Lewis — April 29, 2011 @ 11:29 am BST Apr 29,2011 | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,115 other followers