Oracle Scratchpad

January 18, 2019

DML Tablescans

Filed under: deadlocks,Infrastructure,Locks,Oracle,Parallel Execution,Performance — Jonathan Lewis @ 1:25 pm GMT Jan 18,2019

This note is a follow-up to a recent comment a blog note about Row Migration:

So I wonder what is the difference between the two, parallel dml and serial dml with parallel scan, which makes them behave differently while working with migrated rows. Why might the strategy of serial dml with parallel scan case not work in parallel dml case? I am going to make a service request to get some clarifications but maybe I miss something obvious?

The comment also referenced a couple of MoS notes:

  • Bug 17264297 “Serial DML with Parallel scan performs single block reads during full table scan when table has chained rows in 11.2”
  • Doc ID 1514011.1 “Performance decrease for parallel DML on compressed tables or regular tables after 11.2 Upgrade

The latter document included a comment to the effect that 11.2 uses a “Head Piece Scan” while 11.1 uses a “First Piece scan”, which is a rather helpful comment. Conveniently the blog note itself referenced an earlier note on the potential for differentiating between migrated and chained rows through a “flag” byte associated with each row piece. The flag byte has an H bit for the row head piece, an F bit for the row first piece, and L bit for the row last piece and {no bits set} for a row piece in the middle of a chained row.

Side note: A “typical” simple row will be a single row-piece with the H, F and L bits all set; a simple migrated row will start with an “empty” row-piece in one block with the H bit set and a pointer (nrid – next rowid) to a row in another block that will have the F and L bits set and a pointer (hrid – head rowid) back to the head piece. A chained row could start with a row piece holding a few columns and the H and F bits set and a pointer to the next row piece which might lead to a long chain of row pieces with no bits set each pointing to the next row piece until you get to a row piece with the L bit set.  Alternatively you might have row which had migrated and chained – which means it could start with an empty row piece with just the H bit and a pointer to the next row piece, then a row piece with the F bit set, a back pointer to the header, and a next pointer to the next row piece, which could lead to a long chain of row pieces with no bits set until you reach a row piece with the L bit set.

Combining the comments about “head piece” and “first piece” scans with the general principles of DML and locking it’s now possible to start makings some guesses about why the Oracle developers might want updates through tablescans to behave differently for serial and parallel tablescans. There are two performance targets to consider:

  • How to minimise random (single block) I/O requests
  • How to minimise the risk of deadlock between PX server processes.

Assume you’re doing a serial tablescan to find rows to update – assume for simplicity that there are no chained rows in the table. When you hit a migrated row (H bit only) you could follow the next rowid pointer (nrid) to find and examine the row. If you find that it’s a row that doesn’t need to be updated you’ve just done a completely redundant single block read; so it makes sense to ignore row pieces which are “H”-only row pieces and do a table scan based on “F” pieces (which will be FL “whole row” pieces thanks to our assumption of no chained rows). If you find a row which is an F row and it needs to be updated then you can do a single block read using the head rowid pointer (hrid) to lock the head row piece then lock the current row piece and update it; you only do the extra single block read for rows that need updates, not for all migrated rows. So this is (I guess) the “First Piece Scan” referenced in Doc ID 1514011.1. (And, conversely, if you scan the table looking only for row pieces with the H flag set this is probably the “Head Piece Scan”).

But there’s a potential problem with this strategy if the update is a parallel update. Imagine parallel server process p000 is scanning the first megabyte of a table and process p001 is scanning the second megabyte using the “first piece” algorithm.  What happens if p001 finds a migrated row (flags = FL) that needs to be updated and follows its head pointer back into a block in the megabyte being scanned by p000?  What if p000 has been busy updating rows in that block and there are no free ITLs for p001 to acquire to lock the head row piece? You have the potential for an indefinite deadlock.

On the other hand, if the scan is using the “head piece” algorithm p000 would have found the migrated row’s head piece and followed the next rowid pointer into a block in the megabyte being scanned by p001. If the row needs to be updated p000 can lock the head piece and the migrated piece.

At this point you might think that the two situations are symmetrical – aren’t you just as likely to get a deadlock because p000 now wants an ITL entry in a block that p001 might have been updating? Statistically the answer is “probably not”. When you do lots of updates it is possible for many rows to migrate OUT of a block; it is much less likely that you will see many rows migrate INTO a specific block. This means that in a parallel environment you’re more likely to see several PX servers all trying to acquire ITL entries in the same originating block than you are  to see several PX servers trying to acquire ITL entries in the same destination block. There’s also the feature that when a row (piece) migrates into a block Oracle adds an entry to the ITL list if the number of inwards migrated pieces is more than the current number of ITL entries.

Conclusion

It’s all guesswork of course, but I’d say that for a serial update by tablescan Oracle uses the “first piece scan” to minimise random I/O requests while for a parallel update by tablescan Oracle uses the “head piece scan” to minimise the risk of deadlocks – even though this is likely to increase the number of random (single block) reads.

Finally (to avoid ambiguity) if you’ve done an update which does a parallel tablescan but a serial update (by passing rowids to the query co-ordinator) then I’d hope that Oracle would use the “first piece scan” for the parallel tablescan because there’s no risk of deadlock when only the query co-ordinator is the only process doing the locking and updating, which makes it safe to use the minimum I/O strategy. (And a paralle query with serial update happens quite frequently because people forget to enable parallel dml.)

Footnote

While messing around to see what happened with updates and rows that were both migrated and chained I ran the following script to create one nasty row. so that I could dump a few table blocks to check for ITLs, pointers, and locks. The aim was to get a row with a head-only piece (“H” bit), an F-only piece, a piece with no bits set, then an L-only piece. With an 8KB block size and 4,000 byte maximum for varchar2() this is what I did:


rem
rem     Script:         migrated_lock.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jan 2019
rem     Purpose:
rem
rem     Last tested
rem             18.3.0.0
rem

create table t1 (
        n1 number,
        l1 varchar2(4000),
        s1 varchar2(200),
        l2 varchar2(4000),
        s2 varchar2(200),
        l3 varchar2(4000),
        s3 varchar2(200)
);

insert into t1 (n1,l1,s1) values(0,rpad('X',4000,'X'),rpad('X',200,'X'));
commit;

insert into t1 (n1,l1) values(1,null);
commit;

update t1 set
        l1 = rpad('A',4000),
        s1 = rpad('A',200),
        l2 = rpad('B',4000),
        s2 = rpad('B',200),
        l3 = rpad('C',4000),
        s3 = rpad('C',200)
where
        n1 = 1
;

commit;

execute dbms_stats.gather_table_stats(user,'t1');

update t1 set
        s1 = lower(s1),
        s2 = lower(s2),
        s3 = lower(s3)
where
        n1 = 1
;

alter system flush buffer_cache;

select
        dbms_rowid.rowid_relative_fno(rowid)    rel_file_no,
        dbms_rowid.rowid_block_number(rowid)    block_no,
        count(*)                                rows_starting_in_block
from
        t1
group by
        dbms_rowid.rowid_relative_fno(rowid),
        dbms_rowid.rowid_block_number(rowid)
order by
        dbms_rowid.rowid_relative_fno(rowid),
        dbms_rowid.rowid_block_number(rowid)
;

The query with all the calls to dbms_rowid gave me the file and block number of the row I was interested in, so I dumped the block, then read the trace file to find the next block in the chain, and so on. The first block held just the head piece, the second block held the n1 and l1 columns (which didn’t get modified by the update), the third block held the s1 and l2 columns, the last block held the s2, l3 and s3 columns. I had been expecting to see the split as (head-piece(, (n1, l1, s1), (l2, s2), (l3, s3) – but as it turned out the unexpected split was a bonus.

Here are extracts from each of the blocks (in the order they appeared in the chain), showing the ITL information and the “row overhead” information. If you scan through the list you’ll see that three of the 4 blocks have an ITL entry for transaction id (xid) of 8.1e.df3, using three consecutive undo records in undo block 0x0100043d. My update has locked 3 of the 4 rowpieces – the header and the two that have changed. It didn’t need to “lock” the piece that didn’t change. (This little detail was the bonus of the unexpected split.)


Block 184
---------
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.00b.00000ee1  0x01000bc0.036a.36  C---    0  scn  0x00000000005beb39
0x02   0x0008.01e.00000df3  0x0100043d.0356.2e  ----    1  fsc 0x0000.00000000

...

tab 0, row 1, @0xf18
tl: 9 fb: --H----- lb: 0x2  cc: 0
nrid:  0x00800089.0



Block 137       (columns n1, l1 - DID NOT CHANGE so no ITL entry acquired)
---------       (the lock byte relates to the previous, not cleaned, update) 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.00b.00000ee1  0x01000bc0.036a.35  --U-    1  fsc 0x0000.005beb39
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000

...

tab 0, row 0, @0xfcb
tl: 4021 fb: ----F--- lb: 0x1  cc: 2
hrid: 0x008000b8.1
nrid:  0x00800085.0



Block 133 (columns s1, l2)
--------------------------
Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.00b.00000ee1  0x01000bc0.036a.34  C---    0  scn  0x00000000005beb39
0x02   0x0008.01e.00000df3  0x0100043d.0356.2f  ----    1  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000

...

tab 0, row 0, @0xf0b
tl: 4213 fb: -------- lb: 0x2  cc: 2
nrid:  0x008000bc.0



Block 188 (columns s2, l3, s3)
------------------------------
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000a.00b.00000ee1  0x01000bc0.036a.33  C---    0  scn  0x00000000005beb39
0x02   0x0008.01e.00000df3  0x0100043d.0356.30  ----    1  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000

...

tab 0, row 0, @0xe48
tl: 4408 fb: -----L-- lb: 0x2  cc: 3

Note, by the way, how there are nrid (next rowid) entries pointing forward in every row piece (except the last), but it’s only the “F” (First) row-piece has the hrid (head rowid) pointer pointing backwards.

 

December 3, 2018

Row Migration

Filed under: Infrastructure,Oracle — Jonathan Lewis @ 4:27 pm GMT Dec 3,2018

There’s a little detail of row migration that’s been bugging me for a long time – and I’ve finally found a comment on MoS explaining why it happens. Before saying anything, though, else I’m going to give you a little script (that I’ve run on 12.2.0.1 with an 8KB block size in a tablespace using [corrected ASSM]  manual (freelist) space management and system allocated extents) to demonstrate the anomaly.


rem
rem     Script:         migration_itl.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2018
rem     Purpose:
rem
rem     Last tested
rem             12.2.0.1
rem     Notes
rem     Under ASSM we can get 733 rows in the block,
rem     using freelist management it goes up to 734
rem

create table t1 (v1 varchar2(4000))
segment creation immediate
tablespace test_8k
pctfree 0
;

insert into t1
select  null from dual connect by level <= 734 -- > comment to avoid wordpress format issue
;

commit;

spool migration_itl.lst

column rel_file_no new_value m_file
column block_no    new_value m_block

select 
        dbms_rowid.rowid_relative_fno(rowid)    rel_file_no, 
        dbms_rowid.rowid_block_number(rowid)    block_no,
        count(*)                                rows_starting_in_block
from 
        t1
group by 
        dbms_rowid.rowid_relative_fno(rowid), 
        dbms_rowid.rowid_block_number(rowid) 
order by 
        dbms_rowid.rowid_relative_fno(rowid), 
        dbms_rowid.rowid_block_number(rowid)
;

update t1 set v1 = rpad('x',10);
commit;

alter system flush buffer_cache;

alter system dump datafile &m_file block &m_block;

column tracefile new_value m_tracefile

select
        tracefile 
from 
        v$process where addr = (
                select paddr from v$session where sid = (
                        select sid from v$mystat where rownum = 1
                )
        )
;

-- host grep nrid &m_tracefile

spool off

The script creates a single column table with pctfree set to zero, then populates it with 734 rows where every row has a null for its single column. The query using the calls to the dbms_rowid package will show you that all 734 rows are in the same block. In fact the block will be full (leaving a handful of bytes of free space) because even though each row will require only 5 bytes (2 bytes row directory entry, 3 bytes row overhead, no bytes for data) Oracle’s arithmetic will allow for the 11 bytes that is the minimum needed for a row that has migrated – the extra 6 bytes being the pointer to where the migrated row now lives. So 734 rows * 11 bytes = 8078, leaving 4 bytes free space with 110 bytes block and transaction layer overhead.

After populating and reporting the table the script then updates every row to grow it by a few bytes, and since there’s no free space every row will migrate to a new location. By dumping the block (flushing the buffer cache first) I can check where each row has migrated to. (If you’re running a UNIX flavour and have access to the trace directory then the commented grep command will give you what you want to see.) Here’s a small extract from the dump on a recent run:

nrid:  0x05c00082.0
nrid:  0x05c00082.1
nrid:  0x05c00082.2
nrid:  0x05c00082.3
...
nrid:  0x05c00082.a4
nrid:  0x05c00082.a5
nrid:  0x05c00082.a6
nrid:  0x05c00083.0
nrid:  0x05c00083.1
nrid:  0x05c00083.2
nrid:  0x05c00083.3
...
nrid:  0x05c00085.a4
nrid:  0x05c00085.a5
nrid:  0x05c00085.a6
nrid:  0x05c00086.0
nrid:  0x05c00086.1
nrid:  0x05c00086.2
...
nrid:  0x05c00086.3e
nrid:  0x05c00086.3f
nrid:  0x05c00086.40
nrid:  0x05c00086.41

My 734 rows have migrated to fill the next four blocks (23,130) to (23,133) of the table and taken up some of the space in the one after that (23,134). The first four blocks have used up row directory entries 0x00 to oxa6 (0 to 166), and the last block has used up row directory entries 0x00 to 0x41 (0 to 65) – giving us the expected total: 167 * 4 + 66 = 734 rows. Let’s dump one of the full blocks – and extract the interesting bits:

alter system dump datafile 23 block 130;
Block header dump:  0x05c00082
 Object id on Block? Y
 seg/obj: 0x1ba1e  csc:  0x0000000001e0aff3  itc: 169  flg: -  typ: 1 - DATA
     fsl: 0  fnx: 0x0 ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0006.00f.000042c9  0x0240242d.08f3.14  --U-  167  fsc 0x0000.01e0affb
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0x04   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0x05   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0x06   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
...
0xa6   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0xa7   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0xa8   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000
0xa9   0x0000.000.00000000  0x00000000.0000.00  C---    0  scn  0x0000000000000000

nrow=167
frre=-1
fsbo=0x160
fseo=0x2ec
avsp=0x18c
tosp=0x18c

tab 0, row 0, @0xfe4
tl: 20 fb: ----FL-- lb: 0x1  cc: 1
hrid: 0x05c00081.0
col  0: [10]  78 20 20 20 20 20 20 20 20 20
tab 0, row 1, @0xfd0
tl: 20 fb: ----FL-- lb: 0x1  cc: 1
hrid: 0x05c00081.1

This block has 169 (0xa9) ITL entries – that’s one for each row migrated into the block (nrow = 167) plus a couple spare. The block still has some free space (avsp = tosp = 0x18c: available space = total space = 396 bytes), but it can’t be used for any more incoming migration because Oracle is unable to create any more ITL entries – it’s reached the ITL limit for 8KB blocks.

So finally we come to the question that’s been bugging me for years – why does Oracle want an extra ITL slot for every row that has migrated into a block? The answer appeared in this sentence from MoS Doc ID: 2420831.1: Errors Noted in 12.2 and Above During DML on Compressed Tables”

“It is a requirement during processing of parallel transactions that each data block row that does not have a header have a block ITL available.”

Rows that have migrated into a block do not have a row header – check the flag byte (fb) for the two rows I’ve listed, it’s: “—-FL–“ , there is no ‘H’ for header. We have the First and Last row pieces of the row in this block and that’s it. So my original “why” question now becomes “What’s the significance of parallel DML?”

Imagine the general case where we have multiple processes updating rows at random from multiple blocks, and many different processes forced rows to migrate at the same time into the same block. The next parallel DML statement would dispatch multiple parallel execution slaves, which would all be locking rows in their own separate block ranges – but multiple slaves could find that they wanted to lock rows which had all migrated into the same block – so every slave MUST be able to get an ITL entry in that block at the same time; for example, if we have 8 rows that had migrated into a specific block from 8 different places, and 8 parallel execution slaves each followed a pointer from the region they were scanning to update a row that had migrated into this particular block then all 8 slaves would need an ITL entry in the block (and if there were a ninth slave scanning this region of the table we’d need a 9th ITL entry). If we didn’t have enough ITL entries in the block for every single migrated row to be locked by a different process at the same time then (in principle, at least) parallel execution slaves could deadlock each other because they were visiting blocks in a different order to lock the migrated rows. For example:

  1. PQ00 visits and locks a row that migrated to block (23,131)
  2. PQ01 visits and locks a row that migrated to block (23,132)
  3. PQ00 visits and tries to lock a row that migrated to block (23,132) — but if there were no “extra” ITL slots available, it would wait
  4. PQ01 visits and tries to lock a row that migrated to block (23,131) — but there were no “extra” ITL slots available so it would wait, and we’d be in a deadlock.

Oracle’s solution to this threat: when migrating a row to a block add a new ITL if the number of migrated rows exceeds the number of ITL slots + 2 (the presence of the +2 is a working hypothesis, it might be “+initrans of table”).

Footnote 1

The note was about problems with compression for OLTP, but the underlying message was about 4 Oracle errors of type ORA-00600 and ORA-00700, which report the discovery and potential threat of blocks where the number of ITL entries isn’t large enough compared to the number of inward migrated rows. Specifically:

  • ORA-00600 [PITL1]
  • ORA-00600 [kdt_bseg_srch_cbk PITL1]
  • ORA-00700: soft internal error, arguments: [PITL6]
  • ORA-00700: soft internal error, arguments: [kdt_bseg_srch_cbk PITL5]

 

Footnote 2

While drafting the SQL script above, I decide to check to see how many other scripts I had already written about migrated rows and itl slots: there were 12 of the former and 10 of the latter, and reading through the notes I found that one of the scripts (itl_chain.sql),Ac dated December 2002 included the following note:

According to a comment that came from Oracle support via Steve Adams, the reason for the extra ITLs is to avoid a risk of parallel DML causing an internal deadlock.

So it looks like I knew what the ITLs were for about 16 years ago, but managed to forget sometime since then.

 

 

November 27, 2018

Counting Rows

Filed under: Infrastructure,Oracle,Troubleshooting — Jonathan Lewis @ 9:08 pm GMT Nov 27,2018

Here’s another little utility I use from time to time (usually for small tables) to check how many rows there are in each block of the table, and which blocks are used. It doesn’t do anything clever, just call routines in the dbms_rowid package for each rowid in the table:


rem
rem     Rowid_count.sql
rem     Generic code to count rows per block in a table
rem     Ordered by file and block
rem

define m_table = '&1'

spool rowid_count

select 
        dbms_rowid.rowid_relative_fno(rowid)    rel_file_no, 
        dbms_rowid.rowid_block_number(rowid)    block_no,
        count(*)                                rows_starting_in_block
from 
        &m_table        t1
group by 
        dbms_rowid.rowid_relative_fno(rowid), 
        dbms_rowid.rowid_block_number(rowid) 
order by 
        dbms_rowid.rowid_relative_fno(rowid), 
        dbms_rowid.rowid_block_number(rowid)
;


select
        rows_starting_in_block,
        count(*)        blocks
from
        (
        select 
                dbms_rowid.rowid_relative_fno(rowid), 
                dbms_rowid.rowid_block_number(rowid),
                count(*)                                rows_starting_in_block
        from 
                &m_table        t1
        group by 
                dbms_rowid.rowid_relative_fno(rowid), 
                dbms_rowid.rowid_block_number(rowid) 
        )
group by
        rows_starting_in_block
order by
        rows_starting_in_block
;

spool off


And here’s a sample of the output:


REL_FILE_NO   BLOCK_NO ROWS_STARTING_IN_BLOCK
----------- ---------- ----------------------
	 22	   131			  199
	 22	   132			  199
	 22	   133			  199
	 22	   134			  199
	 22	   135			   88
	 22	   138			  111

6 rows selected.


ROWS_STARTING_IN_BLOCK	   BLOCKS
---------------------- ----------
		    88		1
		   111		1
		   199		4

3 rows selected.


Obviously it could take quite a lot of I/O and CPU to run the two queries against a large table – generally I use it when I want to pick a block to dump afterwards.

Dump logfile

Filed under: Infrastructure,Oracle,redo — Jonathan Lewis @ 9:24 am GMT Nov 27,2018

Here’s a little procedure I’ve been using since Oracle 8i to dump the contents of the current log file – I’ve mentioned it several times in the past but never published it, so I’ll be checking for references to it and linking to it.

The code hasn’t changed in a long time, although I did add a query to get the full tracefile name from v$process when that became available. There’s also an (optional) called to dbms_support.my_sid to pick up the SID of the current session that slid into the code when that package became available.


rem
rem     Script:         c_dump_log.sql
rem     Author:         Jonathan Lewis
rem     Dated:          December 2002
rem     Purpose:        Create procedured to dump the current online redo log file.
rem
rem     Last tested
rem             18.3.0.0
rem             12.2.0.1
rem             11.1.0.7
rem             11.2.0.6
rem             10.2.0.5
rem             10.1.0.4
rem              9.2.0.8
rem              8.1.7.4
rem
rem     Notes:
rem     Must be run as a DBA
rem     Very simple minded - no error trapping
rem     

create or replace procedure dump_log
as
        m_log_name      varchar2(255);
        m_process       varchar2(255);
        m_trace_name    varchar2(255);

begin
        select 
                lf.member
        into
                m_log_name
        from
                V$log           lo,
                v$logfile       lf
        where 
                lo.status = 'CURRENT'
        and     lf.group# = lo.group#
        and     rownum = 1
        ;

        execute immediate
        'alter system dump logfile ''' || m_log_name || '''';

        select
                spid
        into
                m_process
        from
                v$session       se,
                v$process       pr
        where
                se.sid = --dbms_support.mysid
                        (select sid from v$mystat where rownum = 1)
        and     pr.addr = se.paddr
        ;

        select
                tracefile
        into
                m_trace_name
        from
                v$session       se,
                v$process       pr
        where
                se.sid = --dbms_support.mysid
                        (select sid from v$mystat where rownum = 1)
        and     pr.addr = se.paddr
        ;

        dbms_output.put_line('Trace file is: ' || m_trace_name);
        dbms_output.put_line('Log file name is: ' || m_log_name);
        dbms_output.put_line('Trace file name includes: ' || m_process);


end;
/

show errors

drop public synonym dump_log;
create public synonym dump_log for dump_log;
grant execute on dump_log to public;

I don’t use the package often but if I want to find out what redo is generated during a test I usually follow the sequence:

  • alter system switch logfile;
  • do the experiment
  • execute dump_log

If you’re running in a PDB there’s an extra step needed as you can’t “switch logfile” inside a PDB so I’ll either do a log file switch before I start the test or (if there are steps in the test script that could generate a lot of log file I don’t want to see) I include a “pause” in the test script and use another session to do the logfile switch – in both cases the second session has to be connected to the CDB.

You will have noticed the creation of the public synonym and granting of the execute privilege to public. In my own sandbox database that’s a convenience – you may want to be a little more protective in your development and test systems.

The “dump logfile” command has a number of options for selective dumping – I have a note in my file commenting on these options, but I haven’t checked if there are any new ones (or changes to existing ones) for a long time:


alter system dump logfile '{filename}'
        scn min {first SCN to dump}
        scn max {last SCN to dump}
        time min {seconds since midnight at the end of 1st Sept 1987}
        time max {see redo_time_calc.sql}
        layer {integer} opcode {integer} e.g.:
                layer 23        Block Written Records
                layer 5         Undo handling in general
                layer 5 opcode 4        Undo Seg header on commit; or rollback;
                layer 9999 opcode 9999  Trick to validate the whole log file structure
        xid {usn} {slot} {sequence}     -- 10g only, may break on IMU redo (see below)
        objno {object_id}               -- 10g only, may break on IMU redo (see below)
        dba min {datafile no} . {blockno} -- with spaces either side of the dot.
        dba max {datafile no} . {blockno} -- with spaces either side of the dot.
        rba min {log file seq no} . {blockno} -- with spaces either side of the dot.
        rba max {log file seq no} . {blockno} -- with spaces either side of the dot..
(The dots in the last four options becomes invalid syntax in 10g).

The introduction to this note references back to a presentation I did in the year 2000, but the closing comment suggests that I probably haven’t checked the list since some time in the 10g timeline.

The reference to redo_time_calc.sql points to the following script, that expresses the time as the number of seconds since Jan 1988, with the unfortunate simplification that Oracle thinks there are 31 days in every month of the year:


rem
rem     Script:         redo_time_calc3.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2012
rem     Purpose:
rem

select 
        86400 * (
                31 *
                        months_between(
                                trunc(sysdate,'MM'),
                                to_date('01-Jan-1988','dd-mon-yyyy')
                        ) +
                sysdate - trunc(sysdate,'MM')
        )       redo_now
from 
        dual
;



select 
        86400 * (
                (sysdate - 10/1440) - trunc((sysdate-10/1440),'MM') + 
                31 * 
                        months_between(
                                trunc((sysdate - 10/1440),'MM'),
                                to_date('01-Jan-1988','dd-mon-yyyy')
                        )
                )               ten_minutes_ago,
        86400 * (
                sysdate - trunc(sysdate,'MM') + 
                31 * 
                        months_between(
                                trunc(sysdate,'MM'),
                                to_date('01-Jan-1988','dd-mon-yyyy')
                        )
                )               redo_now,
        to_char(sysdate,'mm/dd/yyyy hh24:mi:ss')        now
from 
        dual
;

This isn’t a piece of code I use much – the original version (which I published in Oracle Core, p.241) was something I wrote in 2003 and had to adjust by hand each time I used it without realising that I’d got it wrong. Luckily someone pointed out my error and gave me the corrected code a little while after I’d published the book. (It was one of those “why didn’t I think of that” moments – it seemed so obvious after he’d told me the right answer.)

November 13, 2018

Index Splits – 3

Filed under: Indexing,Infrastructure,Oracle,redo — Jonathan Lewis @ 8:06 pm GMT Nov 13,2018

This is stored only for reference, and in case anyone wants to wade through the details. It’s the redo log dump from the 90/10 index leaf block split test from the previous blog posts running on 11.2.0.4 on Linux. The first part is the full block dump, the second part is an extract of the Record and Change vector headings with the embedded opcode (opc:) for the undo records in the redo vectors, and a tiny note of what each change vector is doing.

Full dump


*** 2018-11-02 19:16:45.844
*** SESSION ID:(244.47) 2018-11-02 19:16:45.844
*** CLIENT ID:() 2018-11-02 19:16:45.844
*** SERVICE NAME:(SYS$USERS) 2018-11-02 19:16:45.844
*** MODULE NAME:(MyModule) 2018-11-02 19:16:45.844
*** ACTION NAME:(MyAction) 2018-11-02 19:16:45.844
 
----- begin tree dump
branch: 0x140008b 20971659 (0: nrow: 2, level: 1)
   leaf: 0x140008f 20971663 (-1: nrow: 147 rrow: 147)
   leaf: 0x140008c 20971660 (0: nrow: 145 rrow: 145)
----- end tree dump
----- begin tree dump
branch: 0x140008b 20971659 (0: nrow: 3, level: 1)
   leaf: 0x140008f 20971663 (-1: nrow: 147 rrow: 147)
   leaf: 0x140008c 20971660 (0: nrow: 145 rrow: 145)
   leaf: 0x140008d 20971661 (1: nrow: 1 rrow: 1)
----- end tree dump
Initial buffer sizes: read 1024K, overflow 832K, change 805K
 
DUMP OF REDO FROM FILE '/u01/app/oracle/oradata/TEST/onlinelog/o1_mf_2_bfjt3tsl_.log'
 Opcodes *.*
 RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
 SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
 Times: creation thru eternity
 FILE HEADER:
        Compatibility Vsn = 186647552=0xb200400
        Db ID=2124268929=0x7e9dc581, Db Name='TEST'
        Activation ID=2124229505=0x7e9d2b81
        Control Seq=28320068=0x1b02144, File size=204800=0x32000
        File Number=2, Blksiz=512, File Type=2 LOG
 descrip:"Thread 0001, Seq# 0000012654, SCN 0x0b860d004016-0xffffffffffff"
 thread: 1 nab: 0xffffffff seq: 0x0000316e hws: 0x1 eot: 1 dis: 0
 resetlogs count: 0x313da101 scn: 0x0000.00000001 (1)
 prev resetlogs count: 0x0 scn: 0x0000.00000000
 Low  scn: 0x0b86.0d004016 (12670371643414) 11/02/2018 19:16:45
 Next scn: 0xffff.ffffffff 01/01/1988 00:00:00
 Enabled scn: 0x0000.00000001 (1) 09/14/2013 14:28:50
 Thread closed scn: 0x0b86.0d004016 (12670371643414) 11/02/2018 19:16:45
 Disk cksum: 0xfc42 Calc cksum: 0xfc42
 Terminal recovery stop scn: 0x0000.00000000
 Terminal recovery  01/01/1988 00:00:00
 Most recent redo scn: 0x0000.00000000
 Largest LWN: 0 blocks
 End-of-redo stream : No
 Unprotected mode
 Miscellaneous flags: 0x800000
 Thread internal enable indicator: thr: 0, seq: 0 scn: 0x0000.00000000
 Zero blocks: 0
 Format ID is 2
 redo log key is 16409c48687eb1bbc3e4a4d820a6f7e5
 redo log key flag is d
 Enabled redo threads: 1 
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000002.0010 LEN: 0x0074 VLD: 0x05
SCN: 0x0b86.0d004016 SUBSCN:  1 11/02/2018 19:16:45
(LWN RBA: 0x00316e.00000002.0010 LEN: 0038 NST: 0001 SCN: 0x0b86.0d004016)
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d003f20 SEQ:2 OP:4.1 ENC:0 RBL:0
Block cleanout record, scn:  0x0b86.0d004016 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0b86.0d003f20
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000002.0084 LEN: 0x0144 VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  2 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d003fe6 SEQ:1 OP:5.2 ENC:0 RBL:0
ktudh redo: slt: 0x000d sqn: 0x00009d48 flg: 0x0412 siz: 136 fbi: 0
            uba: 0x00c05593.2254.1d    pxid:  0x0000.000.00000000
CHANGE #2 TYP:0 CLS:76 AFN:3 DBA:0x00c05593 OBJ:4294967295 SCN:0x0b86.0d003fe5 SEQ:2 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 136 spc: 2818 flg: 0x0012 seq: 0x2254 rec: 0x1d
            xid:  0x001e.00d.00009d48  
ktubl redo: slt: 13 rci: 0 opc: 10.21 [objn: 350367 objd: 350367 tsn: 7]
Undo type:  Regular undo        Begin trans    Last buffer split:  No 
Temp Object:  No 
Tablespace Undo:  No 
             0x00000000  prev ctl uba: 0x00c05593.2254.1b 
prev ctl max cmt scn:  0x0b86.0d003da4  prev tx cmt scn:  0x0b86.0d003da5 
txn start scn:  0xffff.ffffffff  logon user: 62  prev brb: 0  prev bcl: 0 BuExt idx: 0 flg2: 0
index general undo (branch) operations
KTB Redo 
op: 0x04  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: L  itl: xid:  0x0019.01d.00009119 uba: 0x00c1702b.1ea1.02
                      flg: CB--    lkc:  0     scn: 0x0b86.0d003e8f
Dump kdige : block dba :0x0140008c, seghdr dba: 0x0140008a
unlock block
(1):  01
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.6 ENC:0 RBL:0
index redo (kdxlok):  lock block, count=2
KTB Redo 
op: 0x01  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: F  xid:  0x001e.00d.00009d48    uba: 0x00c05593.2254.1d
lock itl 1
operation = 0x5, pre-split
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000002.01c8 LEN: 0x20a4 VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  3 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.2 ENC:0 RBL:0
ktudh redo: slt: 0x000d sqn: 0x00000000 flg: 0x000a siz: 8148 fbi: 255
            uba: 0x00c05595.2254.01    pxid:  0x0000.000.00000000
CHANGE #2 TYP:1 CLS:76 AFN:3 DBA:0x00c05595 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 8148 spc: 2680 flg: 0x000a seq: 0x2254 rec: 0x01
            xid:  0x001e.00d.00009d48  
ktubu redo: slt: 13 rci: 0 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
Undo type:  Regular undo       Undo type:  Last buffer split:  No 
Tablespace Undo:  No 
             0x00c05593
index general undo (branch) operations
KTB Redo 
op: 0x05  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: R  itc: 2
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x001e.00d.00009d48  0x00c05593.2254.1d  ----    1  fsc 0x0000.00000000
0x02   0x001d.012.0000a9d7  0x00c04b88.256f.10  C---    0  scn 0x0b86.0d003f20
Dump kdige : block dba :0x0140008c, seghdr dba: 0x0140008a
restore block before image
(8032): 
 00 01 85 02 01 00 00 00 91 00 46 01 5c 01 16 00 00 00 00 00 00 00 00 00 8f
 00 40 01 06 00 00 00 60 1f 00 00 2b 1f f6 1e c1 1e 8c 1e 57 1e 22 1e ed 1d
 b8 1d 83 1d 4e 1d 19 1d e4 1c af 1c 7a 1c 45 1c 10 1c db 1b a6 1b 71 1b 3c
 1b 07 1b d2 1a 9d 1a 68 1a 33 1a fe 19 c9 19 94 19 5f 19 2a 19 f5 18 c0 18
 8b 18 56 18 21 18 ec 17 b7 17 82 17 4d 17 18 17 e3 16 ae 16 79 16 44 16 0f
 16 da 15 a5 15 70 15 3b 15 06 15 d1 14 9c 14 68 14 33 14 fe 13 c9 13 94 13
 5f 13 2a 13 f5 12 c0 12 8b 12 56 12 21 12 ec 11 b7 11 82 11 4d 11 18 11 e3
 10 ae 10 79 10 44 10 0f 10 da 0f a5 0f 70 0f 3b 0f 06 0f d1 0e 9c 0e 67 0e
 32 0e fd 0d c8 0d 93 0d 5e 0d 29 0d f4 0c bf 0c 8a 0c 55 0c 20 0c eb 0b b6
 0b 81 0b 4c 0b 17 0b e2 0a ad 0a 78 0a 43 0a 0e 0a d9 09 a4 09 6f 09 3a 09
 05 09 d0 08 9b 08 66 08 31 08 fc 07 c7 07 92 07 5d 07 28 07 f3 06 be 06 89
 06 54 06 1f 06 ea 05 b5 05 80 05 4b 05 16 05 e1 04 ac 04 77 04 42 04 0d 04
 d8 03 a3 03 6e 03 39 03 04 03 cf 02 9a 02 65 02 30 02 fb 01 c6 01 91 01 5c
 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 01 40 00 85 00 05 03 c2 03 5d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 85 00 04 03 c2 03 5c 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 85 00 03 03 c2 03 5b 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 85 00 02 03 c2 03 5a 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 85 00 01 03 c2 03 59 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 85 00 00 03 c2 03 58
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 46 03
 c2 03 57 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86
 00 45 03 c2 03 56 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 86 00 44 03 c2 03 55 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 86 00 43 03 c2 03 54 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 86 00 42 03 c2 03 53 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 86 00 41 03 c2 03 52 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 40 03 c2 03 51 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 3f 03 c2 03 50 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 3e 03 c2
 03 4f 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00
 3d 03 c2 03 4e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 86 00 3c 03 c2 03 4d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 86 00 3b 03 c2 03 4c 28 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 00 00 01 40 00 86 00 3a 03 c2 03 4b 28 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 00 00 01 40 00 86 00 39 03 c2 03 4a 28 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 38 03 c2 03 49 28 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 37 03 c2 03 48 28 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 36 03 c2 03
 47 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 35
 03 c2 03 46 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00
 86 00 34 03 c2 03 45 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00
 01 40 00 86 00 33 03 c2 03 44 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 86 00 32 03 c2 03 43 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 86 00 31 03 c2 03 42 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 86 00 30 03 c2 03 41 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 2f 03 c2 03 40 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 2e 03 c2 03 3f
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 2d 03
 c2 03 3e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86
 00 2c 03 c2 03 3d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 86 00 2b 03 c2 03 3c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 86 00 2a 03 c2 03 3b 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 86 00 29 03 c2 03 3a 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 86 00 28 03 c2 03 39 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 27 03 c2 03 38 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 26 03 c2 03 37 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 25 03 c2
 03 36 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00
 24 03 c2 03 35 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 86 00 23 03 c2 03 34 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 86 00 22 03 c2 03 33 28 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 00 00 01 40 00 86 00 21 03 c2 03 32 28 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 00 00 01 40 00 86 00 20 03 c2 03 31 28 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 1f 03 c2 03 30 28 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 1e 03 c2 03 2f 28 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 1d 03 c2 03
 2e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 1c
 03 c2 03 2d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00
 86 00 1b 03 c2 03 2c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00
 01 40 00 86 00 1a 03 c2 03 2b 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 86 00 19 03 c2 03 2a 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 86 00 18 03 c2 03 29 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 86 00 17 03 c2 03 28 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 16 03 c2 03 27 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 15 03 c2 03 26
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 14 03
 c2 03 25 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86
 00 13 03 c2 03 24 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 86 00 12 03 c2 03 23 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 86 00 11 03 c2 03 22 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 86 00 10 03 c2 03 21 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 86 00 0f 03 c2 03 20 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 0e 03 c2 03 1f 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 0d 03 c2 03 1e 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 0c 03 c2
 03 1d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00
 0b 03 c2 03 1c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 86 00 0a 03 c2 03 1b 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 86 00 09 03 c2 03 1a 28 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 00 00 01 40 00 86 00 08 03 c2 03 19 28 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 00 00 01 40 00 86 00 07 03 c2 03 18 28 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 06 03 c2 03 17 28 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 05 03 c2 03 16 28 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 04 03 c2 03
 15 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 86 00 03
 03 c2 03 14 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00
 86 00 02 03 c2 03 13 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00
 01 40 00 86 00 01 03 c2 03 12 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 86 00 00 03 c2 03 11 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 84 00 46 03 c2 03 10 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 84 00 45 03 c2 03 0f 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 44 03 c2 03 0e 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 43 03 c2 03 0d
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 42 03
 c2 03 0c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84
 00 41 03 c2 03 0b 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 84 00 40 03 c2 03 0a 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 84 00 3f 03 c2 03 09 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 84 00 3e 03 c2 03 08 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 84 00 3d 03 c2 03 07 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 3c 03 c2 03 06 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 3b 03 c2 03 05 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 3a 03 c2
 03 04 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00
 39 03 c2 03 03 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 84 00 38 03 c2 03 02 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 84 00 37 02 c2 03 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 84 00 36 03 c2 02 64 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 84 00 35 03 c2 02 63 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 84 00 34 03 c2 02 62 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 33 03 c2 02 61 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 32 03 c2 02 60
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 31 03
 c2 02 5f 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84
 00 30 03 c2 02 5e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 84 00 2f 03 c2 02 5d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 84 00 2e 03 c2 02 5c 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 84 00 2d 03 c2 02 5b 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 84 00 2c 03 c2 02 5a 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 2b 03 c2 02 59 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 2a 03 c2 02 58 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 29 03 c2
 02 57 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00
 28 03 c2 02 56 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 84 00 27 03 c2 02 55 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 84 00 26 03 c2 02 54 28 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 00 00 01 40 00 84 00 25 03 c2 02 53 28 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 00 00 01 40 00 84 00 24 03 c2 02 52 28 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 23 03 c2 02 51 28 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 22 03 c2 02 50 28 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 21 03 c2 02
 4f 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 20
 03 c2 02 4e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00
 84 00 1f 03 c2 02 4d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00
 01 40 00 84 00 1e 03 c2 02 4c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 84 00 1d 03 c2 02 4b 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 84 00 1c 03 c2 02 4a 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 00 00 01 40 00 84 00 1b 03 c2 02 49 28 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 1a 03 c2 02 48 28 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 19 03 c2 02 47
 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 18 03
 c2 02 46 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84
 00 17 03 c2 02 45 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01
 40 00 84 00 16 03 c2 02 44 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 00 00 01 40 00 84 00 15 03 c2 02 43 28 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 00 00 01 40 00 84 00 14 03 c2 02 42 28 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 00 00 01 40 00 84 00 13 03 c2 02 41 28 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 12 03 c2 02 40 28 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 11 03 c2 02 3f 28
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 10 03 c2
 02 3e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00
 0f 03 c2 02 3d 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40
 00 84 00 0e 03 c2 02 3c 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00
 00 01 40 00 84 00 0d 03 c2 02 3b 28 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 00 00 01 40 00 84 00 0c 03 c2 02 3a 28 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 00 00 01 40 00 84 00 0b 03 c2 02 39 28 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 0a 03 c2 02 38 28 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 09 03 c2 02 37 28 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 08 03 c2 02
 36 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00 84 00 07
 03 c2 02 35 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00 01 40 00
 84 00 06 03 c2 02 34 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 00 00
 01 40 00 84 00 05 03 c2 02 33 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 00 00 01 40 00 84 00 04 03 c2 02 32 28 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 00 00 01 40 00 84 00 03 03 c2 02 31 28 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:2 OP:10.9 ENC:0 RBL:0
index redo (kdxair): apply xat do to itl 1 (count=2)
KTB Redo 
op: 0x05  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: R  itc: 1
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x001e.00d.00009d48  0x00c05595.2254.01  -B--    1  fsc 0x0000.00000000
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000013.017c LEN: 0x0044 VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  3 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:8 AFN:5 DBA:0x01400088 OBJ:350367 SCN:0x0b86.0d003e8e SEQ:3 OP:13.22 ENC:0 RBL:0
Redo on Level1 Bitmap Block
Redo for state change
Len: 1 Offset: 4 newstate: 140243567116289
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000013.01c0 LEN: 0x01ac VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  4 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:2 OP:5.2 ENC:0 RBL:0
ktudh redo: slt: 0x000d sqn: 0x00000000 flg: 0x000a siz: 120 fbi: 0
            uba: 0x00c05596.2254.01    pxid:  0x0000.000.00000000
CHANGE #2 TYP:1 CLS:76 AFN:3 DBA:0x00c05596 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 120 spc: 0 flg: 0x000a seq: 0x2254 rec: 0x01
            xid:  0x001e.00d.00009d48  
ktubu redo: slt: 13 rci: 0 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
Undo type:  Regular undo       Undo type:  Last buffer split:  No 
Tablespace Undo:  No 
             0x00c05595
index general undo (branch) operations
KTB Redo 
op: 0x05  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: R  itc: 2
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
Dump kdige : block dba :0x0140008d, seghdr dba: 0x0140008a
make leaf block empty
(2):  01 00
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008d OBJ:350367 SCN:0x0b86.0d003e8e SEQ:2 OP:10.8 ENC:0 RBL:0
index redo (kdxlne): (count=4) init header of newly allocated leaf block
KTB Redo 
op: 0x05  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: R  itc: 2
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x001e.00d.00009d48  0x00c05596.2254.01  -B--    0  fsc 0x0000.00000000
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
kdxlnitl = 1
kdxlnnco = 2
kdxlndsz = 6
kdxlncol = 246
kdxlnflg = 0
kdxlnnxt = 0x0
kdxlnprv = 0x140008c
new block has 1 rows
dumping row index
Dump of memory from 0x00007F8D3FC10078 to 0x00007F8D3FC1007C
7F8D3FC10070                   1F5D1F26                   [&.].]    
dumping rows
Dump of memory from 0x00007F8D3FC1007C to 0x00007F8D3FC100B1
7F8D3FC10070                            40010101              [...@]
7F8D3FC10080 06008500 5E03C203 78787828 78787878  [.......^(xxxxxxx]
7F8D3FC10090 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC100B0 30303078                             [x000]            
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000014.017c LEN: 0x0048 VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  4 11/02/2018 19:16:45
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008b OBJ:350367 SCN:0x0b86.0d003e8f SEQ:2 OP:4.1 ENC:0 RBL:0
Block cleanout record, scn:  0x0b86.0d004016 ver: 0x01 opt: 0x02, entries follow...
  itli: 1  flg: 2  scn: 0x0b86.0d003e8f
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000014.01c4 LEN: 0x00e0 VLD: 0x01
SCN: 0x0b86.0d004016 SUBSCN:  5 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:76 AFN:3 DBA:0x00c05596 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:2 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 84 spc: 8028 flg: 0x0022 seq: 0x2254 rec: 0x02
            xid:  0x001e.00d.00009d48  
ktubu redo: slt: 13 rci: 1 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
Undo type:  Regular undo       Undo type:  Last buffer split:  No 
Tablespace Undo:  No 
             0x00000000
index general undo (branch) operations
KTB Redo 
op: 0x04  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: L  itl: xid:  0x0019.01d.00009119 uba: 0x00c17029.1ea1.01
                      flg: CB--    lkc:  0     scn: 0x0b86.0d003e8f
Dump kdige : block dba :0x0140008b, seghdr dba: 0x0140008a
branch block row purge
(4):  01 00 01 00
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008b OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.15 ENC:0 RBL:0
index redo (kdxbin) :  insert branch block row, count=3
KTB Redo 
op: 0x01  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: F  xid:  0x001e.00d.00009d48    uba: 0x00c05596.2254.02
REDO itl: 1 insert into slot 1, child dba 0x140008d
new key : (5):  03 c2 03 5e fe
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000015.00b4 LEN: 0x1fb0 VLD: 0x01
SCN: 0x0b86.0d004017 SUBSCN:  1 11/02/2018 19:16:45
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:3 OP:5.4 ENC:0 RBL:0
ktucm redo: slt: 0x000d sqn: 0x00009d48 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x00c05596.2254.02 ext: 14 spc: 7942 fbi: 0 
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:3 OP:10.8 ENC:0 RBL:0
index redo (kdxlne): (count=4) init leaf block being split
zeroed lock count and free space, kdxlenxt = 0x140008d
new block has 145 rows
dumping row index
Dump of memory from 0x00007F8D3FC10028 to 0x00007F8D3FC1014C
7F8D3FC10020                   00370000 00A5006E          [..7.n...]
7F8D3FC10030 011300DC 0181014A 01EF01B8 025D0226  [....J.......&.].]
7F8D3FC10040 02CB0294 03390302 03A70370 041503DE  [......9.p.......]
7F8D3FC10050 0483044C 04F104BA 055F0528 05CD0596  [L.......(._.....]
7F8D3FC10060 063B0604 06A90672 071706E0 0785074E  [..;.r.......N...]
7F8D3FC10070 07F307BC 0861082A 08CF0898 093D0906  [....*.a.......=.]
7F8D3FC10080 09AB0974 0A1909E2 0A870A50 0AF50ABE  [t.......P.......]
7F8D3FC10090 0B620B2C 0BD00B99 0C3E0C07 0CAC0C75  [,.b.......>.u...]
7F8D3FC100A0 0D1A0CE3 0D880D51 0DF60DBF 0E640E2D  [....Q.......-.d.]
7F8D3FC100B0 0ED20E9B 0F400F09 0FAE0F77 101C0FE5  [......@.w.......]
7F8D3FC100C0 108A1053 10F810C1 1166112F 11D4119D  [S......./.f.....]
7F8D3FC100D0 1242120B 12B01279 131E12E7 138C1355  [..B.y.......U...]
7F8D3FC100E0 13FA13C3 14681431 14D6149F 1544150D  [....1.h.......D.]
7F8D3FC100F0 15B2157B 162015E9 168E1657 16FC16C5  [{..... .W.......]
7F8D3FC10100 176A1733 17D817A1 1846180F 18B4187D  [3.j.......F.}...]
7F8D3FC10110 192218EB 19901959 19FE19C7 1A6C1A35  [..".Y.......5.l.]
7F8D3FC10120 1ADA1AA3 1B481B11 1BB61B7F 1C241BED  [......H.......$.]
7F8D3FC10130 1C921C5B 1D001CC9 1D6E1D37 1DDC1DA5  [[.......7.n.....]
7F8D3FC10140 1E4A1E13 1EB81E81 1F261EEF           [..J.......&.]    
dumping rows
Dump of memory from 0x00007F8D3FC1014C to 0x00007F8D3FC11F50
7F8D3FC10140                            40010000              [...@]
7F8D3FC10150 03008400 3102C203 78787828 78787878  [.......1(xxxxxxx]
7F8D3FC10160 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10180 01000078 00840040 02C20304 78782832  [x...@.......2(xx]
7F8D3FC10190 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC101B0 78787878 00007878 84004001 C2030500  [xxxxxx...@......]
7F8D3FC101C0 78283302 78787878 78787878 78787878  [.3(xxxxxxxxxxxxx]
7F8D3FC101D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC101E0 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC101F0 03060084 283402C2 78787878 78787878  [......4(xxxxxxxx]
7F8D3FC10200 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10220 40010000 07008400 3502C203 78787828  [...@.......5(xxx]
7F8D3FC10230 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10250 78787878 01000078 00840040 02C20308  [xxxxx...@.......]
7F8D3FC10260 78782836 78787878 78787878 78787878  [6(xxxxxxxxxxxxxx]
7F8D3FC10270 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10280 78787878 78787878 00007878 84004001  [xxxxxxxxxx...@..]
7F8D3FC10290 C2030900 78283702 78787878 78787878  [.....7(xxxxxxxxx]
7F8D3FC102A0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC102B0 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC102C0 00400100 030A0084 283802C2 78787878  [..@.......8(xxxx]
7F8D3FC102D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC102F0 78787878 40010000 0B008400 3902C203  [xxxx...@.......9]
7F8D3FC10300 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC10310 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10320 78787878 78787878 01000078 00840040  [xxxxxxxxx...@...]
7F8D3FC10330 02C2030C 7878283A 78787878 78787878  [....:(xxxxxxxxxx]
7F8D3FC10340 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10350 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC10360 84004001 C2030D00 78283B02 78787878  [.@.......;(xxxxx]
7F8D3FC10370 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10390 00787878 00400100 030E0084 283C02C2  [xxx...@.......<(]
7F8D3FC103A0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC103C0 78787878 78787878 40010000 0F008400  [xxxxxxxx...@....]
7F8D3FC103D0 3D02C203 78787828 78787878 78787878  [...=(xxxxxxxxxxx]
7F8D3FC103E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC103F0 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC10400 00840040 02C20310 7878283E 78787878  [@.......>(xxxxxx]
7F8D3FC10410 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10430 00007878 84004001 C2031100 78283F02  [xx...@.......?(x]
7F8D3FC10440 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10460 78787878 00787878 00400100 03120084  [xxxxxxx...@.....]
7F8D3FC10470 284002C2 78787878 78787878 78787878  [..@(xxxxxxxxxxxx]
7F8D3FC10480 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10490 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC104A0 13008400 4102C203 78787828 78787878  [.......A(xxxxxxx]
7F8D3FC104B0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC104D0 01000078 00840040 02C20314 78782842  [x...@.......B(xx]
7F8D3FC104E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10500 78787878 00007878 84004001 C2031500  [xxxxxx...@......]
7F8D3FC10510 78284302 78787878 78787878 78787878  [.C(xxxxxxxxxxxxx]
7F8D3FC10520 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10530 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC10540 03160084 284402C2 78787878 78787878  [......D(xxxxxxxx]
7F8D3FC10550 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10570 40010000 17008400 4502C203 78787828  [...@.......E(xxx]
7F8D3FC10580 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC105A0 78787878 01000078 00840040 02C20318  [xxxxx...@.......]
7F8D3FC105B0 78782846 78787878 78787878 78787878  [F(xxxxxxxxxxxxxx]
7F8D3FC105C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC105D0 78787878 78787878 00007878 84004001  [xxxxxxxxxx...@..]
7F8D3FC105E0 C2031900 78284702 78787878 78787878  [.....G(xxxxxxxxx]
7F8D3FC105F0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10600 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC10610 00400100 031A0084 284802C2 78787878  [..@.......H(xxxx]
7F8D3FC10620 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10640 78787878 40010000 1B008400 4902C203  [xxxx...@.......I]
7F8D3FC10650 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC10660 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10670 78787878 78787878 01000078 00840040  [xxxxxxxxx...@...]
7F8D3FC10680 02C2031C 7878284A 78787878 78787878  [....J(xxxxxxxxxx]
7F8D3FC10690 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC106A0 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC106B0 84004001 C2031D00 78284B02 78787878  [.@.......K(xxxxx]
7F8D3FC106C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC106E0 00787878 00400100 031E0084 284C02C2  [xxx...@.......L(]
7F8D3FC106F0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10710 78787878 78787878 40010000 1F008400  [xxxxxxxx...@....]
7F8D3FC10720 4D02C203 78787828 78787878 78787878  [...M(xxxxxxxxxxx]
7F8D3FC10730 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10740 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC10750 00840040 02C20320 7878284E 78787878  [@... ...N(xxxxxx]
7F8D3FC10760 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10780 00007878 84004001 C2032100 78284F02  [xx...@...!...O(x]
7F8D3FC10790 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC107B0 78787878 00787878 00400100 03220084  [xxxxxxx...@...".]
7F8D3FC107C0 285002C2 78787878 78787878 78787878  [..P(xxxxxxxxxxxx]
7F8D3FC107D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC107E0 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC107F0 23008400 5102C203 78787828 78787878  [...#...Q(xxxxxxx]
7F8D3FC10800 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10820 01000078 00840040 02C20324 78782852  [x...@...$...R(xx]
7F8D3FC10830 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10850 78787878 00007878 84004001 C2032500  [xxxxxx...@...%..]
7F8D3FC10860 78285302 78787878 78787878 78787878  [.S(xxxxxxxxxxxxx]
7F8D3FC10870 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10880 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC10890 03260084 285402C2 78787878 78787878  [..&...T(xxxxxxxx]
7F8D3FC108A0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC108C0 40010000 27008400 5502C203 78787828  [...@...'...U(xxx]
7F8D3FC108D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC108F0 78787878 01000078 00840040 02C20328  [xxxxx...@...(...]
7F8D3FC10900 78782856 78787878 78787878 78787878  [V(xxxxxxxxxxxxxx]
7F8D3FC10910 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10920 78787878 78787878 00007878 84004001  [xxxxxxxxxx...@..]
7F8D3FC10930 C2032900 78285702 78787878 78787878  [.)...W(xxxxxxxxx]
7F8D3FC10940 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10950 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC10960 00400100 032A0084 285802C2 78787878  [..@...*...X(xxxx]
7F8D3FC10970 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10990 78787878 40010000 2B008400 5902C203  [xxxx...@...+...Y]
7F8D3FC109A0 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC109B0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC109C0 78787878 78787878 01000078 00840040  [xxxxxxxxx...@...]
7F8D3FC109D0 02C2032C 7878285A 78787878 78787878  [,...Z(xxxxxxxxxx]
7F8D3FC109E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC109F0 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC10A00 84004001 C2032D00 78285B02 78787878  [.@...-...[(xxxxx]
7F8D3FC10A10 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10A30 00787878 00400100 032E0084 285C02C2  [xxx...@.......\(]
7F8D3FC10A40 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10A60 78787878 78787878 40010000 2F008400  [xxxxxxxx...@.../]
7F8D3FC10A70 5D02C203 78787828 78787878 78787878  [...](xxxxxxxxxxx]
7F8D3FC10A80 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10A90 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC10AA0 00840040 02C20330 7878285E 78787878  [@...0...^(xxxxxx]
7F8D3FC10AB0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10AD0 00007878 84004001 C2033100 78285F02  [xx...@...1..._(x]
7F8D3FC10AE0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10B00 78787878 00787878 00400100 03320084  [xxxxxxx...@...2.]
7F8D3FC10B10 286002C2 78787878 78787878 78787878  [..`(xxxxxxxxxxxx]
7F8D3FC10B20 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10B30 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC10B40 33008400 6102C203 78787828 78787878  [...3...a(xxxxxxx]
7F8D3FC10B50 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10B70 01000078 00840040 02C20334 78782862  [x...@...4...b(xx]
7F8D3FC10B80 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10BA0 78787878 00007878 84004001 C2033500  [xxxxxx...@...5..]
7F8D3FC10BB0 78286302 78787878 78787878 78787878  [.c(xxxxxxxxxxxxx]
7F8D3FC10BC0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10BD0 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC10BE0 03360084 286402C2 78787878 78787878  [..6...d(xxxxxxxx]
7F8D3FC10BF0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10C10 40010000 37008400 2803C202 78787878  [...@...7...(xxxx]
7F8D3FC10C20 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10C40 78787878 40010000 38008400 0203C203  [xxxx...@...8....]
7F8D3FC10C50 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC10C60 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10C70 78787878 78787878 01000078 00840040  [xxxxxxxxx...@...]
7F8D3FC10C80 03C20339 78782803 78787878 78787878  [9....(xxxxxxxxxx]
7F8D3FC10C90 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10CA0 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC10CB0 84004001 C2033A00 78280403 78787878  [.@...:....(xxxxx]
7F8D3FC10CC0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10CE0 00787878 00400100 033B0084 280503C2  [xxx...@...;....(]
7F8D3FC10CF0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10D10 78787878 78787878 40010000 3C008400  [xxxxxxxx...@...<]
7F8D3FC10D20 0603C203 78787828 78787878 78787878  [....(xxxxxxxxxxx]
7F8D3FC10D30 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10D40 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC10D50 00840040 03C2033D 78782807 78787878  [@...=....(xxxxxx]
7F8D3FC10D60 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10D80 00007878 84004001 C2033E00 78280803  [xx...@...>....(x]
7F8D3FC10D90 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10DB0 78787878 00787878 00400100 033F0084  [xxxxxxx...@...?.]
7F8D3FC10DC0 280903C2 78787878 78787878 78787878  [...(xxxxxxxxxxxx]
7F8D3FC10DD0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10DE0 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC10DF0 40008400 0A03C203 78787828 78787878  [...@....(xxxxxxx]
7F8D3FC10E00 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10E20 01000078 00840040 03C20341 7878280B  [x...@...A....(xx]
7F8D3FC10E30 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10E50 78787878 00007878 84004001 C2034200  [xxxxxx...@...B..]
7F8D3FC10E60 78280C03 78787878 78787878 78787878  [..(xxxxxxxxxxxxx]
7F8D3FC10E70 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10E80 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC10E90 03430084 280D03C2 78787878 78787878  [..C....(xxxxxxxx]
7F8D3FC10EA0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10EC0 40010000 44008400 0E03C203 78787828  [...@...D....(xxx]
7F8D3FC10ED0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10EF0 78787878 01000078 00840040 03C20345  [xxxxx...@...E...]
7F8D3FC10F00 7878280F 78787878 78787878 78787878  [.(xxxxxxxxxxxxxx]
7F8D3FC10F10 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10F20 78787878 78787878 00007878 84004001  [xxxxxxxxxx...@..]
7F8D3FC10F30 C2034600 78281003 78787878 78787878  [.F....(xxxxxxxxx]
7F8D3FC10F40 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10F50 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC10F60 00400100 03000086 281103C2 78787878  [..@........(xxxx]
7F8D3FC10F70 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC10F90 78787878 40010000 01008600 1203C203  [xxxx...@........]
7F8D3FC10FA0 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC10FB0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10FC0 78787878 78787878 01000078 00860040  [xxxxxxxxx...@...]
7F8D3FC10FD0 03C20302 78782813 78787878 78787878  [.....(xxxxxxxxxx]
7F8D3FC10FE0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC10FF0 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC11000 86004001 C2030300 78281403 78787878  [.@........(xxxxx]
7F8D3FC11010 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11030 00787878 00400100 03040086 281503C2  [xxx...@........(]
7F8D3FC11040 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11060 78787878 78787878 40010000 05008600  [xxxxxxxx...@....]
7F8D3FC11070 1603C203 78787828 78787878 78787878  [....(xxxxxxxxxxx]
7F8D3FC11080 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11090 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC110A0 00860040 03C20306 78782817 78787878  [@........(xxxxxx]
7F8D3FC110B0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC110D0 00007878 86004001 C2030700 78281803  [xx...@........(x]
7F8D3FC110E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11100 78787878 00787878 00400100 03080086  [xxxxxxx...@.....]
7F8D3FC11110 281903C2 78787878 78787878 78787878  [...(xxxxxxxxxxxx]
7F8D3FC11120 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11130 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC11140 09008600 1A03C203 78787828 78787878  [........(xxxxxxx]
7F8D3FC11150 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11170 01000078 00860040 03C2030A 7878281B  [x...@........(xx]
7F8D3FC11180 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC111A0 78787878 00007878 86004001 C2030B00  [xxxxxx...@......]
7F8D3FC111B0 78281C03 78787878 78787878 78787878  [..(xxxxxxxxxxxxx]
7F8D3FC111C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC111D0 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC111E0 030C0086 281D03C2 78787878 78787878  [.......(xxxxxxxx]
7F8D3FC111F0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11210 40010000 0D008600 1E03C203 78787828  [...@........(xxx]
7F8D3FC11220 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11240 78787878 01000078 00860040 03C2030E  [xxxxx...@.......]
7F8D3FC11250 7878281F 78787878 78787878 78787878  [.(xxxxxxxxxxxxxx]
7F8D3FC11260 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11270 78787878 78787878 00007878 86004001  [xxxxxxxxxx...@..]
7F8D3FC11280 C2030F00 78282003 78787878 78787878  [..... (xxxxxxxxx]
7F8D3FC11290 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC112A0 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC112B0 00400100 03100086 282103C2 78787878  [..@.......!(xxxx]
7F8D3FC112C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC112E0 78787878 40010000 11008600 2203C203  [xxxx...@......."]
7F8D3FC112F0 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC11300 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11310 78787878 78787878 01000078 00860040  [xxxxxxxxx...@...]
7F8D3FC11320 03C20312 78782823 78787878 78787878  [....#(xxxxxxxxxx]
7F8D3FC11330 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11340 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC11350 86004001 C2031300 78282403 78787878  [.@.......$(xxxxx]
7F8D3FC11360 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11380 00787878 00400100 03140086 282503C2  [xxx...@.......%(]
7F8D3FC11390 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC113B0 78787878 78787878 40010000 15008600  [xxxxxxxx...@....]
7F8D3FC113C0 2603C203 78787828 78787878 78787878  [...&(xxxxxxxxxxx]
7F8D3FC113D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC113E0 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC113F0 00860040 03C20316 78782827 78787878  [@.......'(xxxxxx]
7F8D3FC11400 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11420 00007878 86004001 C2031700 78282803  [xx...@.......((x]
7F8D3FC11430 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11450 78787878 00787878 00400100 03180086  [xxxxxxx...@.....]
7F8D3FC11460 282903C2 78787878 78787878 78787878  [..)(xxxxxxxxxxxx]
7F8D3FC11470 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11480 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC11490 19008600 2A03C203 78787828 78787878  [.......*(xxxxxxx]
7F8D3FC114A0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC114C0 01000078 00860040 03C2031A 7878282B  [x...@.......+(xx]
7F8D3FC114D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC114F0 78787878 00007878 86004001 C2031B00  [xxxxxx...@......]
7F8D3FC11500 78282C03 78787878 78787878 78787878  [.,(xxxxxxxxxxxxx]
7F8D3FC11510 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11520 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC11530 031C0086 282D03C2 78787878 78787878  [......-(xxxxxxxx]
7F8D3FC11540 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11560 40010000 1D008600 2E03C203 78787828  [...@........(xxx]
7F8D3FC11570 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11590 78787878 01000078 00860040 03C2031E  [xxxxx...@.......]
7F8D3FC115A0 7878282F 78787878 78787878 78787878  [/(xxxxxxxxxxxxxx]
7F8D3FC115B0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC115C0 78787878 78787878 00007878 86004001  [xxxxxxxxxx...@..]
7F8D3FC115D0 C2031F00 78283003 78787878 78787878  [.....0(xxxxxxxxx]
7F8D3FC115E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC115F0 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC11600 00400100 03200086 283103C2 78787878  [..@... ...1(xxxx]
7F8D3FC11610 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11630 78787878 40010000 21008600 3203C203  [xxxx...@...!...2]
7F8D3FC11640 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC11650 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11660 78787878 78787878 01000078 00860040  [xxxxxxxxx...@...]
7F8D3FC11670 03C20322 78782833 78787878 78787878  ["...3(xxxxxxxxxx]
7F8D3FC11680 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11690 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC116A0 86004001 C2032300 78283403 78787878  [.@...#...4(xxxxx]
7F8D3FC116B0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC116D0 00787878 00400100 03240086 283503C2  [xxx...@...$...5(]
7F8D3FC116E0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11700 78787878 78787878 40010000 25008600  [xxxxxxxx...@...%]
7F8D3FC11710 3603C203 78787828 78787878 78787878  [...6(xxxxxxxxxxx]
7F8D3FC11720 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11730 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC11740 00860040 03C20326 78782837 78787878  [@...&...7(xxxxxx]
7F8D3FC11750 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11770 00007878 86004001 C2032700 78283803  [xx...@...'...8(x]
7F8D3FC11780 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC117A0 78787878 00787878 00400100 03280086  [xxxxxxx...@...(.]
7F8D3FC117B0 283903C2 78787878 78787878 78787878  [..9(xxxxxxxxxxxx]
7F8D3FC117C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC117D0 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC117E0 29008600 3A03C203 78787828 78787878  [...)...:(xxxxxxx]
7F8D3FC117F0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11810 01000078 00860040 03C2032A 7878283B  [x...@...*...;(xx]
7F8D3FC11820 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11840 78787878 00007878 86004001 C2032B00  [xxxxxx...@...+..]
7F8D3FC11850 78283C03 78787878 78787878 78787878  [.<(xxxxxxxxxxxxx]
7F8D3FC11860 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11870 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC11880 032C0086 283D03C2 78787878 78787878  [..,...=(xxxxxxxx]
7F8D3FC11890 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC118B0 40010000 2D008600 3E03C203 78787828  [...@...-...>(xxx]
7F8D3FC118C0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC118E0 78787878 01000078 00860040 03C2032E  [xxxxx...@.......]
7F8D3FC118F0 7878283F 78787878 78787878 78787878  [?(xxxxxxxxxxxxxx]
7F8D3FC11900 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11910 78787878 78787878 00007878 86004001  [xxxxxxxxxx...@..]
7F8D3FC11920 C2032F00 78284003 78787878 78787878  [./...@(xxxxxxxxx]
7F8D3FC11930 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11940 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC11950 00400100 03300086 284103C2 78787878  [..@...0...A(xxxx]
7F8D3FC11960 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11980 78787878 40010000 31008600 4203C203  [xxxx...@...1...B]
7F8D3FC11990 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC119A0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC119B0 78787878 78787878 01000078 00860040  [xxxxxxxxx...@...]
7F8D3FC119C0 03C20332 78782843 78787878 78787878  [2...C(xxxxxxxxxx]
7F8D3FC119D0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC119E0 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC119F0 86004001 C2033300 78284403 78787878  [.@...3...D(xxxxx]
7F8D3FC11A00 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11A20 00787878 00400100 03340086 284503C2  [xxx...@...4...E(]
7F8D3FC11A30 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11A50 78787878 78787878 40010000 35008600  [xxxxxxxx...@...5]
7F8D3FC11A60 4603C203 78787828 78787878 78787878  [...F(xxxxxxxxxxx]
7F8D3FC11A70 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11A80 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC11A90 00860040 03C20336 78782847 78787878  [@...6...G(xxxxxx]
7F8D3FC11AA0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11AC0 00007878 86004001 C2033700 78284803  [xx...@...7...H(x]
7F8D3FC11AD0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11AF0 78787878 00787878 00400100 03380086  [xxxxxxx...@...8.]
7F8D3FC11B00 284903C2 78787878 78787878 78787878  [..I(xxxxxxxxxxxx]
7F8D3FC11B10 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11B20 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC11B30 39008600 4A03C203 78787828 78787878  [...9...J(xxxxxxx]
7F8D3FC11B40 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11B60 01000078 00860040 03C2033A 7878284B  [x...@...:...K(xx]
7F8D3FC11B70 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11B90 78787878 00007878 86004001 C2033B00  [xxxxxx...@...;..]
7F8D3FC11BA0 78284C03 78787878 78787878 78787878  [.L(xxxxxxxxxxxxx]
7F8D3FC11BB0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11BC0 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC11BD0 033C0086 284D03C2 78787878 78787878  [..<...M(xxxxxxxx]
7F8D3FC11BE0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11C00 40010000 3D008600 4E03C203 78787828  [...@...=...N(xxx]
7F8D3FC11C10 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11C30 78787878 01000078 00860040 03C2033E  [xxxxx...@...>...]
7F8D3FC11C40 7878284F 78787878 78787878 78787878  [O(xxxxxxxxxxxxxx]
7F8D3FC11C50 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11C60 78787878 78787878 00007878 86004001  [xxxxxxxxxx...@..]
7F8D3FC11C70 C2033F00 78285003 78787878 78787878  [.?...P(xxxxxxxxx]
7F8D3FC11C80 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11C90 78787878 78787878 78787878 00787878  [xxxxxxxxxxxxxxx.]
7F8D3FC11CA0 00400100 03400086 285103C2 78787878  [..@...@...Q(xxxx]
7F8D3FC11CB0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11CD0 78787878 40010000 41008600 5203C203  [xxxx...@...A...R]
7F8D3FC11CE0 78787828 78787878 78787878 78787878  [(xxxxxxxxxxxxxxx]
7F8D3FC11CF0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11D00 78787878 78787878 01000078 00860040  [xxxxxxxxx...@...]
7F8D3FC11D10 03C20342 78782853 78787878 78787878  [B...S(xxxxxxxxxx]
7F8D3FC11D20 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11D30 78787878 78787878 78787878 00007878  [xxxxxxxxxxxxxx..]
7F8D3FC11D40 86004001 C2034300 78285403 78787878  [.@...C...T(xxxxx]
7F8D3FC11D50 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11D70 00787878 00400100 03440086 285503C2  [xxx...@...D...U(]
7F8D3FC11D80 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11DA0 78787878 78787878 40010000 45008600  [xxxxxxxx...@...E]
7F8D3FC11DB0 5603C203 78787828 78787878 78787878  [...V(xxxxxxxxxxx]
7F8D3FC11DC0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11DD0 78787878 78787878 78787878 01000078  [xxxxxxxxxxxxx...]
7F8D3FC11DE0 00860040 03C20346 78782857 78787878  [@...F...W(xxxxxx]
7F8D3FC11DF0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11E10 00007878 85004001 C2030000 78285803  [xx...@.......X(x]
7F8D3FC11E20 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11E40 78787878 00787878 00400100 03010085  [xxxxxxx...@.....]
7F8D3FC11E50 285903C2 78787878 78787878 78787878  [..Y(xxxxxxxxxxxx]
7F8D3FC11E60 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11E70 78787878 78787878 78787878 40010000  [xxxxxxxxxxxx...@]
7F8D3FC11E80 02008500 5A03C203 78787828 78787878  [.......Z(xxxxxxx]
7F8D3FC11E90 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11EB0 01000078 00850040 03C20303 7878285B  [x...@.......[(xx]
7F8D3FC11EC0 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
        Repeat 1 times
7F8D3FC11EE0 78787878 00007878 85004001 C2030400  [xxxxxx...@......]
7F8D3FC11EF0 78285C03 78787878 78787878 78787878  [.\(xxxxxxxxxxxxx]
7F8D3FC11F00 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
7F8D3FC11F10 78787878 78787878 00787878 00400100  [xxxxxxxxxxx...@.]
7F8D3FC11F20 03050085 285D03C2 78787878 78787878  [......](xxxxxxxx]
7F8D3FC11F30 78787878 78787878 78787878 78787878  [xxxxxxxxxxxxxxxx]
  Repeat 1 times
 
REDO RECORD - Thread:1 RBA: 0x00316e.00000025.0164 LEN: 0x0330 VLD: 0x09
SCN: 0x0b86.0d004018 SUBSCN:  1 11/02/2018 19:16:45
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x01400085 OBJ:350366 SCN:0x0b86.0d003f20 SEQ:2 OP:11.2 ENC:0 RBL:0
KTB Redo 
op: 0x11  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: F  xid:  0x0019.004.00009104    uba: 0x00c1702a.1ea1.2a
Block cleanout record, scn:  0x0b86.0d004016 ver: 0x01 opt: 0x02, entries follow...
  itli: 1  flg: 2  scn: 0x0b86.0d003f1f
  itli: 2  flg: 2  scn: 0x0b86.0d003f20
KDO Op code: IRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01400085  hdba: 0x01400082
itli: 1  ispac: 0  maxfr: 4858
tabn: 0 slot: 6(0x6) size/delt: 99
fb: --H-FL-- lb: 0x1  cc: 3
null: ---
col  0: [ 3]  c2 03 5e
col  1: [40]
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
col  2: [50]
 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20
CHANGE #2 TYP:0 CLS:65 AFN:3 DBA:0x00c000a8 OBJ:4294967295 SCN:0x0b86.0d003fdc SEQ:1 OP:5.2 ENC:0 RBL:0
ktudh redo: slt: 0x0004 sqn: 0x00009104 flg: 0x0012 siz: 136 fbi: 0
            uba: 0x00c1702a.1ea1.2a    pxid:  0x0000.000.00000000
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008d OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.5 ENC:0 RBL:0
index redo (kdxlre):  restore leaf row
KTB Redo 
op: 0x01  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: F  xid:  0x0019.004.00009104    uba: 0x00c1702a.1ea1.2b
REDO: SINGLE / -- / -- 
itl: 2, sno: 0, row size 55
CHANGE #4 TYP:0 CLS:65 AFN:3 DBA:0x00c000a8 OBJ:4294967295 SCN:0x0b86.0d004018 SEQ:1 OP:5.4 ENC:0 RBL:0
ktucm redo: slt: 0x0004 sqn: 0x00009104 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x00c1702a.1ea1.2b ext: 60 spc: 2072 fbi: 0 
CHANGE #5 TYP:0 CLS:66 AFN:3 DBA:0x00c1702a OBJ:4294967295 SCN:0x0b86.0d003fdb SEQ:2 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 136 spc: 2324 flg: 0x0012 seq: 0x1ea1 rec: 0x2a
            xid:  0x0019.004.00009104  
ktubl redo: slt: 4 rci: 0 opc: 11.1 [objn: 350366 objd: 350366 tsn: 7]
Undo type:  Regular undo        Begin trans    Last buffer split:  No 
Temp Object:  No 
Tablespace Undo:  No 
             0x00000000  prev ctl uba: 0x00c1702a.1ea1.28 
prev ctl max cmt scn:  0x0b86.0d003d78  prev tx cmt scn:  0x0b86.0d003d88 
txn start scn:  0x0b86.0d004017  logon user: 62  prev brb: 12677159  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:  0x001e.013.0000a096 uba: 0x00c05594.2254.32
                      flg: C---    lkc:  0     scn: 0x0b86.0d003f1f
KDO Op code: DRP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x01400085  hdba: 0x01400082
itli: 1  ispac: 0  maxfr: 4858
tabn: 0 slot: 6(0x6)
CHANGE #6 TYP:0 CLS:66 AFN:3 DBA:0x00c1702a OBJ:4294967295 SCN:0x0b86.0d004018 SEQ:1 OP:5.1 ENC:0 RBL:0
ktudb redo: siz: 112 spc: 2186 flg: 0x0022 seq: 0x1ea1 rec: 0x2b
            xid:  0x0019.004.00009104  
ktubu redo: slt: 4 rci: 42 opc: 10.22 objn: 350367 objd: 350367 tsn: 7
Undo type:  Regular undo       Undo type:  Last buffer split:  No 
Tablespace Undo:  No 
             0x00000000
index undo for leaf key operations
KTB Redo 
op: 0x03  ver: 0x01  
compat bit: 4 (post-11) padding: 1
op: Z
Dump kdilk : itl=2, kdxlkflg=0x1 sdc=0 indexid=0x140008a block=0x0140008d
(kdxlpu): purge leaf row
key :(45): 
 03 c2 03 5e 28 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78 78
END OF REDO DUMP
----- Redo read statistics for thread 1 -----
Read rate (ASYNC): 19Kb in 0.02s => 0.93 Mb/sec
Total redo bytes: 1023Kb Longest record: 8Kb, moves: 0/9 moved: 0Mb (0%)
Longest LWN: 19Kb, reads: 1 
Last redo scn: 0x0b86.0d004018 (12670371643416)
Change vector header moves = 0/22 (0%)
----------------------------------------------
[oracle@linux11 trace]$ 



Summary

REDO RECORD - Thread:1 RBA: 0x00316e.00000002.0010 LEN: 0x0074 VLD: 0x05
(LWN RBA: 0x00316e.00000002.0010 LEN: 0038 NST: 0001 SCN: 0x0b86.0d004016)
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d003f20 SEQ:2 OP:4.1 ENC:0 RBL:0
        Cleanout (the DBA is the high values leaf)

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000002.0084 LEN: 0x0144 VLD: 0x01
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d003fe6 SEQ:1 OP:5.2 ENC:0 RBL:0
        Update undo seg header 
                Start transaction (saves old transaction control data)

CHANGE #2 TYP:0 CLS:76 AFN:3 DBA:0x00c05593 OBJ:4294967295 SCN:0x0b86.0d003fe5 SEQ:2 OP:5.1 ENC:0 RBL:0
ktubl redo: slt: 13 rci: 0 opc: 10.21 [objn: 350367 objd: 350367 tsn: 7]
        index general undo (branch) operations
                Actually undo for high-values leaf.
                Detail "unlock block"

CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.6 ENC:0 RBL:0
        Lock block (the DBA is the high values leaf)

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000002.01c8 LEN: 0x20a4 VLD: 0x01
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.2 ENC:0 RBL:0
        Update undo segment header 
                Updates current undo block address
                set to record 1 of new block

CHANGE #2 TYP:1 CLS:76 AFN:3 DBA:0x00c05595 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.1 ENC:0 RBL:0
ktubu redo: slt: 13 rci: 0 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
        index general undo (branch) operations
                Actually undo for high-values leaf.
                Saves leaf block before image
                vector size 8,148 bytes

CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:2 OP:10.9 ENC:0 RBL:0
        Modify service ITL
                the DBA is the high values leaf block
                Set Flag to -B--, Lck to 1

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000013.017c LEN: 0x0044 VLD: 0x01
CHANGE #1 TYP:0 CLS:8 AFN:5 DBA:0x01400088 OBJ:350367 SCN:0x0b86.0d003e8e SEQ:3 OP:13.22 ENC:0 RBL:0
        Update L1 bitmap block 
                Space management for the index segment

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000013.01c0 LEN: 0x01ac VLD: 0x01
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:2 OP:5.2 ENC:0 RBL:0
        Update segment header
                Updates current undo block address
                set to record 1 of new block

CHANGE #2 TYP:1 CLS:76 AFN:3 DBA:0x00c05596 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:1 OP:5.1 ENC:0 RBL:0
ktubu redo: slt: 13 rci: 0 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
        index general undo (branch) operations
                Actually undo for new index leaf block
                Make leaf block empty.

CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008d OBJ:350367 SCN:0x0b86.0d003e8e SEQ:2 OP:10.8 ENC:0 RBL:0
        init header of newly allocated leaf block
                the DBA is next block to current high
                Include ITL (with service set to B), and row(s)

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000014.017c LEN: 0x0048 VLD: 0x01
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008b OBJ:350367 SCN:0x0b86.0d003e8f SEQ:2 OP:4.1 ENC:0 RBL:0
        Block cleanout 
                the DBA is the root block
                set the SCN in the service ITL

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000014.01c4 LEN: 0x00e0 VLD: 0x01
CHANGE #1 TYP:0 CLS:76 AFN:3 DBA:0x00c05596 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:2 OP:5.1 ENC:0 RBL:0
kitubu redo: slt: 13 rci: 1 opc: 10.21 objn: 350367 objd: 350367 tsn: 7
        index general undo (branch) operations
                Modify root block
                Replace service ITL entry
                Purge a row

CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008b OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.15 ENC:0 RBL:0
        Insert branch block row
                The DBA is the root block
                inserts pointer to new high value block

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000015.00b4 LEN: 0x1fb0 VLD: 0x01
CHANGE #1 TYP:0 CLS:75 AFN:3 DBA:0x00c00170 OBJ:4294967295 SCN:0x0b86.0d004016 SEQ:3 OP:5.4 ENC:0 RBL:0
        Commit transaction
                The recursive transaction for the split

CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:350367 SCN:0x0b86.0d004016 SEQ:3 OP:10.8 ENC:0 RBL:0
        init leaf block being split
                the DBA is current high values
                writes most of a block image to disc 

------

REDO RECORD - Thread:1 RBA: 0x00316e.00000025.0164 LEN: 0x0330 VLD: 0x09
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x01400085 OBJ:350366 SCN:0x0b86.0d003f20 SEQ:2 OP:11.2 ENC:0 RBL:0
        Insert row piece
                (to table)
                cleans out current ITL entries

CHANGE #2 TYP:0 CLS:65 AFN:3 DBA:0x00c000a8 OBJ:4294967295 SCN:0x0b86.0d003fdc SEQ:1 OP:5.2 ENC:0 RBL:0
        start transaction 
                new seg header, and transaction table slot

CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008d OBJ:350367 SCN:0x0b86.0d004016 SEQ:1 OP:10.5 ENC:0 RBL:0
        restore leaf row
                This is the new high-values block
                Was the image of data from the previous block marked deleted ?

CHANGE #4 TYP:0 CLS:65 AFN:3 DBA:0x00c000a8 OBJ:4294967295 SCN:0x0b86.0d004018 SEQ:1 OP:5.4 ENC:0 RBL:0
        Commit

CHANGE #5 TYP:0 CLS:66 AFN:3 DBA:0x00c1702a OBJ:4294967295 SCN:0x0b86.0d003fdb SEQ:2 OP:5.1 ENC:0 RBL:0
ktubl redo: slt: 4 rci: 0 opc: 11.1 [objn: 350366 objd: 350366 tsn: 7]
        undo row operation
                Undo for a table row insert
                Also holds transaction table control data

CHANGE #6 TYP:0 CLS:66 AFN:3 DBA:0x00c1702a OBJ:4294967295 SCN:0x0b86.0d004018 SEQ:1 OP:5.1 ENC:0 RBL:0
ktubu redo: slt: 4 rci: 42 opc: 10.22 objn: 350367 objd: 350367 tsn: 7
        undo leaf key operation
                Purge the new row from the new leaf block

One detail to note – the sys-recursive transaction operates in “classic” redo style – i.e. one change at a time in separate records in the order of activity; then the user transaction runs in the “modern” redo style using private redo to batch the forward and backward change vectors.

October 30, 2018

Index Splits – 2

Filed under: Indexing,Infrastructure,Oracle — Jonathan Lewis @ 1:29 pm GMT Oct 30,2018

In yesterday’s article I described the mechanism that Oracle for an index leaf block split when you try to insert a new entry into a leaf block that is already full, and I demonstrated that the “50-50” split and the “90-10” split work in the same way, namely:

  • save the old block into the undo
  • prepare a new leaf block
  • “share” the data between the old and new leaf blocks
  • sort out pointers

The obvious question to ask about this process is: “Why does Oracle save and rewrite the whole of the old leaf block during a 90-10 split when the data in the block doesn’t appear to change ?” The “sharing” in the 90-10 split is most uneven, and it appears that Oracle simply attaches a new leaf block to the index structure and writes the new index entry into it, leaving the existing index entries unchanged in the current leaf block.

The answer to that question can be found by doing block dumps – except you won’t see the answer if you use my original test data. So here’s a follow-on script to the previous test (written 11 years after the previous script):


rem
rem     Script:         index_splits3a.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Oct 2018
rem     Purpose:
rem

drop table t2 purge;

create table t2 as select * from t1 where id <= 148;
alter table t2 add constraint t2_pk primary key(id, idx_pad) using index pctfree 0;

column object_id new_value m_index_id
select object_id from user_objects where object_name = 'T2_PK' and object_type = 'INDEX';

begin
        for r in (select * from t1 where id between 149 and 292 order by dbms_random.value) loop
                insert into t2 values(r.id, r.idx_pad, r.padding);
        end loop;
        commit;
end;
/

alter session set events 'immediate trace name treedump level &m_index_id';
alter system flush buffer_cache;

prompt  check the trace file for the last block of the index
prompt  then do a block dump for it.
prompt  then press return

pause

insert into t2 values(293, rpad('x',40,'x'), rpad('y',50,'y'));
commit;

alter session set events 'immediate trace name treedump level &m_index_id';
alter system flush buffer_cache;


This test depends on the number of rows used for the previous test – and I have four hard-coded values (148, 149, 292, 293) in it that matter. If you’ve had to use a different number of rows in your version of the first test you will need to adjust these values to match.

I’ve created a clone of the t1 table copying only the first 148 rows – this is just enough rows that when I create a unique (PK) index on the table the index will have two leaf blocks, the first holding 147 entries and the second holding one entry. I’ve then inserted the next 144 rows from t1 into t2 in random order, so that I end up with two full leaf blocks.

Once the data is ready the code issues a treedump command (so that we can check the index is as I’ve described it) and flushes the buffer_cache, then prompts you with some instructions and waits for you to press return. At this point you need some manual intervention from another session – you can examine the treedump to work out the file and block addresses of the two leaf blocks and dump the second leaf block (‘alter database dump datafile N block M;’).

After you’ve done the block dump press return and my code resumes and inserts a new row that will cause a 90-10 split to happen, then it does another treedump (to let you check the block addresses and see that the split was 90-10), and flushes the buffer cache again. This is where you can check the block address of the second leaf block (in case it has managed to change – which it shouldn’t) and dump the block again.

Here, with a huge chunk removed from the middle, are the results I got from searching for the expression “row#” in the two block dumps that I generated in my test.


Before 90/10 block split:
-------------------------
row#0[7979] flag: -------, lock: 0, len=53, data:(6):  01 40 01 84 00 03
row#1[1885] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 2b
row#2[1938] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 2a
row#3[5595] flag: -------, lock: 2, len=53, data:(6):  01 40 01 f9 00 2c
row#4[3581] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 0b
...
row#142[1408] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 34
row#143[2150] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 26
row#144[878] flag: -------, lock: 2, len=53, data:(6):  01 40 01 fd 00 3e


After 90/10 block split
-----------------------
row#0[348] flag: -------, lock: 0, len=53, data:(6):  01 40 01 84 00 03
row#1[401] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 2b
row#2[454] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 2a
row#3[507] flag: -------, lock: 0, len=53, data:(6):  01 40 01 f9 00 2c
row#4[560] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 0b
...
row#142[7873] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 34
row#143[7926] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 26
row#144[7979] flag: -------, lock: 0, len=53, data:(6):  01 40 01 fd 00 3e

The “row#” is in ascending order – these lines in an index leaf block dump show Oracle walking through the block’s “row directory”; the number in square brackets following the row number is the offset into the block where the corresponding index entry will be found. When Oracle inserts an index entry into a leaf block it adjusts the row directory to make a gap in the right place so that walking the directory in row# order allows Oracle to jump around the block and find the index entries in key order.

When Oracle rewrites the block it first sorts the index entries into key order so that the actual index entries are written into the block in key order and a range scan that moves a pointer smoothly through the row directory will be moving another pointer smoothly down the block rather than making the pointer jump all over the place. Presumably this has (or maybe had) a benefit as far as the CPU cache and cache lines are concerned.

So there is a method in the madness of “copy the whole block even when the content doesn’t change”. The content doesn’t change but the order does, and paying the cost of sorting once may return a benefit in efficiency many times in the future.

 

October 29, 2018

Index splits

Filed under: Indexing,Infrastructure,Oracle — Jonathan Lewis @ 1:48 pm GMT Oct 29,2018

After writing this note I came to the conclusion that it will be of no practical benefit to anyone …  but I’m publishing it anyway because it’s just an interesting little observation about the thought processes of some Oracle designer/developer. (Or maybe it’s an indication of how it’s sensible to re-use existing code rather than coding for a particular boundary case, or maybe it’s an example of how to take advantage of “dead time” to add a little icing to the cake when the extra time required might not get noticed). Anyway, the topic came up in a recent thread on the OTN/ODC database forum and since the description given there wasn’t quite right I thought I’d write up a correction and a few extra notes.

When an index leaf block is full and a new row has to be inserted in the block Oracle will usually allocate a new leaf block, split the contents of the full block fairly evenly between two leaf blocks, then update various pointers to bring the index structure up to date. At various moments in this process the branch block above the leaf block and the leaf blocks either side of the splitting block have to be pinned. The number of times this happens is reported under the statistic “leaf node splits” but there is a special subset of leaf node splits that handles the case when the key in the new row is greater than the current high value in the block and the block is the “rightmost” (i.e. high values) block in the index. In this case Oracle adds a new leaf block to the end of the index and inserts the new value in the new block; it doesn’t share the data at all between the old and new leaf blocks. This special case is reported under the statistic “leaf node 90-10 splits”, even though “100-0” would be a more accurate description than “90-10”.

This note is a description of the work done by  a leaf node split and compares the work for a “50-50” split (as the general case is often called) and a 90-10 split. You might think that the latter would be less resource-intensive than the former but, in fact, that’s not the case. Here’s a little script to get things going – I’m using an 8KB block size and ASSM (automatic segment space management); if your default tablespace definition is different the number of rows you have to use will need to be changed.


rem
rem     Script:         index_splits3.sql
rem     Author:         Jonathan Lewis
rem     Dated:          September 2007
rem

start setenv
set timing off
set feedback off

define m_limit = 292

drop table t1 purge;

create table t1 (id number, idx_pad varchar2(40), padding varchar2(50));
alter table t1 add constraint t1_pk primary key(id, idx_pad);

column object_id new_value m_index_id

select
        object_id
from
        user_objects
where
        object_name = 'T1_PK'
and     object_type = 'INDEX'
;

begin
        for i in 1..&m_limit loop
                insert into t1 values(
                        i, rpad('x',40,'x'), rpad(' ',50)
                );
                commit;
        end loop;
end;
/


I’ve created a table with a two-column primary key and inserted “m_limit” rows into that table in an order that matches the primary key. The limit of 292 rows (which I’ve declared at the top of the program) means that the index entries for the data set will exactly fill two leaf blocks. I’ve captured the object_id of the index because I want to do a “treedump” of the index before and after inserting the next row.

I now need to run one of two tests inserting a single row. Either insert a row that is above the current highest value to force a 90-10 index leaf node split, or insert a row a little below the current high value to force a 50-50 index node split in the 2nd of the two index leaf blocks.


alter session set events 'immediate trace name treedump level &m_index_id';

alter system switch logfile;
execute snap_my_stats.start_snap;

begin
        for i in &m_limit + 1 .. &m_limit + 1  loop
                insert into t1 values(
                        i, rpad('x',40,'x'), rpad(' ',50)
--                      i - 2 , rpad('y',40,'y'), rpad(' ',50)
                );
                commit;
        end loop;
end;
/

execute snap_my_stats.end_snap

alter session set events 'immediate trace name treedump level &m_index_id';

execute dump_log

The calls to snap_my_stats are using a package I wrote a long time ago to report a delta in my session’s stats. The call to dump_log uses another little package to identify the current log file and issue an “alter system dump logfile …” command. Of the two possible sets of values for the row being inserted the first one will cause a 90-10 split the second (commented out) will cause a 50-50 split.

Here are the results from the calls to treedump – first the dump taken before the insert then the dump after a 90-10 split, finally the dump after re-running the test and forcing a 50-50 split. These results came from a database running 11.2.0.4, but the results are the same for 12.1.0.2 and 18.3.0.0:


----- begin tree dump
branch: 0x140008b 20971659 (0: nrow: 2, level: 1)
   leaf: 0x140008e 20971662 (-1: nrow: 147 rrow: 147)
   leaf: 0x140008f 20971663 (0: nrow: 145 rrow: 145)
----- end tree dump

----- begin tree dump
branch: 0x140008b 20971659 (0: nrow: 3, level: 1)
   leaf: 0x140008e 20971662 (-1: nrow: 147 rrow: 147)
   leaf: 0x140008f 20971663 (0: nrow: 145 rrow: 145)
   leaf: 0x140008c 20971660 (1: nrow: 1 rrow: 1)
----- end tree dump


----- begin tree dump
branch: 0x140008b 20971659 (0: nrow: 3, level: 1)
   leaf: 0x140008e 20971662 (-1: nrow: 147 rrow: 147)
   leaf: 0x140008f 20971663 (0: nrow: 78 rrow: 78)
   leaf: 0x140008c 20971660 (1: nrow: 68 rrow: 68)
----- end tree dump


As you can see the extra row in the first case has been inserted into a new leaf block leaving the 2nd leaf block (apparently) unchanged; in the second case the 145 initial rows plus the one extra row have been shared fairly evenly between two leaf block. I can’t explain the imbalance in this case, it doesn’t affect the length of the branch entry. If you’re wondering why the first leaf block held 147 entries while the original 2nd leaf block held 145 it’s because the first 100 entries in the first leaf block had a value for the id column that was 2 bytes long, after which the id needed 3 bytes storage for Oracle’s internal representation.)

Having examined the treedumps to see that the splits are 90-10 and 50-50 respectively we can now look at the undo and redo generated by the different cases. Here are the relevant values extracted from the snapshots of the session stats. Again the first set comes from the 90-10 split, the second from the 50-50 split.


Redo/Undo stats 90/10 split
--------------------------------------------
redo entries                               9
redo size                             18,500
undo change vector size                8,736

Redo/Undo stats 50/50 split
--------------------------------------------
redo entries                               9
redo size                             18,520
undo change vector size                8,736

In both cases the volume of undo and redo is the same (plus or minus a tiny bit – with tiny variations across versions). The undo is equivalent to roughly a whole block plus a few percent (and that will be copied into the redo, of course) and the “pure” redo is also equivalent to a whole block plus a few percent for a total of two data blocks worth plus a couple of thousand bytes. (The extra percentage is mostly about the old and new pointers as we break and make links in the leaf blocks and update and insert links from the branch block above.)

So why does a 90/10 split, which appears simply to add a leaf block and insert one row, do so much work? The answer lies (to start with) in the dump of the redo log file. The session statistics show 9 redo entries (redo change records) generated in both cases, so I’m going to start by picking out a summary of those records from the log file dumps using egrep to identify the lines showing the redo change record length (LEN:) and the redo change vector op codes (OP:). Here’s the output, with a little cosmetic modification, for the 90-10 split.


egrep -e "LEN:" -e"OP:" test_ora_20690.trc

REDO RECORD - Thread:1 RBA: 0x00314b.00000002.0010 LEN: 0x0074 VLD: 0x05
(LWN RBA: 0x00314b.00000002.0010 LEN: 0038 NST: 0001 SCN: 0x0b86.0cfca74e)
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008f OBJ:349950 SCN:0x0b86.0cfca74a SEQ:2 OP:4.1 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000002.0084 LEN: 0x0144 VLD: 0x01
CHANGE #1 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfca746 SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:1 CLS:74 AFN:3 DBA:0x00c0465f OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:1 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349950 SCN:0x0b86.0cfca74e SEQ:1 OP:10.6 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000002.01c8 LEN: 0x20a4 VLD: 0x01                                        ***
CHANGE #1 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:1 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:1 CLS:74 AFN:3 DBA:0x00c04660 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:1 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349950 SCN:0x0b86.0cfca74e SEQ:2 OP:10.9 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000013.017c LEN: 0x0044 VLD: 0x01
CHANGE #1 TYP:0 CLS:8 AFN:5 DBA:0x01400088 OBJ:349950 SCN:0x0b86.0cfca638 SEQ:3 OP:13.22 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000013.01c0 LEN: 0x01ac VLD: 0x01
CHANGE #1 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:1 CLS:74 AFN:3 DBA:0x00c04661 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:1 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:349950 SCN:0x0b86.0cfca638 SEQ:2 OP:10.8 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000014.017c LEN: 0x0048 VLD: 0x01
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008b OBJ:349950 SCN:0x0b86.0cfca639 SEQ:2 OP:4.1 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000014.01c4 LEN: 0x00e0 VLD: 0x01
CHANGE #1 TYP:0 CLS:74 AFN:3 DBA:0x00c04661 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:2 OP:5.1 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008b OBJ:349950 SCN:0x0b86.0cfca74e SEQ:1 OP:10.15 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000015.00b4 LEN: 0x1fb0 VLD: 0x01                                        ***
CHANGE #1 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfca74e SEQ:3 OP:5.4 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349950 SCN:0x0b86.0cfca74e SEQ:3 OP:10.8 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314b.00000025.0164 LEN: 0x0320 VLD: 0x09
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x01400084 OBJ:349949 SCN:0x0b86.0cfca74a SEQ:2 OP:11.2 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:83 AFN:3 DBA:0x00c004a8 OBJ:4294967295 SCN:0x0b86.0cfca738 SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:349950 SCN:0x0b86.0cfca74e SEQ:1 OP:10.5 ENC:0 RBL:0
CHANGE #4 TYP:0 CLS:83 AFN:3 DBA:0x00c004a8 OBJ:4294967295 SCN:0x0b86.0cfca750 SEQ:1 OP:5.4 ENC:0 RBL:0
CHANGE #5 TYP:0 CLS:84 AFN:3 DBA:0x00c04b0f OBJ:4294967295 SCN:0x0b86.0cfca738 SEQ:2 OP:5.1 ENC:0 RBL:0
CHANGE #6 TYP:0 CLS:84 AFN:3 DBA:0x00c04b0f OBJ:4294967295 SCN:0x0b86.0cfca750 SEQ:1 OP:5.1 ENC:0 RBL:0

I’ve highlighted two redo records with ‘***’ at the end of line. One of these records has length 0x20a4, the other has length 0x1fb0 i.e. roughly a whole data block each. We’ll look at those in more detail in a moment. Here, for comparison, is the result from the 50-50 split – again with a few highlighted lines:

REDO RECORD - Thread:1 RBA: 0x00314f.00000002.0010 LEN: 0x0074 VLD: 0x05
(LWN RBA: 0x00314f.00000002.0010 LEN: 0038 NST: 0001 SCN: 0x0b86.0cfcbc25)
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008f OBJ:349962 SCN:0x0b86.0cfcbc21 SEQ:2 OP:4.1 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.00000002.0084 LEN: 0x0144 VLD: 0x01
CHANGE #1 TYP:0 CLS:69 AFN:3 DBA:0x00c000e8 OBJ:4294967295 SCN:0x0b86.0cfcbc15 SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:70 AFN:3 DBA:0x00c10c43 OBJ:4294967295 SCN:0x0b86.0cfcbc15 SEQ:2 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349962 SCN:0x0b86.0cfcbc25 SEQ:1 OP:10.6 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.00000002.01c8 LEN: 0x20a4 VLD: 0x01                                        ***
CHANGE #1 TYP:0 CLS:69 AFN:3 DBA:0x00c000e8 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:1 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:1 CLS:70 AFN:3 DBA:0x00c10c44 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:1 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349962 SCN:0x0b86.0cfcbc25 SEQ:2 OP:10.9 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.00000013.017c LEN: 0x0044 VLD: 0x01
CHANGE #1 TYP:0 CLS:8 AFN:5 DBA:0x01400088 OBJ:349962 SCN:0x0b86.0cfcbb24 SEQ:3 OP:13.22 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.00000013.01c0 LEN: 0x1010 VLD: 0x01$                                       ***
CHANGE #1 TYP:0 CLS:69 AFN:3 DBA:0x00c000e8 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #2 TYP:1 CLS:70 AFN:3 DBA:0x00c10c45 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:1 OP:5.1 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:349962 SCN:0x0b86.0cfcbb24 SEQ:2 OP:10.8 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.0000001c.0060 LEN: 0x0048 VLD: 0x01
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x0140008b OBJ:349962 SCN:0x0b86.0cfcbb25 SEQ:2 OP:4.1 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.0000001c.00a8 LEN: 0x00e0 VLD: 0x01
CHANGE #1 TYP:0 CLS:70 AFN:3 DBA:0x00c10c45 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:2 OP:5.1 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008b OBJ:349962 SCN:0x0b86.0cfcbc25 SEQ:1 OP:10.15 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.0000001c.0188 LEN: 0x1150 VLD: 0x01                                        ***
CHANGE #1 TYP:0 CLS:69 AFN:3 DBA:0x00c000e8 OBJ:4294967295 SCN:0x0b86.0cfcbc25 SEQ:3 OP:5.4 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:1 AFN:5 DBA:0x0140008f OBJ:349962 SCN:0x0b86.0cfcbc25 SEQ:3 OP:10.8 ENC:0 RBL:0

REDO RECORD - Thread:1 RBA: 0x00314f.00000025.0168 LEN: 0x0330 VLD: 0x09
CHANGE #1 TYP:2 CLS:1 AFN:5 DBA:0x01400084 OBJ:349961 SCN:0x0b86.0cfcbc21 SEQ:2 OP:11.2 ENC:0 RBL:0
CHANGE #2 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfcbc1a SEQ:2 OP:5.2 ENC:0 RBL:0
CHANGE #3 TYP:0 CLS:1 AFN:5 DBA:0x0140008c OBJ:349962 SCN:0x0b86.0cfcbc25 SEQ:1 OP:10.5 ENC:0 RBL:0
CHANGE #4 TYP:0 CLS:73 AFN:3 DBA:0x00c00160 OBJ:4294967295 SCN:0x0b86.0cfcbc27 SEQ:1 OP:5.4 ENC:0 RBL:0
CHANGE #5 TYP:0 CLS:74 AFN:3 DBA:0x00c04c64 OBJ:4294967295 SCN:0x0b86.0cfcbc1a SEQ:2 OP:5.1 ENC:0 RBL:0
CHANGE #6 TYP:0 CLS:74 AFN:3 DBA:0x00c04c64 OBJ:4294967295 SCN:0x0b86.0cfcbc27 SEQ:1 OP:5.1 ENC:0 RBL:0

There are three interesting records in the 50-50 split with lengths 0x20a4 (the same as the 90-10 split), 0x1010, 0x1150. So we seem to start the same way with a “full block” record, and follow up with two “half block” records. The numbers allow you to make a reasonable guess – Oracle copies the original leaf block into the undo, then writes the two new leaf blocks as “pure” redo; in one case the two new leaf block redo records constitute a whole block and a tiny fraction of a block; in the other case the two new leaf block redo records constitute two half blocks.

I won’t show you the full detail that I checked in the log file dump, but the big 0x20a4 record in the 90-10 split is mostly made up of an “OP:5.1” change vector labelled “restore block before image (8032)”, while the 5th and 8th records in both dumps hold “OP:10.8” change vectors labelled “(kdxlne) … new block has NNN rows”. In the case of the 90-10 split the values for NNN are 1 and 145, in the case of the 50-50 split the values for NNN are 68 and 78 – in that (higher values leaf block first) order.

The 90-10 split and the 50-50 split act in exactly the same way – save the old block, allocate a new block, populate two blocks. It really looks as if code re-use has missed an easy opportunity for some optimisation – why save and rewrite a block when the data content is not going to change ?

Before assuming there’s a bug (or defect, or sub-optimal implementation) though it’s wise to consider whether there might be something else going on – Oracle developers (especially at the deeper levels) tend to have good reasons for what they do so maybe the rewrite is deliberate and serves a useful purpose.

If you do anything with my current test you won’t spot the extra little feature because my test is running a very special edge case – but I had a thought that would justify the cost (and timing) of the rewrite, and I’ll be publishing the idea, the test, and the results tomorrow.

Footnote

It is possible that a leaf node split means Oracle has to insert a pointer into a level 1 branch node that is already full – in which case Oracle will have to allocate a new branch node, share the branch data (including the new leaf pointer) between the two nodes, and insert a new branch pointer into the relevant level 2 branch block … and that may split etc. all the way up to the root. When the root node splits Oracle allocates two new blocks, increasing the branch level by one and keeping the original root block in place (immediately after all the space management blocks) but now pointing to just 2 “branch N-1” level blocks. Oracle will update the statistics “branch node splits” and “root node splits”.

In certain situations (typically relating to very large deletes followed by highly concurrent small inserts) Oracle may run into problems identifying a suitable “free” block while trying to do a split, and this can result in very slow splits that generate a lot of undo and redo which pinning index leaf blocks exclusively (leading to a couple of the more rare “enq – TX:” waits. In this case you may see statistics “failed probes on index block reclamation” and “recursive aborts on index block reclamation” starting to climb.  In theory I think you shouldn’t see more than a handful of “failed probes” per “recursive abort” – but I’ve never been able to model the problem to check that.

 

 

July 16, 2018

Direct IOT

Filed under: 12c,Infrastructure,IOT,Oracle — Jonathan Lewis @ 1:02 pm GMT Jul 16,2018

A recent (automatic ?) tweet from Connor McDonald highlighted an article he’d written a couple of years ago about an enhancement introduced in 12c that allowed for direct path inserts to index organized tables (IOTs). The article included a demonstration seemed to suggest that direct path loads to IOTs were of no benefit, and ended with the comment (which could be applied to any Oracle feature): “Direct mode insert is a very cool facility, but it doesn’t mean that it’s going to be the best option in every situation.”

Clearly it’s necessary to pose the question – “so when would direct mode insert be a good option for IOTs?” – because if it’s never a good option you have to wonder why it has been implemented. This naturally leads on to thinking about which tests have not yet been done – what aspects of IOTs did Connor not get round to examining in his article. (That’s a standard principle of trouble-shooting, or testing, or investigation: when someone shows you a test case (or when you think you’ve finished testing) one thing you should do before taking the results as gospel is to ask yourself what possible scenarios have not been covered by the test.)

So if you say IOT what are the obvious tests once you’ve got past the initial step of loading the IOT and seeing what happens. First, I think, would be “What if the IOT weren’t empty before the test started”; second would be “IOTs can have overflow segments, what impact might one have?”; third would be “Do secondary indexes have any effects?”; finally “What happens with bitmap indexes and the requirement for a mapping table?” (Then, of course, you can worry about mixing all the different possibilities together – but for the purposes of this note I’m just going to play with two simple examples: non-empty starting tables, and overflow segments.)

Here’s some code to define a suitable table:


create table t2 
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
	3 * rownum			id,
	lpad(rownum,10,'0')		v1,
	lpad('x',50,'x')		padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e5 -- > comment to avoid WordPress format issue
order by
	dbms_random.value
;

begin
	dbms_stats.gather_table_stats(
		ownname     => null,
		tabname     => 'T2',
		method_opt  => 'for all columns size 1'
	);
end;
/

create table t1(
	id,
	v1,
	padding,
	constraint t1_pk primary key(id)
)
organization index
-- including v1
-- overflow
nologging
as
select * from t2
;

begin
	dbms_stats.gather_table_stats(
		ownname     => null,
		tabname     => 'T1',
		method_opt  => 'for all columns size 1'
	);
end;
/

I’ve created a heap table t2 that holds 100,000 rows with an id column that is randomly ordered; then I’ve used this ta1ble as a source to create an IOT, with the option to have an overflow segment that contains just the 100 character padding columns. I’ve used 3 * rownum to define the id column for t2 so that when I insert another copy of t2 into t1 I can add 1 (or 2) to the id and interleave the new data with the old data. (That’s another thought about IOT testing – are you loading your data in a pre-existing order that suits the IOTs or is it arriving in a way that’s badly out of order with respect to the IOT ordering; and does your data go in above the current high value, or spread across the whole range, or have a partial overlap with the top end of the range and then run on above it.)

Have created the starting data set, here’s the test:


execute snap_my_stats.start_snap
execute snap_events.start_snap

insert 
	/*  append */
into t1
select
	id + 1, v1, padding
from
	t2
;


execute snap_events.end_snap
execute snap_my_stats.end_snap

All I’m doing is using a couple of my snapshot packages to check the work done and time spent while insert 100,000 interleaved rows – which are supplied out of order – into the existing table. As shown the “append” is a comment, not a hint, so I’ll be running the test case a total of 4 times: no overflow, with and without the hint – then with the overflow, with and without the hint. (Then, of course, I could run the test without the overflow but an index on v1).

Here are some summary figures from the tests – first from the test without an overflow segment:

                                      Unhinted       With Append
                                  ============      ============
CPU used when call started                 153               102
CPU used by this session                   153               102
DB time                                    166               139

redo entries                           130,603            42,209
redo size                           78,315,064        65,055,376

sorts (rows)                                30           100,031

You’ll notice that with the /*+ append */ hint in place there’s a noticeable reduction in redo entries and CPU time, but this has been achieved at a cost of sorting the incoming data into order. The reduction in redo (entries and size) is due to an “array insert” effect that Oracle can take advantage of with the delayed index maintenance that takes place when the append hint is legal (See the section labelled Option 4 in this note). So even with an IOT with no overflow there’s a potential benefit to gain from direct path loading that depends on how much the new data overlaps the old data, and there’s a penalty that depends on the amount of sorting you’d have to do.

What happens in my case when I move the big padding column out to an overflow segment – here are the equivalent results:


Headline figures                      Unhinted       With Append
================                  ============      ============
CPU used when call started                 158                52
CPU used by this session                   158                52
DB time                                    163                94
redo entries                           116,669            16,690
redo size                           51,392,748        26,741,868
sorts (memory)                               4                 5
sorts (rows)                                33           100,032

Interestingly, comparing the unhinted results with the previous unhinted results, there’s little difference in the CPU usage between having the padding column in the “TOP” section of the IOT compared to having it in the overflow segment, though there is a significant reduction in redo (the index entries are still going all over the place one by one, but the overflow blocks are being pinned and packed much more efficiently). The difference between having the append hint or not, though, is damatic. One third of the CPU time (despited still having 100,000 rows to sort), and half the redo. One of the side effects of the overflow, of course, is that the things being sorted are much shorted (only the id and v1 columns that go into the TOP section, and not the whole IOT row.

So, if you already have an overflow segment that caters for a significant percentage of the row, it looks as if the benefit you could get from using the /*+ append */ hint would far outweigh the penalty of sorting you have to pay. Of course, an IOT with a large overflow doesn’t look much different from a heap table with index – so perhaps that result isn’t very surprising.

I’ll close by re-iterating Connor’s closing comment:

Direct mode insert is a very cool facility, but it doesn’t mean that it’s going to be the best option in every situation.

Before you dive in and embrace it, or ruthlessly push it to one side, make sure you do some testing that reflects the situations you have to handle.

July 10, 2018

Validate FK

Filed under: constraints,Infrastructure,Oracle — Jonathan Lewis @ 10:42 am GMT Jul 10,2018

A comment arrived yesterday on an earlier posting about an enhancement to the truncate command in 12c that raised the topic of what Oracle might do to validate a foreign key constraint. Despite being sure I had the answer written down somewhere (maybe on a client site or in a report to a client) I couldn’t find anything I’d published about it, so I ran up a quick demo script to show that all Oracle does is construct a simple SQL statement that will do check the data – and then do whatever the optimizer does to produce the fastest possible plan.

Here’s the script – with a few variations to show what happens if you start tweaking features to change the plan.

rem
rem     Script:         validate_fk.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jun 2018
rem
rem     Last tested
rem             12.2.0.1
rem             12.1.0.2
rem             11.2.0.4
rem

create table parent 
as 
select  * 
from    all_Objects 
where   rownum <= 10000 -- > comment to avoid wordpress format issue
;

alter table parent add constraint par_pk primary key(object_id);

execute dbms_stats.gather_table_stats(null, 'parent', cascade=>true)


create table child 
as 
select par.* 
from    (select rownum from dual connect by level <= 10) v1, --> comment to avoid wordpress format issue
        parent par
; 

alter table child add constraint chi_fk_par foreign key(object_id) references parent enable novalidate; 
create index chi_fk_par on child(object_id); 
execute dbms_stats.gather_table_stats(null, 'child', cascade=>true)


-- alter table child modify object_id null;
-- alter table child parallel(degree 8);
-- alter session set "_fast_full_scan_enabled" = FALSE;
-- alter session set "_optimizer_outer_to_anti_enabled" = false;

alter system flush buffer_cache;

alter session set events '10046 trace name context forever, level 12';
alter table child modify constraint chi_fk_par validate;
alter session set events '10046 trace name context off;

All I’ve done is created parent table with a primary key, and a child table with 10 rows per parent. I’ve created a foreign key constraint on the child table, enabled it (so future data will be checked) but not validated it (so there’s no enforced guarantee that the existing data is correct). Then I’ve issued a command to validate the foreign key.

The flush of the buffer cache is to allow me to see the I/O that takes place and will also (usually) let me see some if there are any strange issues due to any recursive SQL Oracle. As you can see I’ve also got a couple of commented commands that might cause a couple of variations in behaviour.

Here’s the critical content from the output of the trace file summary from tkprof (in versions from 11.2.0.4 to 12.2.0.1):


select /*+ all_rows ordered dynamic_sampling(2) */ A.rowid, :1, :2, :3
from
 "TEST_USER"."CHILD" A , "TEST_USER"."PARENT" B where( "A"."OBJECT_ID" is not
  null) and( "B"."OBJECT_ID" (+)= "A"."OBJECT_ID") and( "B"."OBJECT_ID" is
  null)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.01       0.02        241        373          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.02       0.02        241        373          0           0

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  NESTED LOOPS ANTI (cr=373 pr=241 pw=0 time=21779 us starts=1 cost=70 size=22000 card=1000)
    100000     100000     100000   INDEX FAST FULL SCAN CHI_FK_PAR (cr=224 pr=219 pw=0 time=17753 us starts=1 cost=32 size=1700000 card=100000)(object id 104840)
     10000      10000      10000   INDEX UNIQUE SCAN PAR_PK (cr=149 pr=22 pw=0 time=4494 us starts=10000 cost=0 size=49995 card=9999)(object id 104838)

As you can see, Oracle writes SQL for an outer join with an “is null” predicate on the outer table – which the optimizer converts to an anti-join, running a nested loop in this case. It’s an interesting little oddity that the code includes the predicate “A”.”OBJECT_ID” is not null given that the column is declared as not null – but this is presumably a developer deciding to re-use code even if it then includes a redundant predicate (which is effectively zero cost – since the optimizer can use transitive closure to eliminate it).

Given that Oracle has converted an outer join to an anti join I obviously had to check what would happen if I disabled this conversion by altering the “_optimizer_outer_to_anti_enabled” parameter to false. The optimizer obeyed the session setting with the following plan in the trace:

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  FILTER  (cr=373 pr=241 pw=0 time=226926 us starts=1)
    100000     100000     100000   NESTED LOOPS OUTER (cr=373 pr=241 pw=0 time=177182 us starts=1 cost=70 size=22000 card=1000)
    100000     100000     100000    INDEX FAST FULL SCAN CHI_FK_PAR (cr=224 pr=219 pw=0 time=40811 us starts=1 cost=32 size=1700000 card=100000)(object id 104848)
    100000     100000     100000    INDEX UNIQUE SCAN PAR_PK (cr=149 pr=22 pw=0 time=119363 us starts=100000 cost=0 size=49995 card=9999)(object id 104846)

The significant difference is in the CPU usage, of course, and to a degree the magnitude of the change is dictated by the pattern and distribution of the data. The number of CR gets hasn’t changed as the number of index probes jumps from 10,000 to 100,000 because Oracle will have pinned index blocks (There’s a very old article on my old website if you want to read more about buffer pins).

The original question was about the effect of a local session setting that disabled index fast full scans, and followed up with a question on parallelism. After seeing the effect of changing one optimizer parameter at the session level you probably won’t be surprised by the following two results.  First, when the only change I make is the setting of the “_index_fast_full_scan_enabled” parameter, and then when the only change is the declared parallelism of the child table.

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  MERGE JOIN ANTI (cr=240 pr=240 pw=0 time=120163 us starts=1 cost=247 size=22000 card=1000)
    100000     100000     100000   INDEX FULL SCAN CHI_FK_PAR (cr=218 pr=218 pw=0 time=20314 us starts=1 cost=222 size=1700000 card=100000)(object id 104852)
    100000     100000     100000   SORT UNIQUE (cr=22 pr=22 pw=0 time=81402 us starts=100000 cost=25 size=50000 card=10000)
     10000      10000      10000    INDEX FULL SCAN PAR_PK (cr=22 pr=22 pw=0 time=1185 us starts=1 cost=22 size=50000 card=10000)(object id 104850)


Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  PX COORDINATOR  (cr=15 pr=2 pw=0 time=722483 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10001 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=37 size=22000 card=1000)
         0          0          0    HASH JOIN ANTI BUFFERED (cr=0 pr=0 pw=0 time=0 us starts=0 cost=37 size=22000 card=1000)
         0          0          0     PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us starts=0 cost=32 size=1700000 card=100000)
         0          0          0      TABLE ACCESS FULL CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=32 size=1700000 card=100000)
         0          0          0     PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us starts=0 cost=4 size=50000 card=10000)
         0          0          0      PX SEND BROADCAST :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=4 size=50000 card=10000)
         0          0          0       PX SELECTOR  (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0        INDEX FAST FULL SCAN PAR_PK (cr=0 pr=0 pw=0 time=0 us starts=0 cost=4 size=50000 card=10000)(object id 104854)

In the first case my version of Oracle has switched to a merge anti-join with an index full scan (not FAST full scan). It’s interesting to note that the merge join anti hasn’t been as clever as the nested loop anti in avoiding probes of the second data source as it walks the foreign key index (note how starts=100000 in the SORT UNIQUE line).

In the second case all the work was done by the parallel query slaves – and the PX SELECTOR line tells you that this plan must have come from 12c. As you can see we’re still doing an anti-join but this time we do a parallel tablescan of the child table (as we haven’t enabled the index for parallel execution – if we had altered the index to parellel(degree 8) as well we would have seen a parallel index fast full scan instead of the parallel tablescan.)

Bottom line: the SQL executed to validate a foreign key constraint is essentially a join between the parent and child tables, Oracle will simply optimize that statement to the best of its abilities based on the current session settings. If you want to test on a clone (or accurate model) of the tables you may find that you can create an sql_patch that works (even though the necessary SQL will be optimised as SYS – though so far I’ve only tried this with a couple of variants of the parallel() hint on 12.2.0.1)

<h3>Footnote</h3>

If you were wondering what the three bind variables in the query were, this is the relevant extract from the 10046 trace file with bind variable tracing enabled:

 Bind#0
  oacdty=01 mxl=32(09) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f3fbd359c38  bln=32  avl=09  flg=05
  value="TEST_USER"
 Bind#1
  oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f3fbd359c00  bln=32  avl=05  flg=05
  value="CHILD"
 Bind#2
  oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f3fbd359bc8  bln=32  avl=10  flg=05
  value="CHI_FK_PAR"

The values are the owner, table, and constraint names. (Though you have to modify the code a little to show that the last one is the constraint name and not the index name).

 

 

June 29, 2018

Truncate upgrade

Filed under: 12c,Infrastructure,Oracle,Upgrades — Jonathan Lewis @ 8:22 am GMT Jun 29,2018

Connor McDonald produced a tweet yesterday linking to a short video he’d created about an enhancement to the truncate command in 12c. If you have referential integrity declared between a parent and child table then in 12c you can truncate the parent table and Oracle will truncate the child table for you – rather than raising an error. The feature requires the foreign key constraint to be declared “on delete cascade” – which is an option that I don’t see used very often. Unfortunately if you try to change an existing foreign key constraint to meet this requirement you’ll find that you can’t (yet) use the “alter table modify constraint” to make the necessary change. As Connor pointed out, you’ll have to drop and recreate the constraint – which leaves you open to bad data getting into the system or an outage while you do the drop and recreate.

If you don’t want to stop the system but don’t want to leave even a tiny window for bad data to arrive here’s a way to do it. In summary:

  1. Add a virtual column to the child table “cloning” the original foreign key column
  2. Create an index on the  virtual column (if you have concerns about “foreign key locking”)
  3. Add a foreign key constraint based on the virtual column
  4. Drop the old foreign key constraint
  5. Recreate the old foreign key constraint “on delete cascade”
  6. Drop the virtual column

Here’s some sample SQL:


rem
rem	Script:		122_truncate_workaround.sql
rem	Author:		Jonathan Lewis
rem	Dated:		Jun 2018
rem	Purpose:	
rem
rem	Last tested 
rem		18.1.0.0	via LiveSQL
rem		12.2.0.1
rem		12.1.0.2

drop table child;
drop table parent;

create table parent (
	p number,
	constraint p_pk primary key(p)
);

create table child (
	c	number,
	p	number,
	constraint c_pk primary key(c),
	constraint c_fk_p foreign key (p) references parent
);

create index c_fk_p on child(p);

insert into parent values(1);
insert into child values(1,1);

commit;

prompt	==========================================================================
prompt	Truncate  should fail with
prompt	ORA-02266: unique/primary keys in table referenced by enabled foreign keys
prompt	==========================================================================

truncate table parent;

alter table child add (
	pv generated always as (p+0) virtual
)
;

create index c_ipv on child(pv) online;

alter table child add constraint c_fk_pv
	foreign key (pv)
	references parent(p)
	on delete cascade
	enable novalidate
;
alter table child modify constraint c_fk_pv validate;

alter table child drop constraint c_fk_p;

prompt	===================================================================================
prompt	Illegal insert (first 1) should fail with
prompt	ORA-02291: integrity constraint (TEST_USER.C_FK_PV) violated - parent key not found
prompt	===================================================================================

insert into child (c,p) values(2,2);
insert into child (c,p) values(2,1);
commit;

alter table child add constraint c_fk_p
	foreign key (p)
	references parent(p)
	on delete cascade
	enable novalidate
;

alter table child modify constraint c_fk_p validate;

prompt	===================================================
prompt	Dropping the virtual column results in Oracle
prompt	dropping the index and constraint at the same time
prompt	===================================================

alter table child drop column pv;

The overhead of this strategy is significant – I’ve created an index (which you may not need, or want, to do) in anticipation of a possible “foreign key locking” issue – and I’ve used the online option to avoid locking the table while the index is created which means Oracle has to use a tablescan to acquire the data. I’ve enabled a new constraint without validation (which takes a brief lock on the table) then validated it (which doesn’t lock the table but could do a lot of work). Then I’ve dropped the old constraint and recreated it using the same novalidate/validate method to minimise locking time. If I were prepared simply to drop and recreate the original foreign key I wouldn’t need to create that index and I’d only do one validation pass rather than two.

 

June 23, 2018

Cursor_sharing force

Filed under: CBO,Infrastructure,Oracle,Troubleshooting — Jonathan Lewis @ 12:05 pm GMT Jun 23,2018

Prompted by a recent ODC (OTN) question I’ve just written up an example of one case where setting the cursor_sharing parameter to force doesn’t work as you might expect. It’s a specific example of what I believe is a theme that can appear in several different circumstances: if your SQL mixes “genuine” bind variable with literals then the literals may not be substituted.

Here’s a simple data set to start with:


rem
rem     Script:         cursor_sharing_limit.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Jun 2018
rem     Purpose:
rem
rem     Last tested
rem             18.1.0.0
rem             12.2.0.1
rem             12.1.0.2
rem

create table t1
as
select
        rownum            n1,
        rownum            n2,
        lpad(rownum,10)   small_vc,
        rpad('x',100,'x') padding
from dual
connect by
        level <= 1e4 -- > comment to avoid WordPress format issue
;

I haven’t bothered to gather stats – it’s not needed in trivial cases of CTAS.

Here’s one way to execute SQL that doesn’t get literal substitution when (apparently) it should:


alter system flush shared_pool;
alter session set cursor_sharing=force;

declare
        m_ct number;
        m_n1 number := 20;
begin
        execute immediate
                'select /*+ trace this */ count(*) from t1 where n2 = 15 and n1 = :b1'
                into m_ct using m_n1;
        dbms_output.put_line(m_ct);

        execute immediate
                'select /*+ trace this too */ count(*) from t1 where n1 = 15 and n2 = 15'
                into m_ct;
        dbms_output.put_line(m_ct);
end;
/

alter session set cursor_sharing=exact;

I’ve included a “hint” that allows me to find the SQL statements in v$sql very easily – and here they are, preceded by the query I used to find them:


select  sql_id, parse_calls, executions, rows_processed, sql_text 
from    v$sql
where   sql_text like 'select%trace this%'
and     sql_text not like '%v$sql%'
;


SQL_ID        PARSE_CALLS EXECUTIONS ROWS_PROCESSED
------------- ----------- ---------- --------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
cbu4s78h5pfj5           1          1              1
select /*+ trace this too */ count(*) from t1 where n1 = :"SYS_B_0" and n2 = :"SYS_B_1"

cru67sufptx8x           1          1              1
select /*+ trace this */ count(*) from t1 where n2 = 15 and n1 = :b1

Notice how one statement – which used only literals – underwent bind variable transformation but the other – with its mix of literals and bind variables – didn’t. On the other hand, if I execute the mixed format statement from a basic SQL*Plus session then pull the plan from memory, this is what I get:


SQL> select /*+ SQL*Plus session */ count(*) from t1 where n2 = 15 and n1 = :b1;

  COUNT(*)
----------
         0

1 row selected.

SQL> select  sql_id, parse_calls, executions, rows_processed, sql_text
  2  from    v$sql
  3  where   sql_text like 'select%Plus session%'
  4  and     sql_text not like '%v$sql%'
  5  ;

SQL_ID        PARSE_CALLS EXECUTIONS ROWS_PROCESSED
------------- ----------- ---------- --------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
gq2qy2a9yuta7           1          1              1
select /*+ SQL*Plus session */ count(*) from t1 where n2 = :"SYS_B_0" and n1 = :b1

When trying to take advantage of cursor_sharing = force, you have to think about how the SQL gets to the database engine – is it delivered directly, or is it sent through some layer of code that means the raw SQL statement is protected in some way from the substitution code.

Footnote:

I happen to have used an example that puts the bind variable into the where clause; you will see the same effect even if the bind variables are in the select list – for example if you’ve selected something like to_char(date_col, :formatting_variable).

June 11, 2018

dbms_random

Filed under: Infrastructure,Oracle,Performance — Jonathan Lewis @ 8:31 am GMT Jun 11,2018

In a recent ODC thread someone had a piece of SQL that was calling dbms_random.string(‘U’,20) to generate random values for a table of 100,000,000 rows. The thread was about how to handle the ORA-30009 error (not enough memory for operation) that is almost inevitable when you use the “select from dual connect by level <= n” strategy for generating very large numbers of rows, but this example of calling dbms_random.string() so frequently prompted me to point out an important CPU saving , and then publicise through this blog a little known fact (or deduction) about the dbms_random.string() function.

If you generate a random string of length 6 using only upper-case letters there are 308,915,766 different combinations (266); so if you’re after “nearly unique” values for 100 million rows then a six character string is probably good enough – it might give you a small percentage of values which appear in a handful rows but most of the values are likely to be unique or have two rows. If you want to get closer to uniqueness then 7 characters will do it, and 8 will make it almost certain that you will get a unique value in every row.

So if you want “nearly unique” and “random 20 character strings” it’s probably sufficient to generate random strings of 6 to 8 characters and then rpad() them up to 20 characters with spaced – the saving in CPU will be significant; roughly a factor of 3 (which is going to matter when you’re trying to generate 100 million rows. As a little demo I supplied the OP with a script to create a table of just one million random strings – first of 20 random characters, then of 6 random characters with 14 spaces appended. The run time (mostly CPU) dropped from 1 minute 55 seconds to 41 seconds.

Why is there such a difference ? Because to generate a random string of 6 characters Oracle generates a random string of one character six times in a row and concatenates them. The difference between 6 calls and 20 calls per row gives you that factor of around 3. For a quick demo, try running the following anonymous PL/SQL block:

rem
rem     Script:         random_speed.sql
rem     Author:         Jonathan Lewis
rem     Dated:          May 2010
rem

begin
        dbms_random.seed(0);
        dbms_output.put_line(dbms_random.string('U',6));
        dbms_output.new_line;

        dbms_random.seed(0);
        dbms_output.put_line(dbms_random.string('U',1));
        dbms_output.put_line(dbms_random.string('U',1));
        dbms_output.put_line(dbms_random.string('U',1));
        dbms_output.put_line(dbms_random.string('U',1));
        dbms_output.put_line(dbms_random.string('U',1));
        dbms_output.put_line(dbms_random.string('U',1));
end;
/

Jere are the results I got from instances of 12.1.0.2, 12.2.0.1, and 18.1.0.0 (from LiveSQL):


BVGFJB
B
V
G
F
J
B

I haven’t shown the tests for all the possible dbms_random.string() options but, unsurprisingly, changing the test to use the ‘L’ (lower case alpha) option produces the same effect (and the same 6 letters changed to lower case). The same effect, with different characters, also appeared using the ‘A’ (mixed case alpha), ‘X’ (uppercase alphanumeric) and ‘P’ (all printable characters) options.

I haven’t considered the effect of using a multi-byte character set – maybe Oracle calls its random number generator once per byte rather than once per character. The investigation is left as an exercise to the interested reader.

tl;dr

When generating a very large number of random strings – keep the “operational” part of the string as short as you can and leave the rest to be rpad()‘ed.

May 28, 2018

Filtering LOBs

Filed under: CBO,Execution plans,LOBs,Oracle,subqueries — Jonathan Lewis @ 8:25 am GMT May 28,2018

A two-part question about the FILTER operation appeared on the Oracle-L list server a couple of days ago. The first part was a fairly common question – one that’s often prompted by the way the optimizer used to behave in older versions of Oracle. Paraphrased, it was: “Why is the total cost of the query so high compared to the sum of its parts?”

Here’s the query, and the execution plan.

 INSERT INTO TEMP
  SELECT DISTINCT 'id',
    PHT.emplid
  FROM PHOTO PHT
  WHERE 1               =1
  AND PHT.PHOTO IS NOT NULL
  AND NOT EXISTS
    (SELECT 'x'
    FROM TEMP TMP
    WHERE PHT.EMPLID=TMP.EMPLID_SRCH
    AND TMP.OPRID  = 'id'
    )
  ;  

  
-------------------------------------------------------------------------------------
| Id  | Operation                | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |          | 21210 |  3334K|  5802K  (2)| 00:03:47 |
|   1 |  LOAD TABLE CONVENTIONAL | TEMP     |       |       |            |          |
|*  2 |   FILTER                 |          |       |       |            |          |
|*  3 |    TABLE ACCESS FULL     | PHOTO    | 21211 |  3334K|   313   (1)| 00:00:01 |
|*  4 |    TABLE ACCESS FULL     | TEMP     |     1 |    17 |   380   (2)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter( NOT EXISTS (SELECT 0 FROM " TEMP" "TMP" WHERE
              "TMP"."EMPLID_SRCH"=:B1 AND "TMP"."OPRID"='id'))
   3 - filter("PHT"."PHOTO" IS NOT NULL)
   4 - filter("TMP"."EMPLID_SRCH"=:B1 AND "TMP"."OPRID"='id')

Note that the “not exists” subquery against temp runs as a filter subquery with a cost of 380 for the tablescan. Combine that with the cost of 313 for the driving tablescan of photo and you might wonder why the resulting cost isn’t something like 693 – and in some old versions of Oracle that’s probably how it would be reported.

Historically the optimizer has been very bad about producing a final cost when queries have included subqueries – whether as filter subqueries in the predicate section or as scalar subqueries in the select list. Sometimes the cost would simply vanish from the final cost, sometimes it would be added just once to the final cost regardless of how many times the subquery might actually execute.

In this example the subquery against temp is a correlated subquery and might have to run once for every row in photo where the column photo was not null. At best it would have to run at least once for every distinct value of the photo.emplid column (the correlation column) found in those rows. In recent versions of Oracle the optimizer has tried to introduce some estimate of how many times the subquery would run as part of its calculation of the total cost. So (to a crude approximation) 5802K = 313 + N * 380. Unfortunately if we try to work backwards to N we find it would be about 15,267 which is about 72% of the 21,200 rows estimated as the result of the tablescan of photo – I haven’t tried to investigate the algorithms yet but presumably the optimizer makes some allowances somewhere for “self caching” as the subquery runs.

The more interesting part of the question came when the OP decided to test the effect of getting rid of the subquery. Check the costs in the resulting plan:


  INSERT INTO TEMP
  SELECT DISTINCT 'id',
    PHT.emplid
  FROM PHOTO PHT
  WHERE 1               =1
  AND PHT.UC_PBI_PHOTO IS NOT NULL;

  
-------------------------------------------------------------------------------------
| Id  | Operation                | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |          | 21211 |  3334K|  3659   (1)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL | TEMP     |       |       |            |          |
|*  2 |   TABLE ACCESS FULL      | PHOTO    | 21211 |  3334K|  3659   (1)| 00:00:01 |
-------------------------------------------------------------------------------------
  
Predicate Information (identified by operation id):
---------------------------------------------------
     2 - filter("PHT"."PHOTO" IS NOT NULL)

Note how the cost of the tablescan of photo has gone up from 313 in the previous query to 3,659 in the simpler query! How can a tablescan that drives a subquery have a lower cost than the tablescan on its own? Bear in mind that in both cases the Cost attributed to the operation “Table Access Full” is purely about scanning the rows in the photo table and is (or should be) entirely disconnected from the cost and frequency of the subquery.

The clue is in the table definition. The column photo.photo is a BLOB.

Models

I think there are potentially two errors in the optimizer displayed by this example. The first is that it’s adding in a cost that it shouldn’t even be considering; the second is that it’s being inconsistent in the way that it’s deriving that cost.

To demonstrate what I think is happening, I built a variant of the OP’s example as follows:


rem
rem     Script:         optimizer_lob_costs.sql
rem     Author:         Jonathan Lewis
rem     Dated:          May 2018
rem     Purpose:
rem
rem     Last tested
rem             12.2.0.1
rem             12.1.0.2
rem

create table photo (
        emplid          varchar2(11) not null,
        photo           clob,
        other_col       varchar2(1000)
)
lob (photo) 
store as
        photo_lob(
        disable storage in row 
        cache
        logging
)
;

create unique index ph_uk on photo(emplid);

insert /*+ append */ into photo
select
        lpad(2 * rownum,10,0),
        rpad('x',1000),
        rpad('x',1000)
from
        all_objects
where
        rownum <= 10000 -- > comment to avoid wordpress format issue
;

commit;

create table temp(
        oprid           varchar2(30),
        emplid_srch     varchar2(11)
)
;

insert /*+ append */ into temp
select
        'id',
        lpad(2 * rownum,10,0)
from
        all_objects
where
        rownum <= 1000 -- > comment to avoid wordpress format issue
;

commit;

execute dbms_stats.gather_table_stats(user,'photo',method_opt=>'for all columns size 1', cascade=>true)
execute dbms_stats.gather_table_stats(user,'temp', method_opt=>'for all columns size 1', cascade=>true)


I’ve changed the BLOB to a CLOB defined with storage in row disabled, and I’ve introduced a varchar2() column of the same size as the CLOB column. I’ve declared the correlating column not null and created a unique index on it. Here are the two queries I want to review – slightly simplified versions of the original:


explain plan for
insert into temp(emplid_srch)
select 
        distinct pht.emplid
from 
        photo pht
where 
        1 = 1
and  pht.photo is not null
-- and     pht.other_col is not null
and     not exists (
                select /*+ no_unnest */
                        null
                from 
                        temp tmp
                where 
                        pht.emplid=tmp.emplid_srch
        )
;  

select * from table(dbms_xplan.display);

explain plan for
insert into temp(emplid_srch)
select
        distinct pht.emplid
from    photo pht
where   1               =1
and  pht.photo is not null
-- and     pht.other_col is not nulL
;  

select * from table(dbms_xplan.display);

As you can see I’ve had to include a /*+ no_unnest */ hint in my SQL to get the FILTER operation to appear in the plan (the OP had the hidden parameter “_unnest_subquery” set to false); I’ve also allowed for two variants of each query, one referencing the CLOB column the other referencing the varchar2() column. The only results I’ll show are for the queries accessing the CLOB, and here are the plans first with, then without, the subquery. Check the cost of the tablescan of the photo table in the two cases:


----------------------------------------------------------------------------------
| Id  | Operation                | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |       |  9999 |   956K| 10458   (3)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL | TEMP  |       |       |            |          |
|*  2 |   FILTER                 |       |       |       |            |          |
|*  3 |    TABLE ACCESS FULL     | PHOTO | 10000 |   957K|   216   (1)| 00:00:01 |
|*  4 |    TABLE ACCESS FULL     | TEMP  |     1 |    11 |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter( NOT EXISTS (SELECT /*+ NO_UNNEST */ 0 FROM "TEMP" "TMP"
              WHERE "TMP"."EMPLID_SRCH"=:B1))
   3 - filter("PHT"."PHOTO" IS NOT NULL)
   4 - filter("TMP"."EMPLID_SRCH"=:B1)


----------------------------------------------------------------------------------
| Id  | Operation                | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |       | 10000 |   957K|   285   (2)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL | TEMP  |       |       |            |          |
|*  2 |   TABLE ACCESS FULL      | PHOTO | 10000 |   957K|   285   (2)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("PHT"."PHOTO" IS NOT NULL)

With the subquery in place the tablescan of photo reports a cost of 285, in the absence of the subquery it reports a cost of 216, a difference of 69. Repeating the test but using the varchar2() column the cost of the tablescan was 213 in both cases – suggesting that the variation was due to the column being a LOB.

With no further clues in the plan it looked like one of those rare occasions when I have to look at the 10053 (optimizer) trace file – and this is what I got from the 12.1.0.2 trace, looking at the section headed “SINGLE TABLE ACCESS PATH” for the photo table. First the base query without the subquery:


SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for PHOTO[PHT]
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = TABLE
  Column (#2): PHOTO(LOB)
    AvgLen: 87 NDV: 0 Nulls: 0 Density: 0.000000
  Table: PHOTO  Alias: PHT
    Card: Original: 10000.000000  Rounded: 10000  Computed: 10000.000000  Non Adjusted: 10000.000000
  Scan IO  Cost (Disk) =   210.000000
  Scan CPU Cost (Disk) =   13571440.480000
  Total Scan IO  Cost  =   210.000000 (scan (Disk))
                         + 70.000000 (io filter eval) (= 0.007000 (per row) * 10000.000000 (#rows))
                       =   280.000000
  Total Scan CPU  Cost =   13571440.480000 (scan (Disk))
                         + 9138463.200000 (cpu filter eval) (= 913.846320 (per row) * 10000.000000 (#rows))
                       =   22709903.680000

Note the “Total Scan IO Cost” described at line 13 includes a component at line 12 labelled “(io filter eval)” – why, for the predicate “photo is null”, would we do any special I/O when that predicate can be met in the basic table scan.

(Note: A predicate like “lob_column is null” means there is no lob locator in place, so no lob access need be done for that test. In fact the related, but very different, predicate “length(lob_column) = 0” meaning the lob locator exists but the lob is “empty” could also be satisfied during the tablescan without reference to the physical lob segment(s) because the length of the lob is included in the lob locator.)

Let’s assume that the optimizer is incorrectly assuming the run-time engine will have to access the lob in some way to determine that the lob is null. The worst case scenario is that Oracle will start by accessing the LOBindex – so why don’t we check how big the LOBindex is. The first step I took was to check the object_id of the LOBindex and then do a tree dump (which showed 66 leaf blocks) and then I checked the segment header block and dumped that with the following results:


  Extent Control Header
  -----------------------------------------------------------------
  Extent Header:: spare1: 0      spare2: 0      #extents: 1      #blocks: 127
                  last map  0x00000000  #maps: 0      offset: 4128
      Highwater::  0x01400447  ext#: 0      blk#: 70     ext size: 127
  #blocks in seg. hdr's freelists: 4
  #blocks below: 70
  mapblk  0x00000000  offset: 0
                   Unlocked
     Map Header:: next  0x00000000  #extents: 1    obj#: 194295 flag: 0x40000000
  Extent Map
  -----------------------------------------------------------------
   0x01400401  length: 127

See the “Highwater::” information at line 6 – the allocated space in the segment is the first 70 blocks of the first extent. That’s (almost certainly) where the incremental cost of 70 (single block I/Os) comes from.  (And I did couple of big updates to the LOB, designed to expand the LOBindex without changing the segment size of the underlying table, to corroborate that hypothesis.)

This brings us to the question of why the cost of the tablescan drops when the subquery is included. Again we generate the 10053 trace and examine the details under the “SINGLE TABLE ACCESS PATH”:


SINGLE TABLE ACCESS PATH
  Single Table Cardinality Estimation for PHOTO[PHT]
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = TABLE
  Table: PHOTO  Alias: PHT
    Card: Original: 10000.000000  Rounded: 10000  Computed: 10000.000000  Non Adjusted: 10000.000000
  Scan IO  Cost (Disk) =   210.000000
  Scan CPU Cost (Disk) =   13571440.480000
  Total Scan IO  Cost  =   210.000000 (scan (Disk))
                         + 3.500000 (io filter eval) (= 0.000350 (per row) * 10000.000000 (#rows))
                       =   213.500000
  Total Scan CPU  Cost =   13571440.480000 (scan (Disk))
                         + 656923.160000 (cpu filter eval) (= 65.692316 (per row) * 10000.000000 (#rows))
                       =   14228363.640000


In this case the “(io filter eval)” at line 10 is only 3.5 – and if you know your optimizer and how it handles subqueries you’re allowed to guess that could be one of Oracle’s standard guesses of 5% coming into play. (Again, growing the index seemed to corroborate this hypothesis.)

So here’s (possible) bug number 2: the first bug is adding a cost for accessing the LOBindex when there should be no need to  access the index at all – the execution plan says we will get 10,000 rows from the table, the filter predicate does report a cardinality reduced by just 1 on a column that has been declared with a uniqueness constraint, but a fairly commonly used “guess factor” of 5% is used as an indicator of the number of times the lob predicate will be tested. The various bits of the arithmetic are not consistent with each other.

Summary notes:

If you have a tablescan with a predicate that references a lob column then the cost of the tablescan includes the cost of the lob access – and there are cases where lob access is not needed but still gets costed {this is bug number 1 – the predicates are column is/is not null, and length(column) = / != 0)}.

If the lob data itself does not need to be accessed then the size of the lob index – which you can’t easily find – may have a significant impact on the cost of the tablescan.

If the query also includes predicates that result in the optimizer guessing about cardinality effects (1%, 5%, 0.25% are common guesses) then that guess may be used to scale the assumed (and potentially irrelevant) cost of the lob access. (There is scope for further experimentation in this area to examine the effects of “non-guess” predicates and the assumed order of application of predicates, e.g. are lob predicates costed as the last to be applied, does the algorithm for costing matched the execution order.)

As often happens it’s easy to see that there are oddities in the arithmetic that affect the cost of a query in ways that might make the optimizer pick a silly execution plan. Unfortunately it’s not easy to predict when you’re likely to see the effects of these oddities; the best we can do is remember that there is an anomaly with costing lob-based predicates and hope that we think of it when we see the optimizer picking a bad plan for reasons that initially are not obvious.

April 9, 2018

Data Hashing

Filed under: Infrastructure,Oracle — Jonathan Lewis @ 6:10 pm GMT Apr 9,2018

Here’s a little-known feature that has been around since at least Oracle 10, though I don’t think I had ever seen it in the wild until today when someone reported on the ODC (OTN) database forum that they had a problem getting repeatable results.  It’s always possible, of course, that failure to get repeatable results is the natural consequence of running queries against a multi-user system, but if we assume that this was not the cause in this case we have to ask why a special hashing function that Oracle supplies to allow you to check that a set of data hasn’t changed gives you different results when “the data hasn’t changed”.

I’m talking about the function dbms_sqlhash.gethash() – a packaged function that exists in the SYS schema and isn’t usually exposed to other users. The function takes as its inputs the text of query, a selected hashing function, and a “chunk” size. It will run the query, and use the hashing function to return a single, 16 – 64 byte, hash value representing the entire result set. Here’s an example of usage:


begin
        dbms_output.put_line(
                dbms_sqlhash.gethash(
                        sqltext     => 'select n1, d1 from t1 where id > 0',
                        digest_type => dbms_crypto.hash_md5
                        -- chunk_size  => 128*1048576   -- default 128MB
                )
        );
end;
/

6496D2438FECA960B1E916BF8C4BADCA

I haven’t specified a chunk size – the default is 128MB – and Oracle will hash this much of the result set in a single pass. If the result set is larger than this Oracle will hash each chunk in turn then generate a hash of the hash values. (This means, by the way, that changing the chunk size can change the hash value for large data sets).

There are 6 possible digest types in 12.1.0.2 (listed in the $ORACLE_HOME/rdbms/admin/dbmsobtk.sql script that creates the dbms_crypto package – so you will need the execute privilege on both dbms_sqlhash and dbms_crypto to use the function if you want to code with symbolic constants):

rem         HASH_MD4           CONSTANT PLS_INTEGER            :=     1;
rem         HASH_MD5           CONSTANT PLS_INTEGER            :=     2;
rem         HASH_SH1           CONSTANT PLS_INTEGER            :=     3;
rem         HASH_SH256         CONSTANT PLS_INTEGER            :=     4;
rem         HASH_SH384         CONSTANT PLS_INTEGER            :=     5;
rem         HASH_SH512         CONSTANT PLS_INTEGER            :=     6;

Let’s put the whole thing into a demonstration that will allow us to see an important point – you have to be careful with your query:


rem
rem     Script:         gethash.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Feb 2016
rem

execute dbms_random.seed(0)

create table t1
nologging
as
select
        1e4 - rownum                    id,
        trunc(dbms_random.value(0,100)) n1,
        trunc(sysdate)                  d1,
        lpad('x',100,'x')               padding
from
        dual
connect by
        level <= 1e4 -- > comment to avoid WordPress format issue
;

alter table t1 add constraint t1_pk primary key (id);

begin
        dbms_stats.gather_table_stats(
                ownname     => user,
                tabname     => 'T1',
                method_opt  => 'for all columns size 1'
        );
end;
/

set feedback off

alter system flush shared_pool;
alter session set optimizer_mode = first_rows_1;

begin
        dbms_output.put_line(
                dbms_sqlhash.gethash(
                        sqltext     => 'select n1, d1 from t1 where id > 0',
                        digest_type => dbms_crypto.hash_md5
                        -- chunk_size  => 128*1048576   -- default 128MB
                )
        );
end;
/

alter system flush shared_pool;
alter session set optimizer_mode = all_rows;

begin
        dbms_output.put_line(
                dbms_sqlhash.gethash(
                        sqltext     => 'select n1, d1 from t1 where id > 0',
                        digest_type => dbms_crypto.hash_md5
                        -- chunk_size  => 128*1048576   -- default 128MB
                )
        );
end;
/

alter system flush shared_pool;
alter session set nls_date_format='dd-mon-yyyy hh24:mi:ss';

begin
        dbms_output.put_line(
                dbms_sqlhash.gethash(
                        sqltext     => 'select n1, d1 from t1 where id > 0',
                        digest_type => dbms_crypto.hash_md5
                        -- chunk_size  => 128*1048576   -- default 128MB
                )
        );
end;
/

alter session set nls_date_format='DD-MON-RR';

I’ve created a data set, added a primary key, and gathered stats, then I’ve called the same hashing function on the same sql statement three times in a row. However, I’ve changed the session environment for each call – in the first case I’ve set the optimizer to “first rows(1)” optimization, then I’ve set the optimizer back to all_rows, then I’ve changed the nls_date_format from its default of “DD-MON-RR” (and that’s significant because I’ve got a date column in my query). Here are the output from running the script:


Table created.


Table altered.


PL/SQL procedure successfully completed.

6496D2438FECA960B1E916BF8C4BADCA
D41D4A2945D0B89A6C5DEB5060189A54
ECC3D2B66CB61821397CD9BD983FD5F4

The query has to return the same data content in all three cases – but the hash value is different in the three cases. The change in the optimizer mode has affected the order in which the data was returned (with first_rows(1) Oracle did a full scan of the primary key index, with all_rows it did a tablescan and sort); the change in the nls_XXX parameter meant the internal representation of the data changed.

You have to be very careful with dbms_sqlhash every time you use it if you want the same data set to produce the same result. First, to be safe, you need to ensure that you always use the same NLS parameters when using the function; then you need to have an “order by” clause in the query, and the columns used in the order by clause need to a possible candidate key (i.e. unique, not null) for the data otherwise a change in the optimizer parameters, or the object stats, could result in a change in execution plan with an ensuing change in the actual order of the data and a different hash value.

 

March 13, 2018

Deferred Invalidation

Filed under: 12c,CBO,Infrastructure,Oracle,Troubleshooting,Upgrades — Jonathan Lewis @ 6:30 pm GMT Mar 13,2018

I was going to write an article on the way 12.2 has introduced the option for “deferred invalidation” for a number of DDL operations, but I did a quick google search before I started writing and found that both Franck Pachot and Richard Foote (yes, rebuild index is one of the operations) had got there long ago so here are a couple of links – as much for my own benefit as anything else:

Richard Foote:

Franck Pachot:

Franck’s 2nd example may be particularly relevant to some clients of mine who were having problems with SQL queries that were crashing (slowly and randomly) instead of running very efficiently because they were running queries against one subpartition of a table while another subpartition of the same table was subject to exchange. With a little bad luck in the timing an exchange that took place between a parse and an execute would cause a query to have its cursor invalidated and re-parsed in a way that failed to do (sub-)partition elimination the way it should have because the local indexes were in an indeterminate state.

 

Next Page »

Powered by WordPress.com.