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:
1 | SQL> desc hr.VD_TEST_REPLICATION |
3 | ----------------------------------------------------- -------- ------------------------------------ |
7 | TIME2 TIMESTAMP(6) WITH LOCAL TIME ZONE |
8 | TIME3 TIMESTAMP(6) WITH TIME ZONE |
14 | 1 update HR.VD_TEST_REPLICATION |
15 | 2 set clob_data='Czwane cząsteczki Czechowa.', |
16 | 3* strings='ola la la la la' |
The regular dump of redo log with an UPDATE looks like this:
1 | REDO RECORD - Thread:2 RBA: 0x00009d.000400b4.0050 LEN: 0x01e8 VLD: 0x01 CON_UID: 0 |
2 | SCN: 0x0000.0160a562 SUBSCN:362 07/24/2017 09:23:05 |
3 | 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 |
4 | ktudb redo: siz: 216 spc: 4366 flg: 0x0022 seq: 0x031e rec: 0x19 |
5 | xid: 0x0012.016.00001564 |
6 | ktubu redo: slt: 22 rci: 24 opc: 11.1 objn: 98618 objd: 98618 tsn: 7 |
7 | Undo type: Regular undo Undo type: Last buffer split: No |
13 | compat bit: 4 (post-11) padding: 1 |
14 | op: C uba: 0x008021b0.031e.18 |
15 | KDO Op code: URP row dependencies Disabled |
16 | xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2 |
17 | itli: 2 ispac: 0 maxfr: 4858 |
18 | tabn: 0 slot: 31(0x1f) flag: 0x2c lock: 2 ckix: 49 |
19 | ncol: 8 nnew: 2 size: -31 |
21 | 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 |
24 | 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 |
25 | 0d 22 00 01 ee c8 01 00 02 01 c0 3a 5b 10 |
26 | 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 |
29 | compat bit: 4 (post-11) padding: 1 |
30 | op: C uba: 0x008021b0.031e.19 |
31 | KDO Op code: URP row dependencies Disabled |
32 | xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2 |
33 | itli: 2 ispac: 0 maxfr: 4858 |
34 | tabn: 0 slot: 31(0x1f) flag: 0x2c lock: 2 ckix: 49 |
35 | ncol: 8 nnew: 2 size: 31 |
36 | col 1: [15] 6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61 |
38 | 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 |
39 | 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 |
40 | 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 |
41 | 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:
4 | 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',' ','')), |
5 | 2 utl_raw.cast_to_varchar2(replace('6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61',' ','')) |
9 | UTL_RAW.CAST_TO_VARCHAR2(REPLACE('63696570C58265206B6C756368792C206B6F7374756368792040402121','','') |
10 | ---------------------------------------------------------------------------------------------------- |
11 | UTL_RAW.CAST_TO_VARCHAR2(REPLACE('6F6C61206C61206C61206C61206C61','','')) |
12 | ---------------------------------------------------------------------------------------------------- |
13 | cieple kluchy, kostuchy @@!! |
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.
1 | >>> 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") |
2 | 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:
1 | REDO RECORD - Thread:2 RBA: 0x00009d.00040138.01dc LEN: 0x01f8 VLD: 0x01 CON_UID: 0 |
2 | SCN: 0x0000.0160a562 SUBSCN:367 07/24/2017 09:23:05 |
3 | 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 |
4 | ktudb redo: siz: 100 spc: 4054 flg: 0x0022 seq: 0x031e rec: 0x1b |
5 | xid: 0x0012.016.00001564 |
6 | ktubu redo: slt: 22 rci: 26 opc: 11.1 objn: 98618 objd: 98618 tsn: 7 |
7 | Undo type: Regular undo Undo type: Last buffer split: No |
13 | compat bit: 4 (post-11) padding: 1 |
14 | op: C uba: 0x008021af.031e.02 |
15 | KDO Op code: DRP row dependencies Disabled |
16 | xtype: XA flags: 0x00000000 bdba: 0x01c0015f hdba: 0x01c000b2 |
17 | itli: 2 ispac: 0 maxfr: 4858 |
19 | 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 |
22 | compat bit: 4 (post-11) padding: 1 |
23 | op: C uba: 0x008021b0.031e.1b |
24 | KDO Op code: IRP row dependencies Disabled |
25 | xtype: XA flags: 0x00000000 bdba: 0x01c0015f hdba: 0x01c000b2 |
26 | itli: 2 ispac: 24 maxfr: 4858 |
27 | tabn: 0 slot: 21(0x15) size/delt: 209 |
28 | fb: ----FL-- lb: 0x2 cc: 8 |
31 | col 0: [ 6] c2 06 01 26 44 3d |
32 | col 1: [15] 6f 6c 61 20 6c 61 20 6c 61 20 6c 61 20 6c 61 |
33 | col 2: [11] 78 75 07 18 0b 26 33 1e 84 80 00 |
34 | col 3: [11] 78 75 07 18 0b 26 36 05 b8 d8 00 |
35 | col 4: [13] 78 75 07 18 0b 26 39 38 25 c7 80 86 38 |
36 | col 5: [ 7] 78 75 07 18 0b 27 01 |
38 | 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 |
39 | 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 |
40 | 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 |
41 | 68 00 6f 00 77 00 61 00 2e |
43 | 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 |
44 | 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:
1 | REDO RECORD - Thread:2 RBA: 0x00009d.000400b5.01a0 LEN: 0x01f8 VLD: 0x01 CON_UID: 0 |
2 | SCN: 0x0000.0160a562 SUBSCN:368 07/24/2017 09:23:05 |
3 | 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 |
4 | ktudb redo: siz: 324 spc: 3952 flg: 0x0022 seq: 0x031e rec: 0x1c |
5 | xid: 0x0012.016.00001564 |
6 | ktubu redo: slt: 22 rci: 27 opc: 11.1 objn: 98618 objd: 98618 tsn: 7 |
7 | Undo type: Regular undo Undo type: Last buffer split: No |
13 | compat bit: 4 (post-11) padding: 1 |
14 | op: C uba: 0x008021b0.031e.1a |
15 | KDO Op code: ORP row dependencies Disabled |
16 | xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2 |
17 | itli: 2 ispac: 0 maxfr: 4858 |
18 | tabn: 0 slot: 32(0x20) size/delt: 172 |
19 | fb: --H-FL-- lb: 0x2 cc: 8 |
21 | col 0: [ 6] c2 06 01 26 44 3d |
23 | 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 |
25 | col 2: [11] 78 75 07 18 0b 26 33 1e 84 80 00 |
26 | col 3: [11] 78 75 07 18 0b 26 36 05 b8 d8 00 |
27 | col 4: [13] 78 75 07 18 0b 26 39 38 25 c7 80 86 38 |
28 | col 5: [ 7] 78 75 07 18 0b 27 01 |
30 | 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 |
31 | 0d 22 00 01 ee c8 01 00 02 01 c0 3a 6b 10 |
33 | 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 |
34 | 13 22 00 10 5b 5d 01 01 02 01 c1 2c c1 6d 02 01 c2 47 f1 18 |
35 | 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 |
38 | compat bit: 4 (post-11) padding: 1 |
39 | op: C uba: 0x008021b0.031e.1c |
40 | KDO Op code: ORP row dependencies Disabled |
41 | xtype: XA flags: 0x00000000 bdba: 0x01c0015e hdba: 0x01c000b2 |
42 | itli: 2 ispac: 0 maxfr: 4858 |
43 | tabn: 0 slot: 32(0x20) size/delt: 9 |
44 | fb: --H----- lb: 0x2 cc: 0 |
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:
1 | SQL> create table CHAINED_ROWS ( |
2 | owner_name varchar2(30), |
3 | table_name varchar2(30), |
4 | cluster_name varchar2(30), |
5 | partition_name varchar2(30), |
6 | subpartition_name varchar2(30), |
13 | SQL> analyze table hr.VD_TEST_REPLICATION list chained rows; |
21 | 2 from hr.VD_TEST_REPLICATION t, CHAINED_ROWS c |
22 | 3 where id=utl_raw.cast_to_number(replace('c2 06 01 26 44 3d',' ','')) |
23 | 4* and c.head_rowid=t.rowid |
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.