And a recycle bin too?
A few words about the downside of Oracle Database LGWR optimizations
After returning home from the SOUG event in Bern, I kept thinking about the knowledge I gained from Christoph Lutz’s presentation about the internals of the Oracle Database LGWR process. Christoph’s presentation, delivered not just very well, but brilliantly, with a fire of knowledge and a sparkle in his eyes, confirmed my old postulate that the Oracle database is always about optimizing everything to achieve maximum system efficiency.
As usual, I immersed myself in work and, while enhancing the code daily to reduce the number of allocations in my CDC solution, I ran a load test on fresh data and suddenly got 32 times
The transaction with XID='0x0036.00c.00000000' starts with with the record with PARTIAL ROLLBACK flag set to true!
These 32 redo records have only three sizes: 0x0644, 0x07b8, and 0x07c0 bytes, all representing a pair of OP:11.5 and OP:5.6, i.e., a partial rollback.
30 Redo records of size 0x07b8 and 0x07c0 bytes belong to object #174043 - OE_ORDER_LINES_ALL
REDO RECORD - Thread:1 RBA: 0x0045e1.00256d48.0138 LEN: 0x07c0 VLD: 0x01 CON_UID: 1372444423
SCN: 0x0000058e6985723e SUBSCN: 41
CHANGE #1 CON_ID:3 TYP:0 CLS:1 AFN:92 DBA:0x1718439d OBJ:174043 SCN:0x0000058e6984b66d SEQ:1 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: 0x1540266b.721a.0e
KDO Op code: URP row dependencies Disabled
xtype: XR flags: 0x00000000 bdba: 0x1718439d hdba: 0x08c4d432
itli: 7 ispac: 0 maxfr: 2429
tabn: 0 slot: 18(0x12) flag: 0x04 lock: 7 ckix: 42
ncol: 255 nnew: 5 size: -11
col 53: [ 7] 78 7e 03 0d 0a 3b 27
col 54: [ 4] c3 03 25 02
col 55: [ 6] c5 02 33 56 10 60
col 158: [ 6] 42 4f 4f 4b 45 44
col 193: [ 2] c1 06
CHANGE #2 CON_ID:3 TYP:0 CLS:124 AFN:85 DBA:0x1540266c OBJ:4294967295 SCN:0x0000058e6985723e SEQ:40 OP:5.6 ENC:0 RBL:0 FLG:0x0010
ktubu redo: slt: 12 wrp: 41865 flg: 0x0010 prev dba: 0x00000000 rci: 6 opc: 11.1 [objn: 174043 objd: 174043 tsn: 14]
[Undo type ] Regular undo [User undo done ] Yes [Last buffer split] No
[Temp object] No [Tablespace Undo ] No [User only ] No
ktuxvoff: 0x12e0 ktuxvflg: 0x0004
and 2 redo records of size 0x0644 belong to object 174032 - OE_ORDER_HEADERS_ALL
REDO RECORD - Thread:1 RBA: 0x0045e1.00257017.0054 LEN: 0x0644 VLD: 0x01 CON_UID: 1372444423
SCN: 0x0000058e69857242 SUBSCN: 850
CHANGE #1 CON_ID:3 TYP:0 CLS:1 AFN:56 DBA:0x0aef4f0e OBJ:174032 SCN:0x0000058e6984b66b SEQ:1 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: 0x1540263b.721a.2a
KDO Op code: URP row dependencies Disabled
xtype: XR flags: 0x00000000 bdba: 0x0aef4f0e hdba: 0x08c4d382
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 0(0x0) flag: 0x2c lock: 2 ckix: 0
ncol: 180 nnew: 7 size: -7
col 48: [ 3] c2 34 28
col 49: [ 7] 78 7e 03 0c 0e 01 2a
col 50: [ 6] c5 02 33 52 5d 23
col 94: [ 1] 4e
col 135: [ 7] 45 4e 54 45 52 45 44
col 140: *NULL*
col 141: [ 2] c1 02
CHANGE #2 CON_ID:3 TYP:0 CLS:124 AFN:85 DBA:0x1540263c OBJ:4294967295 SCN:0x0000058e69857242 SEQ:12 OP:5.6 ENC:0 RBL:0 FLG:0x0050
ktubu redo: slt: 12 wrp: 41865 flg: 0x0050 prev dba: 0x00000000 rci: 15 opc: 11.1 [objn: 174032 objd: 174032 tsn: 14]
[Undo type ] Regular undo [User undo done ] Yes [Last buffer split] No
[Temp object] No [Tablespace Undo ] No [User only ] Yes
ktuxvoff: 0x1450 ktuxvflg: 0x0244
Interestingly, these tables are directly related to the improvements in Oracle PL/SQL made for Oracle Database 9i, such as native compilation and other improvements of DIANA (Distributed Intermediate Annotated Notation for Ada)
LogMiner query for any data related to OE_ORDER_LINES_ALL
select SCN, TIMESTAMP, OPERATION_CODE, ROLLBACK, XID, RS_ID, SSN, CSF, ROW_ID, DATA_OBJ#, DATA_OBJD#, SQL_REDO
from V$LOGMNR_CONTENTS
where XIDUSN=54 and XIDSLT=12 and (OPERATION_CODE in (7, 36) or DATA_OBJ#=174043);
does not return any rows.
LogMiner query for any data related to OE_ORDER_HEADERS_ALL
select SCN, TIMESTAMP, OPERATION_CODE, ROLLBACK, XID, RS_ID, SSN, CSF, ROW_ID, DATA_OBJ#, DATA_OBJD#, SQL_REDO
from V$LOGMNR_CONTENTS
where XIDUSN=54 and XIDSLT=12 and (OPERATION_CODE in (7, 36) or DATA_OBJ#=174032);
returns two rows, but they have an SCN in the future relative to my two “garbage” redo records - and this is again a partial rollback in the absence of any information that a change was actually made to the table.
Another interesting detail is the FB supplemental data flag:
For all redo records related to OE_ORDER_LINES_ALL, it is very strange.
-C---L--
for two redo records related to OE_ORDER_HEADERS_ALL, it has some sense
---DFL--
It also seems to me that this case is similar to another test case in which LogMiner misrepresent data - unpairedRedoRecords
And it doesn’t seem at all and I’m sure that this garbage in the redo log file is the downside of LGWR optimization and at the very least I should add to my utility that extends the “ALTER SYSTEM DUMP LOGFILE” command the ability to search for such garbage records with cross-checking them in LogMiner
Feel free to contact me if you have any questions or if you would like to connect with me on LinkedIn - https://www.linkedin.com/in/averemee/