Search

Top 60 Oracle Blogs

Recent comments

January 2011

Where is Sun?

First of all, may I wish everyone who comes by my blog a heartfelt Happy New Year.
Secondly, I promise I’ll blog more often and more on technical aspects this year than I have for most of 2010.
Thirdly, I’ll admit the title to this blog is nothing to do with the hardware company now owned by Mr Larry Ellison, but is about the huge glowing ball of fire in the sky (which we have not seen a lot of here in England and Wales for the last couple of weeks – not sure about Scotland but I suspect it has been the same). I apologise for the blatantly misleading (and syntactically poor) title.

A quick question for you – It is the depths of winter for most of us, and it has been unusually cold here in the UK and much of Europe. When are we, as a planet, furthest from the Sun during winter? January the 1st? The Shortest day (21st December)? The day the evening start drawing out (December 14th)?
I think many in the Northern Hemisphere will be surprised to learn that we are closest to the sun today (3rd Jan 2011). A mere 147.104 million kilometers from the centre of our solar system. I mentioned this to a few friends and they were all taken aback, thinking we would be furthest from the warmth of the sun at the depths of our winter.

Come the 4th July 2011 it is not only some strange celebration in the US about having made the terrible decision to go it alone in the world {Joke guys!}, but is the day in the year that the Earth is furthest from the sun – 152.097 million kilometers. That is about 3.39% further away and, as the energy we receive from the sun is equal to the square of the distance, does account for a bit of a drop in the energy received. {Surface of a sphere is 4*pi*(R{adius}squared), you can think of the energy from the sun as being spread over the sphere at any given distance}.

Some of you may be wondering why this furthest/closest to the sun does not match the longest/shortest day. As some of you may remember, I explained about the oddities of the shortest day not matching when the nights start drawing out about this time last year. It is because as we spin around our own pole and around the sun, things are complicated by the fact that the earth “leans over” in it’s orbit.

Check out this nice web site where you can state the location and month you want to see sunrise, sunset, day length and (of particular relevance here) the distance from the sun for each day.

I find it interesting that many of the things us most of us see as “common sense” are often not actually right (I always assumed that the shortest day coincided with both the evenings starting to draw out and mornings getting earlier until I stumbled across it when looking at sunset times – I had to go find a nice Astronomer friend to explain it all to me). I also like the fact that a very simple system – a regularly spinning ball circling a large big “fixed point” in a fixed way – throws up some oddities due to little extra considerations that often go overlooked. Isn’t that so like IT?

That lean in the Earth’s angle of spin compared to the plane we revolve around the sun is slowly rotating too, so in a few years (long, long, long after any of us will be around to care) then the furthest point in the orbit will indeed match the northern hemisphere winter. Again like IT, even the oddities keep shifting.

Redo

A couple of days ago I published a link to some comments I had made on OTN about differences in redo generation between 10g and earlier versions of Oracle. This raised a few questions that suggested a follow-up (or perhaps “prequel”) note might be a little helpful. So I’ve created a simple SQL script to help demonstrate the differences and show how some of the pieces hang together. The whole posting is a little lengthy, but a large fraction of it is just the continuous output from a couple of trace files from which I’ll be highlighting just a few lines.

drop table t1;

create table t1 (
	n1	number,
	n2	number,
	n3	number,
	n4	number
);

create index i1 on t1(n1);
create index i2 on t1(n2);

insert into t1 values (1,1,1,1);
commit;

alter system switch logfile;

insert into t1 values (2,2,2,2);
insert into t1 values (3,3,3,3);

commit;

execute dump_log

All I’ve done is create a simple table with two indexes. I insert a row and commit because the first insert of a row into a table results in all sorts of funny bits of recursive activity (mostly related space management) and I want to get that out of the way so that it doesn’t obscure the more typical activity. Then I “switch logfile”, do a little work, and use a little procedure I’ve written to dump the current log file. The log file switch is just a convenient way to keep the dump small – but there are strategies for being selective about the parts of the redo log file you dump.

The work I’ve done is just two inserts into the table – this means I expect to find something like the following bits of activity listed in the redo log file:

    start transaction
    modify block in table
    modify block in index 1
    modify block in index 2
    modify block in table
    modify block in index 1
    modify block in index 2
    end transaction

What I’m going to show you next is the redo log file dump from Oracle 9.2.0.8 and then the corresponding redo log file dump from 10.2.0.3.

In the 9.2.0.8 dump we’ll see the “traditional” sequence of redo generation, which follows very closely to the steps listed above and also shows that Oracle pairs a “redo change vector” for a table or index block with the matching “redo change vector” for an undo record that describes how to reverse the table (or index) change – an undo record, of course, is just a piece of information that gets stored in an undo block. In general, each pair of redo change vectors will be gathered into a single “redo record”.

In the 10.2.0.3 dump we’ll see that the same redo change vectors still exist but they’ve all been lumped into a single redo record, and their ordering in that record is completely different from the 9.2.0.8 ordering, demonstrating (or at least supporting) the point that the “private redo/in-memory undo” mechanism uses two separate buffers, one for redo change vectors related to table/index blocks (the private redo bit) and the other for redo change vectors related to undo records (the in-memory undo bit).

The key expressions to watch out for in the dump are: “REDO RECORD” and “CHANGE #” (I’ve inserted a few blank lines  into the trace file to give a little white space between records and vectors):

Redo log file dump from 9i

REDO RECORD - Thread:1 RBA: 0x000360.00000002.0010 LEN: 0x0170 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:23 AFN:2 DBA:0x00800039 SCN:0x0000.03ec99bf SEQ:  1 OP:5.2
ktudh redo: slt: 0x0016 sqn: 0x00001a69 flg: 0x0012 siz: 80 fbi: 0
            uba: 0x00800040.075d.26    pxid:  0x0000.000.00000000

CHANGE #2 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99be SEQ:  1 OP:5.1
ktudb redo: siz: 80 spc: 2708 flg: 0x0012 seq: 0x075d rec: 0x26
            xid:  0x0004.016.00001a69
ktubl redo: slt: 22 rci: 0 opc: 11.1 objn: 45648 objd: 45648 tsn: 12
Undo type:  Regular undo        Begin trans    Last buffer split:  No
Temp Object:  No
Tablespace Undo:  No
             0x00000000  prev ctl uba: 0x00800040.075d.25
prev ctl max cmt scn:  0x0000.03ebf084  prev tx cmt scn:  0x0000.03ebf106
KDO undo record:
KTB Redo
op: 0x03  ver: 0x01
op: Z
KDO Op code: DRP row dependencies Disabled
  xtype: XA  bdba: 0x02c0000a  hdba: 0x02c00009
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 1(0x1)

CHANGE #3 TYP:2 CLS: 1 AFN:11 DBA:0x02c0000a SCN:0x0000.03ec99f2 SEQ:  1 OP:11.2
KTB Redo
op: 0x01  ver: 0x01
op: F  xid:  0x0004.016.00001a69    uba: 0x00800040.075d.26
KDO Op code: IRP row dependencies Disabled
  xtype: XA  bdba: 0x02c0000a  hdba: 0x02c00009
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 1(0x1) size/delt: 15
fb: --H-FL-- lb: 0x2  cc: 4
null: ----
col  0: [ 2]  c1 03
col  1: [ 2]  c1 03
col  2: [ 2]  c1 03
col  3: [ 2]  c1 03

CHANGE #4 MEDIA RECOVERY MARKER SCN:0x0000.00000000 SEQ:  0 OP:5.20
session number   = 9
serial  number   = 6
transaction name =

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

REDO RECORD - Thread:1 RBA: 0x000360.00000002.0180 LEN: 0x0108 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99f5 SEQ:  1 OP:5.1
ktudb redo: siz: 96 spc: 2626 flg: 0x0022 seq: 0x075d rec: 0x27
            xid:  0x0004.016.00001a69
ktubu redo: slt: 22 rci: 38 opc: 10.22 objn: 45649 objd: 45649 tsn: 12
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x04  ver: 0x01
op: L  itl: xid:  0x000a.012.00002552 uba: 0x0080009c.09cb.0c
                      flg: C---    lkc:  0     scn: 0x0000.03ec99f2
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=96880916 indexid=0x2c00409 block=0x02c0040a
purge leaf row
key: (10):  02 c1 03 06 02 c0 00 0a 00 01

CHANGE #2 TYP:2 CLS: 1 AFN:11 DBA:0x02c0040a SCN:0x0000.03ec99f2 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x11  ver: 0x01
op: F  xid:  0x0004.016.00001a69    uba: 0x00800040.075d.27
Block cleanout record, scn:  0x0000.03ec99f5 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0000.03ec99f2
REDO: SINGLE / -- / --
itl: 2, sno: 1, row size 14
insert key: (10):  02 c1 03 06 02 c0 00 0a 00 01

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

REDO RECORD - Thread:1 RBA: 0x000360.00000003.0098 LEN: 0x0108 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99f5 SEQ:  2 OP:5.1
ktudb redo: siz: 96 spc: 2528 flg: 0x0022 seq: 0x075d rec: 0x28
            xid:  0x0004.016.00001a69
ktubu redo: slt: 22 rci: 39 opc: 10.22 objn: 45650 objd: 45650 tsn: 12
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x04  ver: 0x01
op: L  itl: xid:  0x000a.012.00002552 uba: 0x0080009c.09cb.0d
                      flg: C---    lkc:  0     scn: 0x0000.03ec99f2
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=96880916 indexid=0x2c00489 block=0x02c0048a
purge leaf row
key: (10):  02 c1 03 06 02 c0 00 0a 00 01

CHANGE #2 TYP:2 CLS: 1 AFN:11 DBA:0x02c0048a SCN:0x0000.03ec99f2 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x11  ver: 0x01
op: F  xid:  0x0004.016.00001a69    uba: 0x00800040.075d.28
Block cleanout record, scn:  0x0000.03ec99f5 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0000.03ec99f2
REDO: SINGLE / -- / --
itl: 2, sno: 1, row size 14
insert key: (10):  02 c1 03 06 02 c0 00 0a 00 01

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

REDO RECORD - Thread:1 RBA: 0x000360.00000003.01a0 LEN: 0x00f4 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99f5 SEQ:  3 OP:5.1
ktudb redo: siz: 64 spc: 2430 flg: 0x0022 seq: 0x075d rec: 0x29
            xid:  0x0004.016.00001a69
ktubu redo: slt: 22 rci: 40 opc: 11.1 objn: 45648 objd: 45648 tsn: 12
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
KDO undo record:
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.26
KDO Op code: DRP row dependencies Disabled
  xtype: XA  bdba: 0x02c0000a  hdba: 0x02c00009
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 2(0x2)

CHANGE #2 TYP:0 CLS: 1 AFN:11 DBA:0x02c0000a SCN:0x0000.03ec99f5 SEQ:  1 OP:11.2
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.29
KDO Op code: IRP row dependencies Disabled
  xtype: XA  bdba: 0x02c0000a  hdba: 0x02c00009
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 2(0x2) size/delt: 15
fb: --H-FL-- lb: 0x2  cc: 4
null: ----
col  0: [ 2]  c1 04
col  1: [ 2]  c1 04
col  2: [ 2]  c1 04
col  3: [ 2]  c1 04

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

REDO RECORD - Thread:1 RBA: 0x000360.00000004.00a4 LEN: 0x00c8 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99f5 SEQ:  4 OP:5.1
ktudb redo: siz: 80 spc: 2364 flg: 0x0022 seq: 0x075d rec: 0x2a
            xid:  0x0004.016.00001a69
ktubu redo: slt: 22 rci: 41 opc: 10.22 objn: 45649 objd: 45649 tsn: 12
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.27
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=96880916 indexid=0x2c00409 block=0x02c0040a
purge leaf row
key: (10):  02 c1 04 06 02 c0 00 0a 00 02

CHANGE #2 TYP:0 CLS: 1 AFN:11 DBA:0x02c0040a SCN:0x0000.03ec99f5 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.2a
REDO: SINGLE / -- / --
itl: 2, sno: 2, row size 14
insert key: (10):  02 c1 04 06 02 c0 00 0a 00 02

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

REDO RECORD - Thread:1 RBA: 0x000360.00000004.016c LEN: 0x00c8 VLD: 0x01
SCN: 0x0000.03ec99f5 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:24 AFN:2 DBA:0x00800040 SCN:0x0000.03ec99f5 SEQ:  5 OP:5.1
ktudb redo: siz: 80 spc: 2282 flg: 0x0022 seq: 0x075d rec: 0x2b
            xid:  0x0004.016.00001a69
ktubu redo: slt: 22 rci: 42 opc: 10.22 objn: 45650 objd: 45650 tsn: 12
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.28
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=96880916 indexid=0x2c00489 block=0x02c0048a
purge leaf row
key: (10):  02 c1 04 06 02 c0 00 0a 00 02

CHANGE #2 TYP:0 CLS: 1 AFN:11 DBA:0x02c0048a SCN:0x0000.03ec99f5 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x00800040.075d.2b
REDO: SINGLE / -- / --
itl: 2, sno: 2, row size 14
insert key: (10):  02 c1 04 06 02 c0 00 0a 00 02

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

REDO RECORD - Thread:1 RBA: 0x000360.00000005.0044 LEN: 0x0070 VLD: 0x01
SCN: 0x0000.03ec99f6 SUBSCN:  1 12/30/2010 14:36:06

CHANGE #1 TYP:0 CLS:23 AFN:2 DBA:0x00800039 SCN:0x0000.03ec99f5 SEQ:  1 OP:5.4
ktucm redo: slt: 0x0016 sqn: 0x00001a69 srt: 0 sta: 9 flg: 0x12
ktucf redo: uba: 0x00800040.075d.2b ext: 0 spc: 2200 fbi: 0

The dump from 9.2.0.8 consists of seven redo records – and most of those records consist of two redo change vectors. We’ll start by looking at the fourth redo record (starting at line 112) which is a typical “old-style” redo record. It consists of two redo change vectors.

In the chosen record, change #1 (line 115) describes how to change an undo block at address (DBA) 0×00800040 which is operating at sequence number (seq: ) 0x075d. The change is to insert a new undo record, with record number (rec: ) 0×29. If you look at lines 126 – 129 you see that this undo record is an instruction to Delete a Row Piece (DRP) from data block (bdba) 0x02c0000a; the row piece is identified as the pointed to by slot 2 of table 0 in the block’s row directory.

Change # 2 (line 131) describes the change needed to create that row piece (note the IRP – Insert Row Piece at line 135). Again we see references to the block, table number and slot number.

The next two redo records are very similar: they describe how to insert and delete a key entry for each of the two indexes that have to be maintained as the row is inserted into the table – again the redo change vector for the “undo” appears before the redo change vector for the “apply”.

The first three redo records form a similar group – the first one is about inserting/removing a table row, the second and third are about the insert/remove pairs for the two indexes – but the first record of the three is more complex, consisting of four redo change vectors rather than just two.

The first redo record happens to be the first record of the transaction – so it contains (for 9i and below) two extra redo change vectors. The standard pair for the table row appear as change #2 and change #3, but in change #1 we see the redo change vector describing a change to the undo segment header block (line 5: ktudh) as we acquire a “transaction table slot” (see my glossary, and “cleanout”) specifically slot 0×0016, which we stamp with sequence number 0x00001a69. The final change vector in this record (change #4 at line 41) is marked as a “Media Recovery Marker” – it’s actually a type of audit label – and the example here is the short form; there is a much longer version used for the first transaction of a session’s lifetime, which is also used after each log file switch that takes place in a session’s lifetime (and in 8i there was a bug that meant the full vector appeared for every transaction start – with could result in a nasty volume of excess redo).

The last redo record is the so-called “commit record”. It consists of just one change vector (line 209). This change vector describes the update to the undo segment header as we commit (ktucm) the transaction; the status (sta: ) of transaction table slot 0×0016 is set to 9 to show that the slot is now free, and the “free pool” list (ktucf) is updated to show that the last undo block we were using has some space available in it that could be used by the next transaction that acquires a slot in this undo segment.

So that’s the redo generated by 9i. The basic pattern is that a typical redo record consists of a pair of redo change vectors, the first describing an undo record and the second describing how to make the required data change.

An important scalability detail (or threat, rather) that goes with this implementation is that the session has to allocate memory in the redo log buffer and copy each redo record in turn so, for our table with two indexes, every row we insert requires us to acquire the redo allocation latch and redo copy latch three times.

Now we move on to see what shows up in the log file when we run our code on 10.2.0.3

Redo log file dump from 10g

REDO RECORD - Thread:1 RBA: 0x00034b.00000002.0010 LEN: 0x0638 VLD: 0x0d
SCN: 0x0000.00d60a85 SUBSCN:  1 12/30/2010 14:24:01

CHANGE #1 TYP:2 CLS: 1 AFN:6 DBA:0x01804d8a OBJ:70577 SCN:0x0000.00d60a81 SEQ:  5 OP:11.2
KTB Redo
op: 0x01  ver: 0x01
op: F  xid:  0x0008.025.00003632    uba: 0x008031d3.07f1.27
KDO Op code: IRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01804d8a  hdba: 0x01804d89
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 1(0x1) size/delt: 15
fb: --H-FL-- lb: 0x2  cc: 4
null: ----
col  0: [ 2]  c1 03
col  1: [ 2]  c1 03
col  2: [ 2]  c1 03
col  3: [ 2]  c1 03

CHANGE #2 TYP:0 CLS:31 AFN:2 DBA:0x00800079 OBJ:4294967295 SCN:0x0000.00d60a5f SEQ:  1 OP:5.2
ktudh redo: slt: 0x0025 sqn: 0x00003632 flg: 0x0012 siz: 104 fbi: 0
            uba: 0x008031d3.07f1.27    pxid:  0x0000.000.00000000

CHANGE #3 TYP:2 CLS: 1 AFN:6 DBA:0x01804e0a OBJ:70578 SCN:0x0000.00d60a81 SEQ:  2 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x11  ver: 0x01
op: F  xid:  0x0008.025.00003632    uba: 0x008031d3.07f1.28
Block cleanout record, scn:  0x0000.00d60a84 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0000.00d60a81
REDO: SINGLE / -- / --
itl: 2, sno: 1, row size 14
insert key: (10):  02 c1 03 06 01 80 4d 8a 00 01

CHANGE #4 TYP:2 CLS: 1 AFN:6 DBA:0x01804e8a OBJ:70579 SCN:0x0000.00d60a81 SEQ:  2 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x11  ver: 0x01
op: F  xid:  0x0008.025.00003632    uba: 0x008031d3.07f1.29
Block cleanout record, scn:  0x0000.00d60a84 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0000.00d60a81
REDO: SINGLE / -- / --
itl: 2, sno: 1, row size 14
insert key: (10):  02 c1 03 06 01 80 4d 8a 00 01

CHANGE #5 TYP:0 CLS: 1 AFN:6 DBA:0x01804d8a OBJ:70577 SCN:0x0000.00d60a85 SEQ:  1 OP:11.2
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.2a
KDO Op code: IRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01804d8a  hdba: 0x01804d89
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 2(0x2) size/delt: 15
fb: --H-FL-- lb: 0x2  cc: 4
null: ----
col  0: [ 2]  c1 04
col  1: [ 2]  c1 04
col  2: [ 2]  c1 04
col  3: [ 2]  c1 04

CHANGE #6 TYP:0 CLS: 1 AFN:6 DBA:0x01804e0a OBJ:70578 SCN:0x0000.00d60a85 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.2b
REDO: SINGLE / -- / --
itl: 2, sno: 2, row size 14
insert key: (10):  02 c1 04 06 01 80 4d 8a 00 02

CHANGE #7 TYP:0 CLS: 1 AFN:6 DBA:0x01804e8a OBJ:70579 SCN:0x0000.00d60a85 SEQ:  1 OP:10.2
index redo (kdxlin):  insert leaf row
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.2c
REDO: SINGLE / -- / --
itl: 2, sno: 2, row size 14
insert key: (10):  02 c1 04 06 01 80 4d 8a 00 02

CHANGE #8 TYP:0 CLS:31 AFN:2 DBA:0x00800079 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  1 OP:5.4
ktucm redo: slt: 0x0025 sqn: 0x00003632 srt: 0 sta: 9 flg: 0x2
ktucf redo: uba: 0x008031d3.07f1.2c ext: 38 spc: 1718 fbi: 0

CHANGE #9 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a5d SEQ:  1 OP:5.1
ktudb redo: siz: 104 spc: 2250 flg: 0x0012 seq: 0x07f1 rec: 0x27
            xid:  0x0008.025.00003632
ktubl redo: slt: 37 rci: 0 opc: 11.1 objn: 70577 objd: 70577 tsn: 5
Undo type:  Regular undo        Begin trans    Last buffer split:  No
Temp Object:  No
Tablespace Undo:  No
             0x00000000  prev ctl uba: 0x008031d3.07f1.26
prev ctl max cmt scn:  0x0000.00d5fa91  prev tx cmt scn:  0x0000.00d5fb64
txn start scn:  0x0000.00d60a81  logon user: 52  prev brb: 8401354  prev bcl: 0 KDO undo record:
KTB Redo
op: 0x03  ver: 0x01
op: Z
KDO Op code: DRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01804d8a  hdba: 0x01804d89
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 1(0x1)

CHANGE #10 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  1 OP:5.1
ktudb redo: siz: 96 spc: 2144 flg: 0x0022 seq: 0x07f1 rec: 0x28
            xid:  0x0008.025.00003632
ktubu redo: slt: 37 rci: 39 opc: 10.22 objn: 70578 objd: 70578 tsn: 5
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x04  ver: 0x01
op: L  itl: xid:  0x0005.01e.000035e3 uba: 0x008034a5.083a.1d
                      flg: C---    lkc:  0     scn: 0x0000.00d60a81
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=0 indexid=0x1804e09 block=0x01804e0a
(kdxlpu): purge leaf row
key: (10):  02 c1 03 06 01 80 4d 8a 00 01

CHANGE #11 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  2 OP:5.1
ktudb redo: siz: 96 spc: 2046 flg: 0x0022 seq: 0x07f1 rec: 0x29
            xid:  0x0008.025.00003632
ktubu redo: slt: 37 rci: 40 opc: 10.22 objn: 70579 objd: 70579 tsn: 5
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x04  ver: 0x01
op: L  itl: xid:  0x0005.01e.000035e3 uba: 0x008034a5.083a.1e
                      flg: C---    lkc:  0     scn: 0x0000.00d60a81
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=0 indexid=0x1804e89 block=0x01804e8a
(kdxlpu): purge leaf row
key: (10):  02 c1 03 06 01 80 4d 8a 00 01

CHANGE #12 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  3 OP:5.1
ktudb redo: siz: 64 spc: 1948 flg: 0x0022 seq: 0x07f1 rec: 0x2a
            xid:  0x0008.025.00003632
ktubu redo: slt: 37 rci: 41 opc: 11.1 objn: 70577 objd: 70577 tsn: 5
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
KDO undo record:
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.27
KDO Op code: DRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01804d8a  hdba: 0x01804d89
itli: 2  ispac: 0  maxfr: 4863
tabn: 0 slot: 2(0x2)

CHANGE #13 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  4 OP:5.1
ktudb redo: siz: 80 spc: 1882 flg: 0x0022 seq: 0x07f1 rec: 0x2b
            xid:  0x0008.025.00003632
ktubu redo: slt: 37 rci: 42 opc: 10.22 objn: 70578 objd: 70578 tsn: 5
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.28
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=0 indexid=0x1804e09 block=0x01804e0a
(kdxlpu): purge leaf row
key: (10):  02 c1 04 06 01 80 4d 8a 00 02

CHANGE #14 TYP:0 CLS:32 AFN:2 DBA:0x008031d3 OBJ:4294967295 SCN:0x0000.00d60a85 SEQ:  5 OP:5.1
ktudb redo: siz: 80 spc: 1800 flg: 0x0022 seq: 0x07f1 rec: 0x2c
            xid:  0x0008.025.00003632
ktubu redo: slt: 37 rci: 43 opc: 10.22 objn: 70579 objd: 70579 tsn: 5
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
index undo for leaf key operations
KTB Redo
op: 0x02  ver: 0x01
op: C  uba: 0x008031d3.07f1.29
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=0 indexid=0x1804e89 block=0x01804e8a
(kdxlpu): purge leaf row
key: (10):  02 c1 04 06 01 80 4d 8a 00 02

The entire transaction is wrapped up into a single redo record with fourteen redo change vectors. (The 9i dump showed a total of fifteen redo change vectors – we’ve lost the “audit” vector in our 10g setup.) In order, the vectors describe how to…

    insert first row into table
    acquire transaction table slot (start transaction – slightly odd order)
    insert first row into first index
    insert first row into second index
    insert second row into table
    insert second row into first index
    insert second row into second index
    release transaction table slot (commit transaction)
    create undo record showing how to remove first row from table
    create undo record showing how to remove first row from first index
    create undo record showing how to remove first row from second index
    create undo record showing how to remove second row from table
    create unto record showing how to remove second row from first index
    create undo record showing how to remove second row from second index

It is reasonable to infer from this that Oracle is generating a list of “forward” changes (i.e. the private redo) in one buffer and a list of “reverse” changes (i.e. the in-memory undo) in another buffer – and simply concatenates the two lists on the commit.

On the plus side, if we’ve only got one redo record we only have to allocate and copy into the (public) redo buffer once – which reduces contention on a single important hot spot in the Oracle database; on the other hand we have to keep a number of data blocks pinned in memory until the commit, and we have to modify all those data blocks at the same time as we copy the two private buffers into the (public) redo log buffer, and this requirement introduces a different concurrency threat.

Because of this alternative threat there is a fairly tight limit on how much change a single transaction is allowed to make using this new mechanism . For 32-bit Oracle the buffers are about 64Kb each, and for 64-bit Oracle they are about 128KB – and if a session fills either of the two buffers it has acquired then Oracle flushes the contents to the public log buffer and the session then carries on using the public log buffer in the “traditional” way (while still keeping “ownership” of the pair of private buffers that it had allocated.)

A final thought – if you issue a rollback instead of a commit, the “commit record” (change #8 in the above) disappears from the redo record, and the redo stream gets a further six redo records showing how each of the previous undo records have been applied at the user’s request; these records are followed by one last redo record which describes the release of the transaction table slot i.e. a “commit record”.

How Oracle Locking Works

Myth: Oracle has a Central Locking System

A week or so ago I started a new series – 100 Things You Probably didn’t Know about Oracle Database . Part 1 of the series proved quite popular, as I surmise from the emails I received. Here is the Part 2 of the series.

When a transaction updates a row, it puts a lock so that no one can update the same row until it commits. When another transaction issues an update to the same row, it waits until the first one either commits or rolls back. After the first transaction performs a commit or rollback, the update by the second transaction is executed immediately, since the lock placed by the first transaction is now gone. How exactly does this locking mechanism work? Several questions come to mind in this context:

  1. Is there some kind of logical or physical structure called lock?
  2. How does the second transaction know when the first transaction has lifted the lock?
  3. Is there some kind of “pool” of such locks where transactions line up to get one?
  4. If so, do they line up to return it when they are done with the locking?
  5. Is there a maximum number of possible locks?
  6. Is there something called a block level lock? Since Oracle stores the rows in blocks, when all or the majority of rows in the blocks are locked by a single transaction, doesn’t it make sense for to lock the entire block to conserve the number of locks?
  7. The previous question brings up another question – does the number of active locks in the database at any point really matter?

If you are interested to learn about all this, please read on.

Lock Manager

Since locks convey information on who has what rows modified but not committed, anyone interested in making the update much check with some sort of system that is available across the entire database. So, it makes perfect sense to have a central locking system in the database, doesn’t it? But, when you think about it, a central lock manager can quickly become a single point of contention in a busy system where a lot of updates occur. Also, when a large number of rows are updated in a single transaction, an equally large number of locks will be required as well. The question is: how many? One can guess; but it will be at best a wild one. What if you guessed on the low side and the supply of available locks is depleted? In that case some transactions can’t get locks and therefore will have to wait (or, worse, abort). Not a pleasant thought in a system that needs to be scalable. To counter such a travesty you may want to make the available supply of locks really high. What is the downside of that action? Since each lock would potentially consume some memory, and memory is finite, it would not be advisable to create an infinite supply of locks.

Some databases actually have a lock manager with a finite supply of such locks. Each transaction must ask to get a lock from it before beginning and relinquish locks to it at the completion. In those technologies, the scalability of application suffers immensely as a result of the lock manager being the point of contention. In addition, since the supply of locks is limited, the developers need to commit frequently to release the locks for other transactions. When a large number of rows have locks on them, the database replaces the row locks with a block level lock to cover all the rows in the block – a concept known as lock escalation. Oracle does not follow that approach. In Oracle, there no central lock manager, no finite limit on locks and there is no such concept called lock escalation. The developers commit only when there is a logical need to do so; not otherwise.

Lock Management in Oracle

So, how is that approach different in case of Oracle? For starters, there is no central lock manager. But the information on locking has to be recorded somewhere. Where then? Well, consider this: when a row is locked, it must be available to the session, which means the session’s server process must have already accessed and placed the block in the buffer cache prior to the transaction occurring. Therefore, what is a better place for putting this information than right there in the block (actually the buffer in the buffer cache) itself?

Oracle does precisely that – it records the information in the block. When a row is locked by a transaction, that nugget of information is placed in the header of the block where the row is located. When another transaction wishes to acquire the lock on the same row, it has to access the block containing the row anyway (as you learned in Part 1 of this series) and upon reaching the block, it can easily confirm that the row is locked from the block header. A transaction looking to update a row in a different block puts that information on the header of that block. There is no need to queue behind some single central resource like a lock manager. Since lock information is spread over multiple blocks instead of a single place, this mechanism makes transactions immensely scalable.

Being the smart reader you are, you are now hopefully excited to learn more or perhaps you are skeptical. You want to know the nuts and bolts of this whole mechanism and, more, you want proof. We will see all that in a moment.

Transaction Address

Before understanding the locks, you should understand clearly what a transaction is and how it is addressed. A transaction starts when an update to data such as insert, update or delete occurs (or the intention to do so, e.g. SELECT FOR UPDATE) and ends when the session issues a commit or rollback. Like everything else, a specific transaction should have a name or an identifier to differentiate it from another one of the same type. Each transaction is given a transaction ID. When a transaction updates a row (it could also insert a new row or delete an existing one; but we will cover that little later in this article), it records two things:

  • The new value
  • The old value

The old value is recorded in the undo segments while the new value is immediately updated in the buffer where the row is stored. The data buffer containing the row is updated regardless of whether the transaction is committed or not. Yes, let me repeat – the data buffer is updated as soon as the transaction modifies the row (before commit). If you didn’t know that, please see the Part 1 of this series.

Undo information is recorded in a circular fashion. When new undo is created, it is stored in the next available undo “slot”. Each transaction occupies a record in the slot. After all the slots are exhausted and a new transaction arrives, the next processing depends on the state of the transactions. If the oldest transaction occupying any of the other slots is no longer active (that is either committed or rolled back), Oracle will reuse that slot. If none of the transactions is inactive, Oracle will have to expand the undo tablespace to make room. In the former case (where a transaction is no longer active and its information in undo has been erased by a new transaction), if a long running query that started before the transaction occurred selects the value, it will get an ORA-1555 error. But that will be covered in a different article in the future. If the tablespace containing the undo segment can’t extend due to some reason (such as in case of the filesystem being completely full), the transaction will fail.

Speaking of transaction identifiers, it is in the form of three numbers separated by periods. These three numbers are:

  • Undo Segment Number where the transaction records its undo entry
  • Slot# in the undo segment
  • Sequence# (or wrap) in the undo slot

This is sort of like the social security number of the transaction. This information is recorded in the block header. Let’s see the proof now through a demo.

Demo

First, create a table:

SQL> create table itltest (col1 number, col2 char(8));

Insert some rows into the table.

SQL> begin
2 for i in 1..10000 loop
3 insert into itltest values (i,'x');
4 end loop;
5 commit;
6 end;
7 /

Remember, this is a single transaction. It started at the “BEGIN” line and ended at “COMMIT”. The 10,000 rows were all inserted as a part of the same transaction. To know the transaction ID of this transaction, Oracle provides a special package - dbms_transaction. Here is how you use it. Remember, you must use it in the same transaction. Let’s see:

SQL> select dbms_transaction.local_transaction_id from dual;

LOCAL_TRANSACTION_ID
------------------------------------------------------------------------


1 row selected.

Wait? There is nothing. The transaction ID returned is null. How come?

If you followed the previous section closely, you will realize that the transaction ends when a commit or rollback is issued. The commit was issued inside the PL/SQL block. So, the transaction had ended before you called the dbms_transaction is package. Since there was no transaction, the package returned null.

Let’s see another demo. Update one row:

SQL> update itltest set col2 = 'y' where col1 = 1;

1 row updated.

In the same session, check the transaction ID:

SQL> select dbms_transaction.local_transaction_id from dual;

LOCAL_TRANSACTION_ID
-------------------------------------------------------------------------
3.23.40484

1 row selected.

There you see – the transaction ID. The three numbers separated by period signify undo segment number, slot# and record# respectively. Now perform a commit:

SQL> commit;

Commit complete.

Check the transaction ID again:

SQL> select dbms_transaction.local_transaction_id from dual;

LOCAL_TRANSACTION_ID
-------------------------------------------------------------------------


1 row selected.

The transaction is gone so the ID is null, as expected.

Since the call to the package must be in the same transaction (and therefore in the same session), how can you check the transaction in a different session? In real life you will be asked to check transaction in other sessions, typically application sessions. Let’s do a slightly different test. Update the row one more time and check the transaction:

SQL> update itltest set col2 = 'y' where col1 = 1;

1 row updated.

SQL> select dbms_transaction.local_transaction_id from dual;

LOCAL_TRANSACTION_ID
-----------------------------------------------------------------------
10.25.31749

1 row selected.

From a different session, check for active transactions. This information is available in the view V$TRANSACTION. There are several columns; but we will look at four of the most important ones:

  • ADDR – the address of the transaction, which is a raw value
  • XIDUSN – the undo segment number
  • XIDSLOT – the slot#
  • XIDSQN – the sequence# or record# inside the slot
SQL> select addr, xidusn, xidslot, xidsqn
2 from v$transaction;

ADDR XIDUSN XIDSLOT XIDSQN
-------- ---------- ---------- ----------
3F063C48 10 25 31749

Voila! You see the transaction id of the active transaction from a different session. Compare the above output to the one you got from the call to dbms_transaction package. You can see that the transaction identifier shows the same set of numbers.

Interested Transaction List

You must be eager to know about the section of the block header that contains information on locking and how it records it. It is a simple data structure called "Interested Transaction List" (ITL), a list that maintains information on transaction. The ITL contains several placeholders (or slots) for transactions. When a row in the block is locked for the first time, the transaction places a lock in one of the slots. In other words, the transaction makes it known that it is interested in some rows (hence the term "Interested Transaction List"). When a different transaction locks another set of rows in the same block, that information is stored in another slot and so on. When a transaction ends after a commit or a rollback, the locks are released and the slot which was used to mark the row locks in the block is now considered free (although it is not updated immediately - fact about which you will learn later in a different installment).

#45818e;">[Updated Jan 22, 2011] [Thank you, Randolph Geist (#45818e;">info@www.sqltools-plusplus.org#45818e;">) for pointing it out. I follow his blog #45818e;">http://oracle-randolf.blogspot.com/#45818e;">, which is a treasure trove of information.
The row also stores a bit that represents the whether it is locked or not.
#45818e;">[end of Update Jan 22, 2011]
#45818e;">

ITLs in Action

Let's see how ITLs really work. Here is an empty block. The block header is the only occupant of the block.

This is how the block looks like after a single row has been inserted:

Note, the row was inserted from the bottom of the block. Now, a second row has been inserted:

A session comes in and updates the row Record1, i.e. it places a lock on the row, shown by the star symbol. The lock information is recorded in the ITL slot in the block header:

The session does not commit yet; so the lock is active. Now a second session - Session 2 - comes in and updates row Record2. It puts a lock on the record - as stored in the ITL slot.

I have used two different colors to show the locks (as shown by the star symbol) and the color of the ITL entry.

As you can clearly see, when a transaction wants to update a specific row, it doesn’t have to go anywhere but the block header itself to know if the row is locked or not. All it has to do is to check the ITL slots. However ITL alone does not show with 100% accuracy that row is locked (again, something I will explain in a different installment). The transaction must go to the undo segment to check if the transaction has been committed. How does it know which specifci part of the undo segment to go to? Well, it has the information in the ITL entry. If the row is indeed locked, the transaction must wait and retry. As soon as the previous transaction ends, the undo information is updated and the waiting transaction completes its operation.

So, there is in fact a queue for the locks, but it's at the block level, not at the level of the entire database or even the segment.

Demo

The proof is in the pudding. Let’s see all this through a demo. Now that you know the transaction entry, let’s see how it is stored in the block header. To do that, first, we need to know which blocks to look for. So, we should get the blocks numbers where the table is stored:

SQL> select file_id, relative_fno, extent_id, block_id, blocks
2 from dba_extents
3 where segment_name = 'ITLTEST';

FILE_ID RELATIVE_FNO EXTENT_ID BLOCK_ID BLOCKS
---------- ------------ ---------- ---------- ----------
7 7 0 3576 8
7 7 1 3968 8
7 7 2 3976 8
7 7 3 3984 8

To check inside the block, we need to “dump” the contents of the block to a tracefile so that we can read it. From a different session issue a checkpoint so that the buffer data is now written to the dis:

SQL> alter system checkpoint;

Now dump the data blocks 3576 through 3583.

SQL> alter system dump datafile 7 block min 3576 block max 3583;

System altered.

This will create a tracefile in the user dump destination directory. In case of Oracle 11g, the tracefile will be in the diag structure under /diag/rdbms///trace directory. It will be most likely the last tracefile generated. You can also get the precise name by getting the OS process ID of the session:

SQL> select p.spid
2 from v$session s, v$process p
3 where s.sid = (select sid from v$mystat where rownum < 2)
4 and p.addr = s.paddr
5 /

SPID
------------------------
9202

1 row selected.

Now look for a file named _ora_9202.trc. Open the file in vi and search for the phrase “Itl”. Here is an excerpt from the file:


Itl           Xid                  Uba          Flag  Lck        Scn/Fsc
0x01 0x000a.019.00007c05 0x00c00288.1607.0e ---- 1 fsc 0x0000.00000000
0x02 0x0003.017.00009e24 0x00c00862.190a.0f C--- 0 scn 0x0000.02234e2b

This is where the information on row locking is stored. Remember, the row locking information is known as Interested Transaction List (ITL) and each ITL is stored in a “slot”. Here it shows two slots, which is the default number. Look for the one where the “Lck” column shows a value. It shows “1”, meaning one of the rows in the blocks is locked by a transaction. But, which transaction? To get that answer, note the value under the “Xid” column. It shows the transaction ID - 0x000a.019.00007c05. These numbers are in hexadecimal (as indicated by the 0x at the beginning of the number). Using the scientific calculator in Windows, I converted the values to decimal as 10, 25 and 31749 respectively. Do they sound familiar? Of course they do; they are exactly as reported by both the record in v$transaction and the dbms_transaction.local_transaction_id function call.


This is how Oracle determines that there is a transaction has locked the row and correlates it to the various components in the other areas – mostly the undo segments to determne if it is active. Now that you know undo segments holds the transaction details, you may want to know more about the segment. Remember, the undo segment is just a segment, like any other table, indexes, etc. It resides in a tablespace, which is on some datafile. To find out the specifics of the segment, we will look into some more columns of the view V$TRANSACTION:

SQL> select addr, xidusn, xidslot, xidsqn, ubafil, ubablk, ubasqn, ubarec,
2 status, start_time, start_scnb, start_scnw, ses_addr
3 from v$transaction;

ADDR XIDUSN XIDSLOT XIDSQN UBAFIL UBABLK UBASQN
-------- ---------- ---------- ---------- ---------- ---------- ----------
UBAREC STATUS START_TIME START_SCNB START_SCNW SES_ADDR
---------- ---------------- -------------------- ---------- ---------- --------
3F063C48 10 25 31749 3 648 5639
14 ACTIVE 12/30/10 20:00:25 35868240 0 40A73784


1 row selected.

The columns with names starting with UBA show the undo block address information. Look at the above output. The UBAFIL shows the file#, which is “3” in this case. Checking for the file_id: 

SQL> select * from dba_data_files
2> where file_id = 3;

FILE_NAME
-------------------------------------------------------------------------
FILE_ID TABLESPACE_NAME BYTES BLOCKS STATUS
---------- ------------------------------ ---------- ---------- ---------
RELATIVE_FNO AUT MAXBYTES MAXBLOCKS INCREMENT_BY USER_BYTES USER_BLOCKS
------------ --- ---------- ---------- ------------ ---------- -----------
ONLINE_
-------
+DATA/d112d2/datafile/undotbs1.260.722742813
3 UNDOTBS1 4037017600 492800 AVAILABLE
3 YES 3.4360E+10 4194302 640 4035969024 492672
ONLINE


1 row selected.

Note the UBASQN (which is the undo block sequence#) value in the earlier output, which was 5639. Let’s revisit the ITL entries in the dump of block:

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01 0x000a.019.00007c05 0x00c00288.1607.0e ---- 1 fsc 0x0000.00000000
0x02 0x0003.017.00009e24 0x00c00862.190a.0f C--- 0 scn 0x0000.02234e2b

Look at the entry under the Uba column: 0x00c00288.1607.0e. As indicated by the “0x” at the beginning, these are in hexadecimal. Using a scientific calculator, let’s convert them. 1607 in hex means 5639 in decimal – the UBA Sequence# (UBASQN). The value “e” is 14 in decimal, which corresponds to the UBAREC. Finally the value 288 is 648 in decimal, which is the UBABLK. Now you see how the information is recorded in the block header and is also available to the DBA through the view V$TRANSACTION. 


Let’s see some more important columns of the view. A typical database will have many sessions; not just one. Each session may have an active transaction, which means you have to link sessions to transactions to generate meaningful information. The transaction information also contains the session link. Note the column SES_ADDR, which is the address of the session that issued the transaction. From that, you can get the session information


SQL> select sid, username
2 from v$session
3 where saddr = '40A73784';

SID USERNAME
--- --------
123 ARUP

There you go – you now have the SID of the session. And now that you know the SID, you can look up any other relevant data on the session from the view V$SESSION.

Takeaways

Here is a summary of what you learned so far:

  1. Transaction in Oracle starts with a data update (or intention to update) statement. Actually there are some exceptions which we will cover in a later article.
  2. It ends when a commit or rollback is issued
  3. A transaction is identified by a transaction ID (XID) which is a set of three numbers – undo segment#, undo slot# and undo record# - separated by periods.
  4. You can view the transaction ID in the session itself by calling dbms_transaction.local_transaction_id function.
  5. You can also check all the active transactions in the view v$transaction, where the columns XIDUSN, XIDSLOT and XIDSQN denote the undo segment#, undo slot# and undo rec# - the values that make up the transaction ID.
  6. The transaction information is also stored in the block header. You can check it by dumping the block and looking for the term “Itl”.
  7. The v$transaction view also contains the session address under SES_ADDR column, which can be used to join with the SADDR column of v$session view to get the session details.
  8. From the session details, you can find out other actions by the session such as the username, the SQL issues, the machine issued from, etc.

I hope you found it useful. As always, I will be grateful to know how you liked it. In the next installment we will examine how these ITLs could cause issues and how to identify or resolve them.

NO_QUERY_TRANSFORMATION Hint is Ignored… Well, Almost Ignored

January 3, 2011 A couple of days ago I used a NO_QUERY_TRANSFORMATION hint to permit a query (provided by Martin Berger) to execute, which on the surface appeared to be quite sane, but without hints the query would usually fail to execute.  A test case version of the query worked on 11.2.0.1 running on 64 bit Windows on [...]

Adaptive Cursor Sharing

This post was motivated by a recent discussion I had where I mentioned that Adaptive Cursor Sharing (ACS) does not work with embedded SQL in PL/SQL, but when looking for an existing post realized that I didn't find any good and freely available examples of that limitation of ACS.

Therefore I decided to put together this post that outlines what ACS is supposed to do, its inherent limitations and finally shed some light on the specific limitation that started its life with the description that "it does not work with embedded SQL in PL/SQL".

Adaptive Cursor Sharing (ACS) has been introduced in Oracle 11g to address the potential threat of cursor sharing and bind variables - yes, you have read correctly: The usage of bind variables can be a possible threat if different values of bind variables are executed using the same execution plan, but actually would require different execution plans to prevent poor performing executions.

So ACS allows Oracle to detect such problems and selectively "unshare" cursors, which means that Oracle creates one or more additional child cursors for different (ranges) of bind values.

However, there are a couple of limitations to this strategy. Let's have a look at a working example of ACS. Therefore I run the following script against database versions 11.1.0.7 and 11.2.0.2:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_1.sql
--
-- Purpose: Demonstrate a simple case of adaptive cursor sharing
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading off newpage none tab off serveroutput off

alter session set statistics_level = all;

alter system flush buffer_cache;

alter system flush shared_pool;

var x number

exec :x := 100000

-- pause

set timing on

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

column prev_sql_id new_value sql_id noprint
column sid new_value session_id noprint

select
prev_sql_id
, sid
from
v$session
where
sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

exec :x := 1

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

set heading on

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = '&sql_id';

and I get the following result from 11.2.0.2 (and 11.1.0.7):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75795

SQL>
SQL> set echo on linesize 200 heading off newpage none tab off serveroutput off
SQL>
SQL> alter session set statistics_level = all;

Session altered.

SQL>
SQL> alter system flush buffer_cache;

System altered.

SQL>
SQL> alter system flush shared_pool;

System altered.

SQL>
SQL> var x number
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

SQL>
SQL> -- pause
SQL>
SQL> set timing on
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.09
SQL>
SQL> column prev_sql_id new_value sql_id noprint
SQL> column sid new_value session_id noprint
SQL>
SQL> select
2 prev_sql_id
3 , sid
4 from
5 v$session
6 where
7 sid = sys_context('userenv', 'sid');

Elapsed: 00:00:00.15
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

-------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | 3 | | | |
| 2 | VIEW | | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 13 | 0 |00:00:00.01 | 3 | 3 | | | |
-------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:01.74
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.7361E+11

Elapsed: 00:00:17.12
SQL>
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:17.12 | 1460K| 35371 | 10532 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:17.12 | 1460K| 35371 | 10532 | | | | |
| 2 | VIEW | | 1 | 13 | 1457K|00:00:16.94 | 1460K| 35371 | 10532 | | | | |
| 3 | WINDOW SORT | | 1 | 13 | 1457K|00:00:16.66 | 1460K| 35371 | 10532 | 93M| 3313K| 37M (1)| 84992 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 13 | 1457K|00:00:12.01 | 1460K| 24839 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 13 | 1457K|00:00:01.53 | 3221 | 3220 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.17
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.7361E+11

Elapsed: 00:00:05.10
SQL>
SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));
SQL_ID fmbq5ytmh0hng, child number 1
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 2719131525

----------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
----------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:05.10 | 21539 | 29966 | 8375 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:05.10 | 21539 | 29966 | 8375 | | | | |
| 2 | VIEW | | 1 | 1457K| 1457K|00:00:04.98 | 21539 | 29966 | 8375 | | | | |
| 3 | WINDOW SORT | | 1 | 1457K| 1457K|00:00:04.80 | 21539 | 29966 | 8375 | 74M| 2971K| 37M (1)| 67584 |
|* 4 | TABLE ACCESS FULL| T | 1 | 1457K| 1457K|00:00:01.38 | 21532 | 21528 | 0 | | | | |
----------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:X)

24 rows selected.

Elapsed: 00:00:00.05
SQL>
SQL> set heading on
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = '&sql_id';
old 12: sql_id = '&sql_id'
new 12: sql_id = 'fmbq5ytmh0hng'
SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
fmbq5ytmh0hng 0 2 3 1460762 Y N
fmbq5ytmh0hng 1 1 0 21539 Y Y

Elapsed: 00:00:00.00
SQL>

So I intentionally use bind variables in a dangerous way here: The "object_id > :x" predicate is a potential threat - depending on the value of :x the usage of the index on OBJECT_ID can be a very good or a very bad idea.

From this example we therefore can tell a couple of things you should know about ACS:

1. ACS is not limited to the typical "skewed column data" / "histogram" case. We can see that I explicitly did not create any histograms (method_opt "for all columns size 1"), still ACS marked the cursor as "BIND_SENSITIVE" and eventually created a second child cursor with a more appropriate execution plan for the bind value, because it detected the "expression > :x" predicate.

2. However, and this one of the most important aspects, for ACS to detect the problem, it first has to go wrong at least once. As you can see from the example it was only the second execution using the "bad" bind value that created the child cursor. So depending on how "wrong" things can go - think of a more complex execution plan including multiple joins - it might already be "too late" for your application: If for example a query is not going to return in a reasonable amount of time your application might effectively be "broken" even if ACS might be able to "fix" the problem at the next execution...

3. Another important point to consider is that the ACS information is not stored persistently but only exists in the Shared Pool. This means, if the information is aged out of the Shared Pool for whatever reason, the same mistake has to be made again for ACS to detect the problem. So if your problematic cursors age out of the Shared Pool it will potentially go "wrong" again with the next execution before ACS can come for help.

From this you can see that - although ACS is a great feature - it is not a "Silver Bullet" for all possible cases. You still might need to help your database for those special cases where ACS is not able to support your application properly. How you can help your database? More on that later.

Now let's have a look at the point that ACS "does not work with embedded SQL in PL/SQL". Therefore I put together the following script that in principle does the same as the first script, but this time uses the most commonly used techniques in PL/SQL to execute SQL:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_2.sql
--
-- Purpose: Demonstrate adaptive cursor sharing is not working with PL/SQL when
-- optimizations are enabled, in particular holding cursors open
-- See bug 8357294
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading on tab off serveroutput off

set timing on

-- This is a workaround that disables also the cursor optimizations in PL/SQL
-- In particular the PL/SQL hold cursor open optimization
-- Therefore the cursor gets reparsed and ACS kicks in
alter session set session_cached_cursors = 0;
--
-- Does this make any difference? No
-- alter session set plsql_optimize_level = 0;

variable sql_id varchar2(255)

-- Static SQL
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
select
sum(row_num)
into
n_dummy
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > x
);
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

-- dynamic SQL with binds
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
execute immediate '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
)' into n_dummy using x;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

-- dynamic SQL with literals
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
execute immediate '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > ' || x || '
)' into n_dummy;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
b.sql_id
, b.child_number
, b.executions
, b.parse_calls
, b.buffer_gets
, b.is_bind_sensitive
, b.is_bind_aware
from
v$sql a, v$sql b
where
a.force_matching_signature = b.force_matching_signature
and a.sql_id = :sql_id;

set pagesize 0

select
c.*
from
v$sql a
, v$sql b
, table(dbms_xplan.display_cursor(b.sql_id)) c
where
a.force_matching_signature = b.force_matching_signature
and a.sql_id = :sql_id;

set pagesize 9999

-- dynamic SQL with binds + OPEN
alter system flush buffer_cache;

alter system flush shared_pool;

declare
x integer;
n_dummy number;
c sys_refcursor;
begin
for i in 1..10 loop
if i = 1 then
x := 100000;
else
x := 1;
end if;
open c for '
select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
)' using x;
fetch c into n_dummy;
close c;
if i = 1 then
select
prev_sql_id
into
:sql_id
from
v$session
where
sid = sys_context('userenv', 'sid');
end if;
end loop;
end;
/

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = :sql_id;

set pagesize 0

select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));

set pagesize 9999

So this script executes the same query as used in the first script ten times in a row, again deliberately using the same bind values in the same order: The first execution can benefit from the index, all following executions would better use a full table scan.

These are the different techniques used:

1. Static embedded SQL which are sometimes in PL/SQL are also called "implicit cursors". They should exhibit the same characteristics as explicitly declared cursors, which I haven't included in this script.

2. Dynamic SQL using EXECUTE IMMEDIATE and binds, so the cursor can still be shared

3. Dynamic SQL using EXECUTE IMMEDIATE and literals, which leads to different SQLs and therefore different parent cursors with potentially different executions plans since both will be parsed / optimized independently from each other

4. Dynamic SQL using OPEN / FETCH / CLOSE and binds, so the cursor again can be shared

And this is the result that I get from 11.2.0.2 (11.1.0.7 showed the same):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75819

SQL>
SQL> set echo on linesize 200 heading on tab off serveroutput off
SQL>
SQL> set timing on
SQL>
SQL> -- This is a workaround that disables also the cursor optimizations in PL/SQL
SQL> -- In particular the PL/SQL hold cursor open optimization
SQL> -- Therefore the cursor gets reparsed and ACS kicks in
SQL> -- alter session set session_cached_cursors = 0;
SQL> --
SQL> -- Does this make any difference? No
SQL> -- alter session set plsql_optimize_level = 0;

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> variable sql_id varchar2(255)
SQL>
SQL> -- Static SQL
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.03
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.63
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 select
12 sum(row_num)
13 into
14 n_dummy
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > x
24 );
25 if i = 1 then
26 select
27 prev_sql_id
28 into
29 :sql_id
30 from
31 v$session
32 where
33 sid = sys_context('userenv', 'sid');
34 end if;
35 end loop;
36 end;
37 /

PL/SQL procedure successfully completed.

Elapsed: 00:02:50.68
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
g89tq3q521rbg 0 10 1 13146414 Y N

Elapsed: 00:00:00.17
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID g89tq3q521rbg, child number 0
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:B1)

29 rows selected.

Elapsed: 00:00:01.86
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.09
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.84
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > :x
23 )' into n_dummy using x;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:03:17.26
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 10 1 13146434 Y N

Elapsed: 00:00:00.14
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

31 rows selected.

Elapsed: 00:00:01.35
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with literals
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.05
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.66
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > ' || x || '
23 )' into n_dummy;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:52.29
SQL>
SQL> select
2 b.sql_id
3 , b.child_number
4 , b.executions
5 , b.parse_calls
6 , b.buffer_gets
7 , b.is_bind_sensitive
8 , b.is_bind_aware
9 from
10 v$sql a, v$sql b
11 where
12 a.force_matching_signature = b.force_matching_signature
13 and a.sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
2tgumwrfx40bu 0 1 1 53 N N
03zrk5tr7zsn4 0 9 1 193851 N N

Elapsed: 00:00:00.10
SQL>
SQL> set pagesize 0
SQL>
SQL> select
2 c.*
3 from
4 v$sql a
5 , v$sql b
6 , table(dbms_xplan.display_cursor(b.sql_id)) c
7 where
8 a.force_matching_signature = b.force_matching_signature
9 and a.sql_id = :sql_id;
SQL_ID 2tgumwrfx40bu, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 100000 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | |
| 2 | VIEW | | 13 | 195 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">100000)

SQL_ID 03zrk5tr7zsn4, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | | |
| 2 | VIEW | | 1457K| 20M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">1)

51 rows selected.

Elapsed: 00:00:01.24
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds + OPEN
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.04
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.66
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 c sys_refcursor;
5 begin
6 for i in 1..10 loop
7 if i = 1 then
8 x := 100000;
9 else
10 x := 1;
11 end if;
12 open c for '
13 select
14 sum(row_num)
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > :x
24 )' using x;
25 fetch c into n_dummy;
26 close c;
27 if i = 1 then
28 select
29 prev_sql_id
30 into
31 :sql_id
32 from
33 v$session
34 where
35 sid = sys_context('userenv', 'sid');
36 end if;
37 end loop;
38 end;
39 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:12.12
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.36
SQL>
SQL> set pagesize 9999
SQL>

So this script shows some interesting results:

1. It can be seen that ACS does not seem to work with several of the used variations: Both the static and the dynamic SQL using EXECUTE IMMEDIATE and binds do not create a second child cursor and re-use the same execution plan for all ten executions. Although the cursor has been marked as BIND_SENSITIVE, it has not been marked as BIND_AWARE.

Both execution variants also share the fact that there seems to be a PL/SQL optimization in place that allows to keep the cursors open - there is only a single PARSE call recorded in V$SQL for this SQL statement, although we loop through the same code ten times and therefore should in principle see as many parse as execution calls.

You would even see the same optimization in place when explicit cursors were used with explicit OPEN / FETCH / CLOSE calls: Albeit the explicit CLOSE you would still see only a single PARSE call for the statement - PL/SQL holds the cursor open for maximum performance and scalibility.

2. Another interesting side note is that the new feature "Cardinality Feedback" that has been introduced with Oracle 11.2 seems also to be not working in these examples, but this is definitely something for another post.

"Cardinality Feedback" allows Oracle to compare the cardinality estimates of the cost-based optimizer with the actual cardinalities at execution time and perform "instant tuning" by automatically adding OPT_ESTIMATE and other hints to the statement to correct the cardinality estimates and do a re-optimization of the "tuned" statement. Again this information only resides in the Shared Pool and will be potentially aged out like the ACS information.

3. The clear winner in terms of both elapsed and performed logical I/O is the third variant that creates two different cursors using literals. For both cursors the optimal execution plan has been found and nothing had to go "wrong" first to be fixed afterwards, therefore the total elapsed time and number of buffer gets is significantly lower than in the other cases. This gives us already a hint regarding the point "How can we help the database in such cases?"

Note also that although the number of buffer gets is significantly lower compared to the other cases, the elapsed time is not that much different, which is another example that buffer gets are not necessarily a good indicator for the overall work performed. In this particular case a lot of time is spent on writing and reading from the temporary tablespace for the WINDOW SORT operation, and since this operation has more or less to do the same work in all cases where the whole table needs to read in whatever efficient or inefficient way, the overall runtime does not differ as dramatically as the number of buffer gets. You could see this additional work in this example by checking the columns DISK_READS and DIRECT_WRITES from V$SQL and of course by checking the ASH / extended SQL trace profile.

4. The fourth variant using the dynamic SQL with OPEN obviously does not benefit from the PL/SQL optimization: V$SQL clearly shows that there have been as many PARSE calls as EXECUTE calls. Interestingly in this case ACS worked and created a second child cursor. This gives us already a hint what seems to prevent ACS from working.

The shown behaviour of ACS not working is officially documented in My Oracle Support, however not available in the Knowledge Base but only as bug number 8357294: ADAPTIVE CURSOR SHARING DOESN'T WORK FOR SQL FROM PL/SQL. It is interesting to note that the very detailed bug description does not mention a fix release or patch, but does mention that setting "session_cached_cursors" to 0 allows ACS again to work.

And indeed, when running the same script again with "session_cached_cursors" set to 0, I get this result:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1457480 2 75821

SQL>
SQL> set echo on linesize 200 heading on tab off serveroutput off
SQL>
SQL> set timing on
SQL>
SQL> -- This is a workaround that disables also the cursor optimizations in PL/SQL
SQL> -- In particular the PL/SQL hold cursor open optimization
SQL> -- Therefore the cursor gets reparsed and ACS kicks in
SQL> alter session set session_cached_cursors = 0;

Session altered.

Elapsed: 00:00:00.00
SQL> --
SQL> -- Does this make any difference? No
SQL> -- alter session set plsql_optimize_level = 0;
SQL>
SQL> variable sql_id varchar2(255)
SQL>
SQL> -- Static SQL
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.05
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.71
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 select
12 sum(row_num)
13 into
14 n_dummy
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > x
24 );
25 if i = 1 then
26 select
27 prev_sql_id
28 into
29 :sql_id
30 from
31 v$session
32 where
33 sid = sys_context('userenv', 'sid');
34 end if;
35 end loop;
36 end;
37 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:00.82
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
g89tq3q521rbg 0 2 3 1460742 Y N
g89tq3q521rbg 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID g89tq3q521rbg, child number 0
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:B1)

SQL_ID g89tq3q521rbg, child number 1
-------------------------------------
SELECT SUM(ROW_NUM) FROM ( SELECT ROW_NUMBER() OVER (PARTITION BY
OBJECT_TYPE ORDER BY OBJECT_NAME) AS ROW_NUM , T.* FROM T WHERE
OBJECT_ID > :B1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :B1 (NUMBER): 1

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:B1)

57 rows selected.

Elapsed: 00:00:01.50
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.07
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.70
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > :x
23 )' into n_dummy using x;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:12.41
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.13
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.10
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with literals
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.03
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.69
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 begin
5 for i in 1..10 loop
6 if i = 1 then
7 x := 100000;
8 else
9 x := 1;
10 end if;
11 execute immediate '
12 select
13 sum(row_num)
14 from
15 (
16 select
17 row_number() over (partition by object_type order by object_name) as row_num
18 , t.*
19 from
20 t
21 where
22 object_id > ' || x || '
23 )' into n_dummy;
24 if i = 1 then
25 select
26 prev_sql_id
27 into
28 :sql_id
29 from
30 v$session
31 where
32 sid = sys_context('userenv', 'sid');
33 end if;
34 end loop;
35 end;
36 /

PL/SQL procedure successfully completed.

Elapsed: 00:00:55.97
SQL>
SQL> select
2 b.sql_id
3 , b.child_number
4 , b.executions
5 , b.parse_calls
6 , b.buffer_gets
7 , b.is_bind_sensitive
8 , b.is_bind_aware
9 from
10 v$sql a, v$sql b
11 where
12 a.force_matching_signature = b.force_matching_signature
13 and a.sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
2tgumwrfx40bu 0 1 1 53 N N
03zrk5tr7zsn4 0 9 9 193851 N N

Elapsed: 00:00:00.11
SQL>
SQL> set pagesize 0
SQL>
SQL> select
2 c.*
3 from
4 v$sql a
5 , v$sql b
6 , table(dbms_xplan.display_cursor(b.sql_id)) c
7 where
8 a.force_matching_signature = b.force_matching_signature
9 and a.sql_id = :sql_id;
SQL_ID 2tgumwrfx40bu, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 100000 )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | |
| 2 | VIEW | | 13 | 195 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">100000)

SQL_ID 03zrk5tr7zsn4, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > 1 )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 15 | | | |
| 2 | VIEW | | 1457K| 20M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">1)

51 rows selected.

Elapsed: 00:00:01.17
SQL>
SQL> set pagesize 9999
SQL>
SQL> -- dynamic SQL with binds + OPEN
SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.04
SQL>
SQL> alter system flush shared_pool;

System altered.

Elapsed: 00:00:00.73
SQL>
SQL> declare
2 x integer;
3 n_dummy number;
4 c sys_refcursor;
5 begin
6 for i in 1..10 loop
7 if i = 1 then
8 x := 100000;
9 else
10 x := 1;
11 end if;
12 open c for '
13 select
14 sum(row_num)
15 from
16 (
17 select
18 row_number() over (partition by object_type order by object_name) as row_num
19 , t.*
20 from
21 t
22 where
23 object_id > :x
24 )' using x;
25 fetch c into n_dummy;
26 close c;
27 if i = 1 then
28 select
29 prev_sql_id
30 into
31 :sql_id
32 from
33 v$session
34 where
35 sid = sys_context('userenv', 'sid');
36 end if;
37 end loop;
38 end;
39 /

PL/SQL procedure successfully completed.

Elapsed: 00:01:05.62
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = :sql_id;

SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
3snga4x0swy99 0 2 3 1460762 Y N
3snga4x0swy99 1 8 7 172312 Y Y

Elapsed: 00:00:00.16
SQL>
SQL> set pagesize 0
SQL>
SQL> select * from table(dbms_xplan.display_cursor(:sql_id,null,'+PEEKED_BINDS'));
SQL_ID 3snga4x0swy99, child number 0
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 1399240396

---------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 18 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | |
| 2 | VIEW | | 13 | 169 | 18 (6)| 00:00:01 |
| 3 | WINDOW SORT | | 13 | 507 | 18 (6)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 13 | 507 | 17 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I | 13 | | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 100000

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

SQL_ID 3snga4x0swy99, child number 1
-------------------------------------
select sum(row_num) from (
select row_number() over (partition by object_type
order by object_name) as row_num , t.*
from t where
object_id > :x )

Plan hash value: 2719131525

-------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
-------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | 20588 (100)| |
| 1 | SORT AGGREGATE | | 1 | 13 | | | |
| 2 | VIEW | | 1457K| 18M| | 20588 (1)| 00:04:08 |
| 3 | WINDOW SORT | | 1457K| 54M| 72M| 20588 (1)| 00:04:08 |
|* 4 | TABLE ACCESS FULL| T | 1457K| 54M| | 5894 (2)| 00:01:11 |
-------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :X (NUMBER): 1

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:X)

61 rows selected.

Elapsed: 00:00:01.57
SQL>
SQL> set pagesize 9999
SQL>

Now in all cases where the cursor is potentially shared we can see that ACS eventually kicks in and creates a second child cursor. Notice however that this comes at a price: All cases show now that there are as many PARSE calls as executions.

So this seems to mean that disabling the session cursor cache actually disabled also the PL/SQL optimization that prevents the repeated PARSE calls by keeping the cursors open.

Remember that the session cursor cache is merely a means to make a soft PARSE call even _softer_ by avoiding the otherwise required access to the Shared Pool library cache resources because the cursor information has been cached in a private memory area of the process, but the session cursor cache does not avoid the PARSE call itself - this can only be done on application resp. client side, not on database side.

In order to understand if the session cursor cache or the "keep cursors open" optimization affects ACS we can run the following simple script:

--------------------------------------------------------------------------------
--
-- File name: adaptive_cursor_sharing_3.sql
--
-- Purpose: Check if the session cursor cache affects adaptive cursor sharing
--
-- Author: Randolf Geist
--
-- Last tested: December 2010
--
-- Versions: 11.1.0.7
-- 11.2.0.2
--------------------------------------------------------------------------------

set echo on define on tab off

drop table t;
purge table t;
create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);
create index i on t(object_id);

exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

set echo on

select count(*), min(object_id)
, max(object_id) from t;

set echo on linesize 200 heading off newpage none tab off serveroutput off

alter session set statistics_level = all;

-- alter session set session_cached_cursors = 0;

alter system flush buffer_cache;

alter system flush shared_pool;

var x number

exec :x := 100000

-- pause

set timing on

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

column prev_sql_id new_value sql_id noprint
column sid new_value session_id noprint

select
prev_sql_id
, sid
from
v$session
where
sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

column value new_value value_1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 100000

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

exec :x := 1

select
name
, value
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select
sum(row_num)
from
(
select
row_number() over (partition by object_type order by object_name) as row_num
, t.*
from
t
where
object_id > :x
);

select
name
, value - &value_1 as diff
from
v$statname a
, v$sesstat b
where
a.statistic# = b.statistic#
and a.name = 'session cursor cache hits'
and b.sid = sys_context('userenv', 'sid');

select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));

set heading on

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = '&sql_id';

This script simply runs the same SQL that we already know sufficiently often to ensure that it gets cached in the session cursor cache by executing it at least three times. Then in one of the next executions the "bad" bind values is used to see if the caching in the session cursor cache somehow prevents ACS from kicking in. Here is the result, this time from 11.1.0.7 (but again I got the same from 11.2.0.2):

Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL>
SQL> drop table t;

Table dropped.

SQL> purge table t;

Table purged.

SQL> create table t as select * from dba_objects, (select rownum from dual connect by level <= 20);

Table created.

SQL> create index i on t(object_id);

Index created.

SQL>
SQL> exec dbms_stats.gather_table_stats(user, 'T', method_opt => 'for all columns size 1')

PL/SQL procedure successfully completed.

SQL>
SQL> set echo on
SQL>
SQL> select count(*), min(object_id)
2 , max(object_id) from t;

COUNT(*) MIN(OBJECT_ID) MAX(OBJECT_ID)
---------- -------------- --------------
1385560 2 71521

SQL>
SQL> set echo on linesize 200 heading off newpage none tab off serveroutput off
SQL>
SQL> alter session set statistics_level = all;

Session altered.

SQL>
SQL> -- alter session set session_cached_cursors = 0;
SQL>
SQL> alter system flush buffer_cache;

System altered.

SQL>
SQL> alter system flush shared_pool;

System altered.

SQL>
SQL> var x number
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

SQL>
SQL> -- pause
SQL>
SQL> set timing on
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> column prev_sql_id new_value sql_id noprint
SQL> column sid new_value session_id noprint
SQL>
SQL> select
2 prev_sql_id
3 , sid
4 from
5 v$session
6 where
7 sid = sys_context('userenv', 'sid');

Elapsed: 00:00:00.06
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

-------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | 3 | | | |
-------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.46
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> column value new_value value_1
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5058

Elapsed: 00:00:00.01
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5058 as diff
session cursor cache hits 2

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5063

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5063 as diff
session cursor cache hits 2

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5069

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5069 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 100000

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5080

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );

Elapsed: 00:00:00.01
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5080 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

----------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:00.01 | 3 | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 3 | | | |
| 2 | VIEW | | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
| 3 | WINDOW SORT | | 1 | 12 | 0 |00:00:00.01 | 3 | 1024 | 1024 | |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 0 |00:00:00.01 | 3 | | | |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.10
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5090

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:17.12
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5090 as diff
session cursor cache hits 3

Elapsed: 00:00:00.00
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:17.10 | 1388K| 44110 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:17.10 | 1388K| 44110 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:16.03 | 1388K| 44110 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:16.03 | 1388K| 44110 | 10005 | 88M| 3227K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:09.70 | 1388K| 24154 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:01.39 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5100

Elapsed: 00:00:00.00
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:12.94
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5100 as diff
session cursor cache hits 3

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | 88M| 3232K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:06.93 | 1388K| 24059 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:00.01 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

25 rows selected.

Elapsed: 00:00:00.11
SQL>
SQL> exec :x := 1

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
SQL>
SQL> select
2 name
3 , value
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
session cursor cache hits 5110

Elapsed: 00:00:00.01
SQL>
SQL> select
2 sum(row_num)
3 from
4 (
5 select
6 row_number() over (partition by object_type order by object_name) as row_num
7 , t.*
8 from
9 t
10 where
11 object_id > :x
12 );
2.5311E+11

Elapsed: 00:00:06.02
SQL>
SQL> select
2 name
3 , value - &value_1 as diff
4 from
5 v$statname a
6 , v$sesstat b
7 where
8 a.statistic# = b.statistic#
9 and a.name = 'session cursor cache hits'
10 and b.sid = sys_context('userenv', 'sid');
old 3: , value - &value_1 as diff
new 3: , value - 5110 as diff
session cursor cache hits 3

Elapsed: 00:00:00.01
SQL>
SQL> select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'));
old 1: select * from table(dbms_xplan.display_cursor('&sql_id',null,'ALLSTATS LAST'))
new 1: select * from table(dbms_xplan.display_cursor('fmbq5ytmh0hng',null,'ALLSTATS LAST'))
SQL_ID fmbq5ytmh0hng, child number 0
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 1399240396

--------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:12.95 | 1388K| 44001 | 10005 | | | | |
| 2 | VIEW | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | | | | |
| 3 | WINDOW SORT | | 1 | 12 | 1385K|00:00:12.29 | 1388K| 44001 | 10005 | 88M| 3232K| 55M (1)| 80896 |
| 4 | TABLE ACCESS BY INDEX ROWID| T | 1 | 12 | 1385K|00:00:06.93 | 1388K| 24059 | 0 | | | | |
|* 5 | INDEX RANGE SCAN | I | 1 | 12 | 1385K|00:00:00.01 | 3060 | 3059 | 0 | | | | |
--------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

5 - access("OBJECT_ID">:X)

SQL_ID fmbq5ytmh0hng, child number 1
-------------------------------------
select sum(row_num) from ( select
row_number() over (partition by object_type order by object_name) as
row_num , t.* from t
where object_id > :x )

Plan hash value: 2719131525

----------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem | Used-Tmp|
----------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 1 |00:00:05.99 | 21058 | 34648 | 7955 | | | | |
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:05.99 | 21058 | 34648 | 7955 | | | | |
| 2 | VIEW | | 1 | 1385K| 1385K|00:00:05.74 | 21058 | 34648 | 7955 | | | | |
| 3 | WINDOW SORT | | 1 | 1385K| 1385K|00:00:04.35 | 21058 | 34648 | 7955 | 69M| 2893K| 55M (1)| 64512 |
|* 4 | TABLE ACCESS FULL| T | 1 | 1385K| 1385K|00:00:00.01 | 21054 | 21049 | 0 | | | | |
----------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

4 - filter("OBJECT_ID">:X)

49 rows selected.

Elapsed: 00:00:00.21
SQL>
SQL> set heading on
SQL>
SQL> select
2 sql_id
3 , child_number
4 , executions
5 , parse_calls
6 , buffer_gets
7 , is_bind_sensitive
8 , is_bind_aware
9 from
10 v$sql
11 where
12 sql_id = '&sql_id';
old 12: sql_id = '&sql_id'
new 12: sql_id = 'fmbq5ytmh0hng'
SQL_ID CHILD_NUMBER EXECUTIONS PARSE_CALLS BUFFER_GETS I I
------------- ------------ ---------- ----------- ----------- - -
fmbq5ytmh0hng 0 7 8 2777315 Y N
fmbq5ytmh0hng 1 1 0 21058 Y Y

Elapsed: 00:00:00.03
SQL>

So we can see that from the third execution on we seem to get a hit in the session cursor cache (increase from 2 to 3), but still ACS seems to work properly, although this time it had to go wrong twice before ACS created the second child cursor. We can also see that we still get as many PARSE calls as executions, so the session cursor cache does not avoid the parsing as outlined above.

All this seems to suggest that the ACS (and potentially the "Cardinality Feedback", too) code is only triggered by a PARSE call and not evaluated as part of an EXECUTE call.

But if this was the case, then by no means the problem would be limited to PL/SQL and its clever optimizations that try to hold cursors open to avoid repeated PARSE calls.

Actually one of the core principles that we are told to make an application as scalable as possible is to parse only once but execute many times. So let's try to simulate such a well behaving application with this simple Java code snippet that accesses the database via JDBC:

import java.sql.* ;

class JDBCQuery
{
public static void main( String args[] )
{
try
{
// Load the database driver
Class.forName( "oracle.jdbc.driver.OracleDriver" ) ;

// Get a connection to the database
Connection conn = DriverManager.getConnection("jdbc:oracle:thin:@host:port:sid",
"username", "pwd");

// Print all warnings
for( SQLWarning warn = conn.getWarnings(); warn != null; warn = warn.getNextWarning() )
{
System.out.println( "SQL Warning:" ) ;
System.out.println( "State : " + warn.getSQLState() ) ;
System.out.println( "Message: " + warn.getMessage() ) ;
System.out.println( "Error : " + warn.getErrorCode() ) ;
}

// Reset the buffer cache and shared pool
Statement ddl = conn.createStatement();
ddl.executeUpdate("alter system flush shared_pool");
ddl.executeUpdate("alter system flush buffer_cache");
ddl.close();

// Prepare the statement
String query =
"select\n" +
" sum(row_num)\n" +
"from\n" +
" (\n" +
" select\n" +
" row_number() over (partition by object_type order by object_name) as row_num\n" +
" , t.*\n" +
" from\n" +
" t\n" +
" where\n" +
" object_id > ?\n" +
" )";

PreparedStatement stmt = conn.prepareStatement(query);

System.out.println(query);

Integer i;
Integer id;

for (i = 1; i <= 10; i++)
{
if (i == 1)
{
id = 100000;
}
else
{
id = 1;
}

System.out.println( "Iteration: " + i.toString() ) ;

stmt.setInt(1, id);

long startTime = System.currentTimeMillis();

// Execute the query
ResultSet rs = stmt.executeQuery();

// Loop through the result set
while( rs.next() )
System.out.println( rs.getLong(1)) ;

// Close the result set
rs.close() ;

long endTime = System.currentTimeMillis();

float seconds = (endTime - startTime) / 1000F;

// Elapsed time
System.out.println(Float.toString(seconds) + " seconds.");
}

stmt.close() ;
conn.close() ;
}
catch( SQLException se )
{
System.out.println( "SQL Exception:" ) ;

// Loop through the SQL Exceptions
while( se != null )
{
System.out.println( "State : " + se.getSQLState() ) ;
System.out.println( "Message: " + se.getMessage() ) ;
System.out.println( "Error : " + se.getErrorCode() ) ;

se = se.getNextException() ;
}
}
catch( Exception e )
{
System.out.println( e ) ;
}
}
}

/*
Check the Shared Pool by this query:

select
sql_id
, child_number
, executions
, parse_calls
, buffer_gets
, disk_reads
, direct_writes
, is_bind_sensitive
, is_bind_aware
from
v$sql
where
sql_id = 'cq3a8ukkws0su';

*/

This (by no means elegant or clever) piece of Java code again tries to do the same as our previous examples: It executes the known query ten times but behaves well since it parses only once and executes ten times using the two different bind values as already done before.

I only tested this with the JDBC thin driver that comes with Oracle 11.2.0.2 but not with the thick driver. However, since I assume that 95%+ of all Java applications out there actually use the thin driver this probably covers the most relevant case.

The results correspond to those of the PL/SQL examples with the "keep cursors open" optimization enabled: Neither ACS nor "Cardinality Feedback" kick in, and the SQL is executed every time using the same execution plan. The SQL is only parsed once, so the problem is not really limited to PL/SQL, but to every application that tries to avoid parse calls.

Summary

ACS is a great feature, but you need to be aware of its limitations, the most important being:

- Things have to go wrong first before ACS will be able to provide a fix. Depending on how "wrong" things can go, this might mean that ACS is actually not able to provide an efficient fix for certain cases
- The ACS information can be aged out of the Shared Pool which might lead to repeated "things have to go wrong" cases
- ACS is only triggered by explicit PARSE calls, it is not activated if the application parses once and executes many times

If you have a case where you need to help (or "co-operate" as Jonathan Lewis calls it in his brilliant presentation of the same name) your database, the simplest strategy is to use literals instead of bind variables. If you can't do this due to the issues introduced by this strategy (excessive hard parses, increased CPU and Shared Pool usage, library cache contention etc.) a more complex strategy - if applicable - is to "know your data" and generate a minimum amount of cursors that try to cover the cases where a different execution plan is desired.

This means something like this in pseudo code:

- If "known value A that requires a special treatment" then
-- execute SQL with dummy hint "A" or additional non-modifying predicate "A" = "A" to make the SQL unique
- If "known value B that requires a special treatment" then
-- execute SQL with dummy hint "B" or additional non-modifying predicate "B" = "B" to make the SQL unique
- Else "in all other cases"
-- execute SQL as is

Notice that using comments to make the SQL unique might not lead to the expected result since there are cases/environments where comments are stripped prior to execution.

Update: From a comment by Sokrates below that for some reason didn't make to the comments section but also doesn't show up in the "Spam" comments of the blog control panel I see that above description "dummy hint" might need a bit more explanation.

By "dummy hint" I mean to say that you should use hint syntax rather than normal comment syntax to make the SQL unique, because the normal comment might get filtered out whereas the comment using hint syntax is supposed to be kept. By "dummy hint" I mean any invalid hint comment in order to prevent any influence on the optimizer, for example /*+ CASE_A */ rather than /* CASE_A */

Nice surprise-automatic statistics email

Today I got a nice surprise email from WordPress. Seems like my blog wasn’t doing too badly last year. I would like to thank all visitors for passing by and reading my ramblings about this and that-mainly Oracle related.

Have a happy New Year all!

nullif()

Have you ever written SQL that had to protect against a “divide by zero” error ?

The way I used to do this was typically to introduce a decode() function to produce some vaguely appropriate result if the divisor were zero; but there is a tidier option that appeared a few years ago. For example:

select
	sql_id,
	executions,
	rows_processed,
	rows_processed/(executions) rows_per_exec
from
	v$sql
where
	cpu_time > 1000000
;

ERROR:
ORA-01476: divisor is equal to zero

select
	sql_id,
	executions,
	rows_processed,
	rows_processed/nullif(executions,0) rows_per_exec
from
	v$sql
where
	cpu_time > 1000000
;

SQL_ID        EXECUTIONS ROWS_PROCESSED ROWS_PER_EXEC
------------- ---------- -------------- -------------
cn1gtsav2d5jh        653            653             1
d92h3rjp0y217         18             18             1
78m9ryygp65v5        856            856             1
bcvpx27d43v6s          0              3
63fyqfhnd7u5k         41            134    3.26829268

To avoid the error I’ve used the nullif() function – it’s easy to read: the function returns null if the first parameter equals the second parameter (otherwise it returns the first parameter). So in my example my divisor returns null if executions is zero. (And any arithmetic involving null returns null – which is something I’d generally rather see than a gap-filling “silly number”.)

Analytic Functions – What is Wrong with this Statement?

January 1, 2011 I was a bit excited to see the chapter discussing analytic functions in the book “Pro Oracle SQL”, which has a rather extensive coverage of most of Oracle Database’s analytic functions (something that I have not seen from other SQL books).  That chapter is very well assembled, with easier to understand descriptions [...]

O-1 Visa

Congratulations to Mark Rittman of Ritmann Mead who emailed me last night to tell me that his application for an O1 visa (“aliens of exceptional ability”) to work in the USA had been granted.

There aren’t many of us around in the Oracle field (in a quick google search the I found just one other holder from the UK in a facebook entry for a Hyperion specialist) and Mark is certainly an appropriate addition to the select band.

Quiz Night

Many people in the UK like to greet the new year with some sort of party, and in this household the type of party we like includes old-fashioned party games (can you draw “Brief Encounters” in 10 seconds ?); so, for all those members of the Oracle community who haven’t prepared their party games this year, here’s a little quiz:

Which processes could report waits for “log file sequential read”, and why ?

    1.

    10.

Warning: the number of answers I have may, or may not, be the 10 suggested by the list.

Update Jan 5th: There were a couple of answers I wasn’t expecting (and would need to check), but some things are fairly easy to check. Here, for example, is a simple script that will identify sessions that regularly wait for ‘log file sequential read’.

select
	ses.program
from
	v$session_event sev,
	V$session ses
where
	sev.event = 'log file sequential read'
and	ses.sid = sev.sid
;

Answers 7th Jan:

The obvious one, of course, is ARCH (or ARCn as they tend to be) the archiver process(es). Archiving requires something to read the online redo and copy them to some other location. Here’s a brief extract from tracing an archive process – showing reads of 1MB (2048 x 512 bytes per block) -just after a log file switch:

WAIT #0: nam='log file sequential read' ela= 38410 log#=0 block#=1 blocks=2048 obj#=-1 tim=101515708285
WAIT #0: nam='Log archive I/O' ela= 183580 count=1 intr=256 timeout=-1 obj#=-1 tim=101515892589
WAIT #0: nam='log file sequential read' ela= 84409 log#=0 block#=2049 blocks=2048 obj#=-1 tim=101515977375
WAIT #0: nam='Log archive I/O' ela= 116641 count=1 intr=256 timeout=-1 obj#=-1 tim=101516094684
WAIT #0: nam='log file sequential read' ela= 31139 log#=0 block#=4097 blocks=2048 obj#=-1 tim=101516126157
WAIT #0: nam='Log archive I/O' ela= 122492 count=1 intr=256 timeout=-1 obj#=-1 tim=101516250399
WAIT #0: nam='log file sequential read' ela= 32197 log#=0 block#=6145 blocks=2048 obj#=-1 tim=101516282965
WAIT #0: nam='Log archive I/O' ela= 122779 count=1 intr=256 timeout=-1 obj#=-1 tim=101516552698
WAIT #0: nam='Log archive I/O' ela= 4 count=0 intr=32 timeout=2147483647 obj#=-1 tim=101516552996
WAIT #0: nam='Log archive I/O' ela= 25 count=1 intr=32 timeout=2147483647 obj#=-1 tim=101516553297

Slightly less obvious is LGWR, the log writer itself. Apart from reading the log files at (normal) startup to check that they’re there, LGWR reads the start of the current and next log files on every log switch. Here’s the trace file of LGWR on a log file switch where there are two files in each group:

WAIT #0: nam='log file sequential read' ela= 32788 log#=0 block#=1 blocks=1 obj#=-1 tim=100016453547
WAIT #0: nam='log file sequential read' ela= 18309 log#=1 block#=1 blocks=1 obj#=-1 tim=100016471921
WAIT #0: nam='log file single write' ela= 518 log#=0 block#=1 blocks=1 obj#=-1 tim=100016472654
WAIT #0: nam='log file single write' ela= 516 log#=1 block#=1 blocks=1 obj#=-1 tim=100016473225
Media recovery not enabled or manual archival only 0x10000
WAIT #0: nam='log file sequential read' ela= 90 log#=0 block#=1 blocks=1 obj#=-1 tim=100016473376
WAIT #0: nam='log file sequential read' ela= 73 log#=1 block#=1 blocks=1 obj#=-1 tim=100016473474
WAIT #0: nam='log file single write' ela= 477 log#=0 block#=1 blocks=1 obj#=-1 tim=100016473981
WAIT #0: nam='log file single write' ela= 856 log#=1 block#=1 blocks=1 obj#=-1 tim=100016474885

By playing around with files per group we can work out that the order of activity is:

    read the current
    write the next
    read the current
    write the current

Next up: any process which is involved in (asynchronous) Change Data Capture (CDC) or Streams will be reading the log files, as will any process running a Log Miner session.

A couple of people suggested the SMON and PX slaves could read the log file on database startup – but as another poster pointed out, it’s the startup process that reads the log files – and if parallel recovery is invoked it passes change vectors to the PX slaves, the slaves don’t read the log files directly. Apart from that, I don’t really know which processes read the log file – I don’t want to say “process X doesn’t” read the log file, because it may do at times that I haven’t considered. (And there are lots of processes to look into in 11g.)

However, there is one (generic) process that can read the log files – and that’s ANY process that has to handle data blocks. And that’s really why I wrote this note in the first place. If a process finds at any time that the buffer it’s looking at in memory is corrupt it may do real-time block recovery if it thinks the corruption has occurred between the moment the block was read from disk and the present. There are various flags and details in the buffer header that tell it that the block is dirty (differs from what’s on disk) and the redo block address (RBA) where the earliest known change to the in-memory block can be found in the log files.

So any process may, in conditions that shouldn’t happen often (we hope), identify an in-memory corrupt, read a block from disc, then go backwards in time in the redo logs and start walking the redo logs to find the redo needed to bring the block up to date. So if you see excessive amounts of “log file sequential read” coming from your foreground session, check what’s going on – it might be an indication of a hardware fault.

Thanks to anyone who participated – and if anyone runs the little script and finds some new examples of log file sequential reads, please add them to the list.

Update Jan 2011:
Thanks to Pavol Babel in comment 8 and his reply to comment 7 for adding MRP0 and RFS to the list of processes that are expected to read the log file.