During a research for VOODOO, we came across a lot of interesting stuff inside REDO.
One of my favourites is an UPDATE, becoming an INSERT 🙂
So let’s see what has happened – I performed the following update on a sample table:
SQL> desc hr.VD_TEST_REPLICATION Name Null? Type ----------------------------------------------------- -------- ------------------------------------ ID NOT NULL NUMBER STRINGS VARCHAR2(4000) TIME1 TIMESTAMP(6) TIME2 TIMESTAMP(6) WITH LOCAL TIME ZONE TIME3 TIMESTAMP(6) WITH TIME ZONE TIME4 DATE CLOB_DATA CLOB BLOB_DATA BLOB SQL> ; 1 update HR.VD_TEST_REPLICATION 2 set clob_data='Czwane cząsteczki Czechowa.', 3* strings='ola la la la la' SQL> / 101 rows updated.
The regular dump of redo log with an UPDATE looks like this:
REDO RECORD - Thread:2 RBA: 0x00009d.000400b4.0050 LEN: 0x01e8 VLD: 0x01 CON_UID: 0
SCN: 0x0000.0160a562 SUBSCN:362 07/24/2017 09:23:05
CHANGE #1 CON_ID:0 TYP:0 CLS:52 AFN:2 DBA:0x008021b0 OBJ:4294967295 SCN:0x0000.0160a562 SEQ:25 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 216 spc: 4366 flg: 0x0022 seq: 0x031e rec: 0x19
xid: 0x0012.016.00001564
ktubu redo: slt: 22 rci: 24 opc: 11.1 objn: 98618 objd: 98618 tsn: 7
Undo type: Regular undo Undo type: Last buffer split: No
Tablespace Undo: No
0x00000000
KDO undo record:
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021b0.031e.18
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 31(0x1f) flag: 0x2c lock: 2 ckix: 49
ncol: 8 nnew: 2 size: -31
col 1: [29]
63 69 65 70 c5 82 65 20 6b 6c 75 63 68 79 2c 20 6b 6f 73 74 75 63 68 79 20
40 40 21 21
col 6: [39]
00 54 00 01 02 0c 80 80 00 02 00 00 00 01 00 00 00 3f 74 2b 00 13 40 90 00
0d 22 00 01 ee c8 01 00 02 01 c0 3a 5b 10
CHANGE #2 CON_ID:0 TYP:0 CLS:1 AFN:7 DBA:0x01c0015e OBJ:98618 SCN:0x0000.0160a562 SEQ:63 OP:11.5 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021b0.031e.19
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 31(0x1f) flag: 0x2c lock: 2 ckix: 49
ncol: 8 nnew: 2 size: 31
col 1: [15] 6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61
col 6: [84]
00 54 00 01 02 0c 80 80 00 02 00 00 00 01 00 00 00 3f 75 b0 00 40 48 90 00
3a 00 00 36 01 00 43 00 7a 00 77 00 61 00 6e 00 65 00 20 00 63 00 7a 01 05
00 73 00 74 00 65 00 63 00 7a 00 6b 00 69 00 20 00 43 00 7a 00 65 00 63 00
68 00 6f 00 77 00 61 00 2e
In this particular redo record, we can see 2 changes:
- CHANGE #1 – with OP:5.1 is an UNDO information
- CHANGE #2 – with OP:11.5 is an actual UPDATE
We can see here, that column 1 changes from "cieple kluchy, kostuchy @@!!" to "ola la la la la". You can check it with simple query:
SQL> ed
Wrote file afiedt.buf
1 select utl_raw.cast_to_varchar2(replace('63 69 65 70 c5 82 65 20 6b 6c 75 63 68 79 2c 20 6b 6f 73 74 75 63 68 79 20 40 40 21 21',' ','')),
2 utl_raw.cast_to_varchar2(replace('6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61',' ',''))
3* from dual
SQL> /
UTL_RAW.CAST_TO_VARCHAR2(REPLACE('63696570C58265206B6C756368792C206B6F7374756368792040402121','','')
----------------------------------------------------------------------------------------------------
UTL_RAW.CAST_TO_VARCHAR2(REPLACE('6F6C61206C61206C61206C61206C61','',''))
----------------------------------------------------------------------------------------------------
cieple kluchy, kostuchy @@!!
ola la la la la
The column 6 (CLOB) on the other hand changes from out of row storage to in-line storage. You can see it by obtaining bytes on position 22 and 23 – "0x4890″ means, that this CLOB is in-line and you can check the actual value by extracting bytes from position 30 to the end.
You can use Python to decode CLOB value. Since my database is AL32UTF8 I have to use utf-16-be coding which is actual coding for CLOBs in Oracle with AL32UTF8.
>>> print unicode("00 54 00 01 02 0c 80 80 00 02 00 00 00 01 00 00 00 3f 75 b0 00 40 48 90 00 3a 00 00 36 01 00 43 00 7a 00 77 00 61 00 6e 00 65 00 20 00 63 00 7a 01 05 00 73 00 74 00 65 00 63 00 7a 00 6b 00 69 00 20 00 43 00 7a 00 65 00 63 00 68 00 6f 00 77 00 61 00 2e".replace(" ","").decode("hex")[30:],"utf-16-be")
Czwane cząsteczki Czechowa.
So this is how an UPDATE actually looks like. But the funny thing is, that I found also an INSERT in my REDO dump! It looks like this:
REDO RECORD - Thread:2 RBA: 0x00009d.00040138.01dc LEN: 0x01f8 VLD: 0x01 CON_UID: 0
SCN: 0x0000.0160a562 SUBSCN:367 07/24/2017 09:23:05
CHANGE #1 CON_ID:0 TYP:0 CLS:52 AFN:2 DBA:0x008021b0 OBJ:4294967295 SCN:0x0000.0160a562 SEQ:27 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 100 spc: 4054 flg: 0x0022 seq: 0x031e rec: 0x1b
xid: 0x0012.016.00001564
ktubu redo: slt: 22 rci: 26 opc: 11.1 objn: 98618 objd: 98618 tsn: 7
Undo type: Regular undo Undo type: Last buffer split: No
Tablespace Undo: No
0x00000000
KDO undo record:
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021af.031e.02
KDO Op code: DRP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015f hdba: 0x01c000b2
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15)
CHANGE #2 CON_ID:0 TYP:0 CLS:1 AFN:7 DBA:0x01c0015f OBJ:98618 SCN:0x0000.0160a562 SEQ:1 OP:11.2 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021b0.031e.1b
KDO Op code: IRP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015f hdba: 0x01c000b2
itli: 2 ispac: 24 maxfr: 4858
tabn: 0 slot: 21(0x15) size/delt: 209
fb: ----FL-- lb: 0x2 cc: 8
hrid: 0x01c0015e.20
null: --------
col 0: [ 6] c2 06 01 26 44 3d
col 1: [15] 6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61
col 2: [11] 78 75 07 18 0b 26 33 1e 84 80 00
col 3: [11] 78 75 07 18 0b 26 36 05 b8 d8 00
col 4: [13] 78 75 07 18 0b 26 39 38 25 c7 80 86 38
col 5: [ 7] 78 75 07 18 0b 27 01
col 6: [84]
00 54 00 01 02 0c 80 80 00 02 00 00 00 01 00 00 00 3f 75 b1 00 40 48 90 00
3a 00 00 36 01 00 43 00 7a 00 77 00 61 00 6e 00 65 00 20 00 63 00 7a 01 05
00 73 00 74 00 65 00 63 00 7a 00 6b 00 69 00 20 00 43 00 7a 00 65 00 63 00
68 00 6f 00 77 00 61 00 2e
col 7: [45]
00 54 00 01 01 0c 00 80 00 01 00 00 00 01 00 00 00 3f 74 2e 00 19 40 90 00
13 22 00 10 5b 5d 01 01 02 01 c1 2c c1 6d 02 01 c2 47 f1 18
OP:11.2 is code for INSERT and we can see here all 8 columns of the table. The next REDO record which follows looks almost like a DELETE:
REDO RECORD - Thread:2 RBA: 0x00009d.000400b5.01a0 LEN: 0x01f8 VLD: 0x01 CON_UID: 0
SCN: 0x0000.0160a562 SUBSCN:368 07/24/2017 09:23:05
CHANGE #1 CON_ID:0 TYP:0 CLS:52 AFN:2 DBA:0x008021b0 OBJ:4294967295 SCN:0x0000.0160a562 SEQ:28 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 324 spc: 3952 flg: 0x0022 seq: 0x031e rec: 0x1c
xid: 0x0012.016.00001564
ktubu redo: slt: 22 rci: 27 opc: 11.1 objn: 98618 objd: 98618 tsn: 7
Undo type: Regular undo Undo type: Last buffer split: No
Tablespace Undo: No
0x00000000
KDO undo record:
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021b0.031e.1a
KDO Op code: ORP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 32(0x20) size/delt: 172
fb: --H-FL-- lb: 0x2 cc: 8
null: --------
col 0: [ 6] c2 06 01 26 44 3d
col 1: [29]
63 69 65 70 c5 82 65 20 6b 6c 75 63 68 79 2c 20 6b 6f 73 74 75 63 68 79 20
40 40 21 21
col 2: [11] 78 75 07 18 0b 26 33 1e 84 80 00
col 3: [11] 78 75 07 18 0b 26 36 05 b8 d8 00
col 4: [13] 78 75 07 18 0b 26 39 38 25 c7 80 86 38
col 5: [ 7] 78 75 07 18 0b 27 01
col 6: [39]
00 54 00 01 02 0c 80 80 00 02 00 00 00 01 00 00 00 3f 74 2d 00 13 40 90 00
0d 22 00 01 ee c8 01 00 02 01 c0 3a 6b 10
col 7: [45]
00 54 00 01 01 0c 00 80 00 01 00 00 00 01 00 00 00 3f 74 2e 00 19 40 90 00
13 22 00 10 5b 5d 01 01 02 01 c1 2c c1 6d 02 01 c2 47 f1 18
CHANGE #2 CON_ID:0 TYP:0 CLS:1 AFN:7 DBA:0x01c0015e OBJ:98618 SCN:0x0000.0160a562 SEQ:65 OP:11.6 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x008021b0.031e.1c
KDO Op code: ORP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 32(0x20) size/delt: 9
fb: --H----- lb: 0x2 cc: 0
nrid: 0x01c0015f.15
null:
It looks almost like DELETE because the actual DELETE code is 11.3 and not 11.6. So it seems like instead of UPDATE, Oracle is doing an INSERT and then something like DELETE. But why? Everything clears when we ANALYZE a table in search for chained rows.
(Please check out this article by Tanel Poder on chained and migrated rows https://blog.tanelpoder.com/2009/11/04/detect-chained-and-migrated-rows-in-oracle/)
In the UNDO vector, you can see all the values necessary to build an INSERT, which is the actual undo operation for this statement.
Let’s check if the content of the UNDO INSERT matches with a chained row:
SQL> create table CHAINED_ROWS (
owner_name varchar2(30),
table_name varchar2(30),
cluster_name varchar2(30),
partition_name varchar2(30),
subpartition_name varchar2(30),
head_rowid rowid,
analyze_timestamp date
); 2 3 4 5 6 7 8 9
Table created.
SQL> analyze table hr.VD_TEST_REPLICATION list chained rows;
Table analyzed.
SQL> ed
Wrote file afiedt.buf
1 select t.id
2 from hr.VD_TEST_REPLICATION t, CHAINED_ROWS c
3 where id=utl_raw.cast_to_number(replace('c2 06 01 26 44 3d',' ',''))
4* and c.head_rowid=t.rowid
SQL> /
ID
----------
500.37676
So we have a winner! Whenever the rows are being chained or migrated, the content of the REDO looks a little bit like INSERT and DELETE instead of just UPDATE.
So it means that chained and migrated rows are not only affecting SELECT statements but also can cause much more REDO to be generated.