I was using SLOB to compare the throughput between 12.1 and 12.2 databases, and was surprised to see that the average redo size per transaction was ~18.5KB on 12cR2, and ~339KB on 12cR1. Understanding this difference was important for the assessment and interpretation of the test results.
This is going to be a short blog post about an apparently new redo volume optimization that’s introduced in Oracle Database 12c R2.
Before I explain how I found it, here’s the conclusion for the impatient ones: There’s a new feature in 12cR2 that reduces the redo volume by removing the new column values from the redo records in cases when UPDATES set the column to its already existing value.
I spent some time checking the AWR report differences and tracing the sessions to rule out all the obvious candidates and found nothing obvious there:
- the redo block size was the same – 512
- the “redo wastage” (statistic) was very low
- no other workload was running at the same time, so the transactions were coming purely from SLOB.
- in both cases, SLOB was configured with the same parameters, and the workload characteristics were the same (i.e. the same number of updates per transaction, the same SQL in the top, etc)
I also used a query I wrote a while ago to extract the redo size (by object and by transaction) directly from the redo logs:
exec DBMS_LOGMNR.ADD_LOGFILE('&FILENAME');
exec DBMS_LOGMNR.START_LOGMNR(OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG);
set pages 50000 lines 500 tab OFF TIME ON serverout ON
col owner FOR a30
col object_name FOR a30
col subobject_name FOR a30
col object_type FOR a30
select * from (
SELECT data_obj#,
owner,
object_name,
subobject_name,
XIDUSN,XIDSLT,XIDSQN,XID,
COUNT(*) REDO_CNT,
SUM(r_size_b) / 1024 / 1024 REDO_MB
FROM (SELECT data_obj#,XIDUSN,XIDSLT,XIDSQN,XID,
rbablk,
rbabyte,
rbablk * 512 + rbabyte
b_offset,
( LEAD(rbablk * 512 + rbabyte)
over (
PARTITION BY rbasqn
ORDER BY rbablk*512+rbabyte) ) - ( rbablk * 512 + rbabyte )
R_SIZE_B
FROM v$logmnr_contents) lc,
dba_objects o
WHERE o.object_id(+) = lc.data_obj#
and owner='USER1' and object_name='CF1'
GROUP BY data_obj#,
owner,
object_name,
subobject_name, XIDUSN,XIDSLT,XIDSQN,XID
) where rownum<=5;
exec DBMS_LOGMNR.END_LOGMNR;
And I confirmed the redo size per transaction was a lot different between the two versions.
This is on 12cR1 (pay attention to the REDO_MB column, I moved it to the front for visibility):
REDO_MB DATA_OBJ# OWNER OBJECT_NAME SUBOBJECT_NAME XIDUSN XIDSLT XIDSQN XID REDO_CNT
---------- ---------- ------------------------------ ------------------------------ ------------------------------ ---------- ---------- ---------- ---------------- ----------
.333778381 19726234 USER1 CF1 1 0 5582960 0100000070305500 63
.334209442 19726234 USER1 CF1 1 0 5582961 0100000071305500 63
.333782196 19726234 USER1 CF1 1 1 5583160 0100010038315500 63
.33380127 19726234 USER1 CF1 1 1 5583161 0100010039315500 63
.328651428 19726234 USER1 CF1 1 2 5582217 01000200892D5500 63
This is on 12cR2:
REDO_MB DATA_OBJ# OWNER OBJECT_NAME SUBOBJECT_NAME XIDUSN XIDSLT XIDSQN XID REDO_CNT
---------- ---------- ------------------------------ ------------------------------ ------------------------------ ---------- ---------- ---------- ---------------- ----------
.018199921 100475 USER1 CF1 1 0 148400 01000000B0430200 63
.018596649 100475 USER1 CF1 1 0 148351 010000007F430200 63
.018745422 100475 USER1 CF1 1 0 148352 0100000080430200 63
.018726349 100475 USER1 CF1 1 0 148353 0100000081430200 63
.018543243 100475 USER1 CF1 1 0 148354 0100000082430200 63
As I hadn’t observed any workload differences up to this point, I decided to take some logfile dumps and look at them. SLOB uses one SQL statement to update the data, so it was easy to identify the redo records for the CF1:
UPDATE CF1 SET C2 = 'AAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBB',
... skipped 18 more columns to improve readability ...,
C20 = 'AAAAAAAABBBBBBBBAAAAAAAA0BBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBBBBBBAAAAAAAABBBB0BBBAAAAAAAABBBBBBBBAAAAAAAABBBBB3BBAAAAAAAABBBBBBBB'
WHERE CUSTID > ( :B1 - :B2 ) AND ( CUSTID < :B1 )
And this is what I found in the redo log dumps on 12cR1 – we see two records per row – redo for the undo blocks first, and the actual change of the CF1, including the new values that the columns are updated to:
REDO RECORD - Thread:1 RBA: 0x00354d.000002ae.010c LEN: 0x15b0 VLD: 0x01 CON_UID: 0
SCN: 0x0b28.3f9903c6 SUBSCN: 1 06/20/2018 05:41:48
CHANGE #1 CON_ID:0 TYP:0 CLS:83 AFN:7 DBA:0x01c00290 OBJ:4294967295 SCN:0x0b28.3f9903bb SEQ:1 OP:5.2 ENC:0 RBL:0 FLG:0x0000
ktudh redo: slt: 0x0005 sqn: 0x005391cc flg: 0x0012 siz: 2684 fbi: 0
uba: 0x022173ea.3dc2.02 pxid: 0x0000.000.00000000
CHANGE #2 CON_ID:0 TYP:0 CLS:84 AFN:8 DBA:0x022173ea OBJ:4294967295 SCN:0x0b28.3f9903ba SEQ:2 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 2684 spc: 5516 flg: 0x0012 seq: 0x3dc2 rec: 0x02
xid: 0x0022.005.005391cc
ktubl redo: slt: 5 rci: 0 opc: 11.1 [objn: 19726234 objd: 19726236 tsn: 463]
Undo type: Regular undo Begin trans Last buffer split: No
Temp Object: No
Tablespace Undo: No
0x00000000 prev ctl uba: 0x022173d5.3dc2.02
prev ctl max cmt scn: 0x0b28.3f990377 prev tx cmt scn: 0x0b28.3f990378
txn start scn: 0xffff.ffffffff logon user: 3124 prev brb: 35746101 prev bcl: 0 BuExt idx: 0 flg2: 0
KDO undo record:
KTB Redo
op: 0x04 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: L itl: xid: 0x0019.016.0055d79e uba: 0x01e5c11c.7646.03
flg: C--- lkc: 0 scn: 0x0b28.3f99032b
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x0315b558 hdba: 0x02a40003
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0) flag: 0x2c lock: 0 ckix: 6
ncol: 20 nnew: 19 size: 0
col 1: [128]
41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42
42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41
41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42
42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41
41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42
42 42 42
...
col 19: [128]
41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 30
42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41
41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42
42 30 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41
41 41 41 41 42 42 42 42 42 33 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42
42 42 42
CHANGE #3 CON_ID:0 TYP:2 CLS:1 AFN:301 DBA:0x0315b558 OBJ:19726236 SCN:0x0b28.3f990368 SEQ:1 OP:11.5 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x11 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0022.005.005391cc uba: 0x022173ea.3dc2.02
Block cleanout record, scn: 0x0b28.3f9903c6 ver: 0x01 opt: 0x02, entries follow...
itli: 1 flg: (opt=2 whr=1) scn: 0x0b28.3f990368
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x0315b558 hdba: 0x02a40003
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0) flag: 0x2c lock: 2 ckix: 6
ncol: 20 nnew: 19 size: 0
col 1: [128]
41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42
42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41
41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42
42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41
41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42
42 42 42
...
col 19: [128]
41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 30
42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41
41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41 41 41 41 41 42 42 42
42 30 42 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42 42 42 42 41 41 41 41
41 41 41 41 42 42 42 42 42 33 42 42 41 41 41 41 41 41 41 41 42 42 42 42 42
42 42 42
CHANGE #4 MEDIA RECOVERY MARKER CON_ID:0 SCN:0x0000.00000000 SEQ:0 OP:5.20 ENC:0 FLG:0x0000
session number = 1327
serial number = 20241
transaction name =
version 202375680
audit sessionid 931488888
Client Id =
login username = USER1
However, on 12cR2, the records differ – the new column values are no longer recorded, and I assume it’s because the values actually didn’t change. There are still both redo entries there, but the column values are no longer there:
REDO RECORD - Thread:1 RBA: 0x00059b.002cd649.016c LEN: 0x0128 VLD: 0x01 CON_UID: 0
SCN: 0x0000000012f55a0f SUBSCN: 59 06/21/2018 07:39:08
CHANGE #1 CON_ID:0 TYP:0 CLS:18 AFN:4 DBA:0x0101a3f6 OBJ:4294967295 SCN:0x0000000012f55a0f SEQ:11 OP:5.1 ENC:0 RBL:0 FLG:0x0000
ktudb redo: siz: 84 spc: 7290 flg: 0x0022 seq: 0x374e rec: 0x0b
xid: 0x0001.000.000243b0
ktubu redo: slt: 0 rci: 10 opc: 11.1 objn: 100475 objd: 100477 tsn: 7
Undo type: Regular undo Undo type: Last buffer split: No
Tablespace Undo: No
0x00000000
KDO undo record:
KTB Redo
op: 0x04 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: L itl: xid: 0x0008.000.0002aff4 uba: 0x0101aed8.30cb.4b
flg: C--- lkc: 0 scn: 0x0000000012f557ff
KDO Op code: LKR row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x006ee8f5 hdba: 0x00500003
itli: 1 ispac: 0 maxfr: 4858
tabn: 0 slot: 0 to: 0
CHANGE #2 CON_ID:0 TYP:2 CLS:1 AFN:8 DBA:0x006ee8f5 OBJ:100477 SCN:0x0000000012f559d5 SEQ:1 OP:11.4 ENC:0 RBL:0 FLG:0x0000
KTB Redo
op: 0x11 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0001.000.000243b0 uba: 0x0101a3f6.374e.0b
Block cleanout record, scn: 0x0000000012f55a0f ver: 0x01 opt: 0x02 bigscn: Y compact: Y spare: 00000000, entries follow...
itli: 2 flg: (opt=2 whr=1) scn: 0x0000000012f559d5
KDO Op code: LKR row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x006ee8f5 hdba: 0x00500003
itli: 1 ispac: 0 maxfr: 4858
tabn: 0 slot: 0 to: 1
I haven’t done a very thorough testing, so there may be a situation when it works and when it doesn’t.
No comments