Re-partitioning

I wrote a short note a little while ago demonstrating how flexible Oracle 12.2 can be about physically rebuilding a table online to introduce or change the partitioning while discarding data, and so on.  But what do you do (as a recent question on ODC asked) if you want to upgrade a customer’s database to meet the requirements of a new release of your application by changing a partitioned table into a composite partitioned table and don’t have enough room to do an online rebuild. Which could require two copies of the data to exist at the same time.)

If you’ve got the down time (and not necessarily a lot is needed) you can fall back on “traditional methods” with some 12c enhancements. Let’s start with a range partitioned table:

rem
rem     Script:         pt_comp_from_pt.sql
rem     Author:         Jonathan Lewis
rem     Dated:          May 2019
rem

create table pt_range (
        id              number(8,0)     not null,
        grp             varchar2(1)     not null,
        small_vc        varchar2(10),
        padding         varchar2(100)
)
partition by range(id) (
        partition p200 values less than (200),
        partition p400 values less than (400),
        partition p600 values less than (600)
)
;

insert into pt_range
select
        rownum-1,
        mod(rownum,2),
        lpad(rownum,10,'0'),
        rpad('x',100,'x')
from
        all_objects
where
        rownum <= 600
;

commit;

So we’ve got a range-partitioned table with three partitions and some data in each partition. Let’s pretend we want to change this to range/list with the grp column as the subpartition key, allowing explicit use of values 0,1,2 and a bucket subpartition for anything else. First we create an empty version of the table with a suitable subpartition template, and a simple heap table to be used as an exchange medium:

create table pt_range_list (
        id              number(8,0)     not null,
        grp             varchar2(1)     not null,
        small_vc        varchar2(10),
        padding         varchar2(100)
)
partition by range(id)
subpartition by list (grp)
subpartition template (
        subpartition p_def      values(default)
)
(
        partition p200 values less than (200),
        partition p400 values less than (400),
        partition p600 values less than (600)
)
;

prompt  ===============================================
prompt  First nice 12.2 feature - "create for exchange"
prompt  ===============================================

create table t for exchange with table pt_range;

You’ll notice that our subpartition template identifies just a single subpartition that takes default values – i.e. anything for which no explicit subpartition has been identified. This means we have a one to one correspondance between the data segments of the original table and the copy table. So now we go through a tedious loop (which we could code up with a PL/SQL “execute immediate” approach) to do a double-exchange for each partition in turn. (Any PL/SQL code is left as an exercise to the interested reader.)

alter table pt_range exchange partition p200 with table t;
alter table pt_range_list exchange subpartition p200_p_def with table t;

alter table pt_range exchange partition p400 with table t;
alter table pt_range_list exchange subpartition p400_p_def with table t;

alter table pt_range exchange partition p600 with table t;
alter table pt_range_list exchange subpartition p600_p_def with table t;

prompt  =====================================
prompt  Show that we've got the data in place
prompt  =====================================

execute dbms_stats.gather_table_stats(user,'pt_range_list',granularity=>'ALL')

break on partition_name skip 1

select  partition_name, subpartition_name, num_rows
from    user_tab_subpartitions
where   table_name = 'PT_RANGE_LIST'
order by
        partition_name, subpartition_name
;


PARTITION_NAME         SUBPARTITION_NAME        NUM_ROWS
---------------------- ---------------------- ----------
P200                   P200_P_DEF                    200

P400                   P400_P_DEF                    200

P600                   P600_P_DEF                    200


3 rows selected.

We now have to split the newly arrived subpartitions into the 4 pieces we want – but before we do that let’s make sure that any new partitions automatically have the correct subpartitions by changing the subpartition template:

alter table pt_range_list
set subpartition template(
        subpartition p_0 values (0),
        subpartition p_1 values (1),
        subpartition p_2 values (2),
        subpartition p_def values (default)
)
;

prompt  =========================================================
prompt  Second nice 12.2 feature - multiple splits in one command
prompt  We could do this online after allowing the users back on.
prompt  =========================================================

alter table pt_range_list split subpartition p200_p_def
        into (
                subpartition p200_p_0 values(0),
                subpartition p200_p_1 values(1),
                subpartition p200_p_2 values(2),
                subpartition p200_p_def
        )
;

alter table pt_range_list split subpartition p400_p_def
        into (
                subpartition p400_p_0 values(0),
                subpartition p400_p_1 values(1),
                subpartition p400_p_2 values(2),
                subpartition p400_p_def
        )
;

alter table pt_range_list split subpartition p600_p_def
        into (
                subpartition p600_p_0 values(0),
                subpartition p600_p_1 values(1),
                subpartition p600_p_2 values(2),
                subpartition p600_p_def
        )
;

Now, just to check that everything is behaving, let’s add a new partition, and check to see what partitions and subpartitions we end up with:

alter table pt_range_list add partition p800 values less than (800);

execute dbms_stats.gather_table_stats(user,'pt_range_list',granularity=>'ALL')

select  partition_name, subpartition_name, num_rows
from    user_tab_subpartitions
where   table_name = 'PT_RANGE_LIST'
order by
        partition_name, subpartition_name
;

PARTITION_NAME         SUBPARTITION_NAME        NUM_ROWS
---------------------- ---------------------- ----------
P200                   P200_P_0                      100
                       P200_P_1                      100
                       P200_P_2                        0
                       P200_P_DEF                      0

P400                   P400_P_0                      100
                       P400_P_1                      100
                       P400_P_2                        0
                       P400_P_DEF                      0

P600                   P600_P_0                      100
                       P600_P_1                      100
                       P600_P_2                        0
                       P600_P_DEF                      0

P800                   P800_P_0                        0
                       P800_P_1                        0
                       P800_P_2                        0
                       P800_P_DEF                      0


16 rows selected.

And as a final note – if we decide we want to put it all back we could merge four subpartitions down to one subpartition with a single command – then loop through every partition in turn:

alter table pt_range_list
        merge subpartitions  p200_p_0, p200_p_1, p200_p_2, p200_p_def
        into  subpartition  p200_p_def
;

And now I feel like I’m turning into Tim Hall – writing potentially useful demonstrations instead of trying to baffle people with rocket science. But I hope to get over that quite soon. Of course I have left out some important “real-world” details – particularly how you choose to handle indexes while doing the double-exchange. My view would be to take the local indexes with you on the exchange, bypass the global indexes on the exchange out, and be choosy about which global indexes to maintain on the exchange back in; but it all depends on how much downtime you have, how many indexes there are, and the state they’re likely to start or end in.

As ever it’s possible to start with a simple idea like this, then discover there are real-world complications that have to be dealt with. So there’s another article in the pipeline to handle a slightly more complex case. I’ll also be publishing a short note about the easy way of getting the job done from 18c onwards – if you’ve got the spare resources.

 

LOB length

This note is a reminder combined with a warning about unexpected changes as you move from version to version. Since it involves LOBs (large objects) it may not be relevant for most people but since there’s a significant change in the default character set for the database as you move up to 18.3 (or maybe even as you move to 12.2) anyone using character LOBs may get a surprise.

Here’s a simple script that I’m first going to run on an instance of 11.2.0.4:

rem
rem     Script:         lob_length_4.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Apr 2019
rem

create table t1(
        n1      number,
        version varchar2(8),
        v1      varchar2(4000),
        c1      clob,
        nc1     nclob
)
lob (c1) store as securefile c1_lob(
        enable storage in row
        chunk 8K
        cache logging
)
lob (nc1) store as securefile nc1_lob(
        enable storage in row
        chunk 8K
        cache logging
)
;

insert into t1 values( 0,'General',  null,               empty_clob(),       empty_clob()      ) ;

insert into t1 values( 1,'11.2.0.4', rpad('x',1951,'x'), rpad('x',1951,'x'), rpad('x',1951,'x')) ;
insert into t1 values( 2,'11.2.0.4', rpad('x',1952,'x'), rpad('x',1952,'x'), rpad('x',1952,'x')) ;

insert into t1 values( 3,'12.1.0.2', rpad('x',1951,'x'), rpad('x',1951,'x'), rpad('x',1951,'x')) ;
insert into t1 values( 4,'12.1.0.2', rpad('x',1952,'x'), rpad('x',1952,'x'), rpad('x',1952,'x')) ;

insert into t1 values( 5,'12.2.0.1', rpad('x',1937,'x'), rpad('x',1937,'x'), rpad('x',1937,'x')) ;
insert into t1 values( 6,'12.2.0.1', rpad('x',1938,'x'), rpad('x',1938,'x'), rpad('x',1938,'x')) ;

insert into t1 values( 7,'18.3.0.0', rpad('x',1984,'x'), rpad('x',1984,'x'), rpad('x',1984,'x')) ;
insert into t1 values( 8,'18.3.0.0', rpad('x',1985,'x'), rpad('x',1985,'x'), rpad('x',1985,'x')) ;

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

break on version skip 1 on report

compute avg of sys_op_opnsize(c1)  on report
compute avg of sys_op_opnsize(nc1) on report

select
        version, n1,
        length(v1), length(c1), length(nc1),
        sys_op_opnsize(v1), sys_op_opnsize(c1), sys_op_opnsize(nc1)
from
        t1
order by
        n1
;

select  avg_row_len
from    user_tables
where   table_name = 'T1'
;

select  column_name, avg_col_len
from    user_tab_cols
where   table_name = 'T1'
order by
        column_id
;

I’ve created a table holding a varchar2() a CLOB, and an NCLOB, then I’ve inserted some rows into that table, labelling the rows in pairs with what appear to be Oracle version numbers, with one extra row labelled “General” that holds the special “empty LOB“ value (note a NULL and an empty clob behave very differently). Then I’ve reported the lengths of the LOB columns in two different ways, once using the standard length() function (I could have used the dbms_lob.getlength() function) and once using the internal sys_op_opnsize() function that Oracle uses in its queries to gather table stats.

Here’s the output from the script. Since this first run is on 11.2.0.4 I want you to note, particularly, the numbers in the rows labelled 11.2.0.4

VERSION          N1 LENGTH(V1) LENGTH(C1) LENGTH(NC1) SYS_OP_OPNSIZE(V1) SYS_OP_OPNSIZE(C1) SYS_OP_OPNSIZE(NC1)
-------- ---------- ---------- ---------- ----------- ------------------ ------------------ -------------------
General           0                     0           0                                    96                  96

11.2.0.4          1       1951       1951        1951               1951               2048                3999
                  2       1952       1952        1952               1952               2049                  86

12.1.0.2          3       1951       1951        1951               1951               2048                3999
                  4       1952       1952        1952               1952               2049                  86

12.2.0.1          5       1937       1937        1937               1937               2034                3971
                  6       1938       1938        1938               1938               2035                3973

18.3.0.0          7       1984       1984        1984               1984               2081                  86
                  8       1985       1985        1985               1985               2082                  86

********                                                                 ------------------ -------------------
avg                                                                              1835.77778          1820.22222


AVG_ROW_LEN
-----------
       5410

COLUMN_NAME          AVG_COL_LEN
-------------------- -----------
N1                             3
VERSION                        9
V1                          1740
C1                          1837
NC1                         1822

The reminders:

• A LOB that uses a multi-byte character set (and possibly, but I have not checked, an NCLOB that is using a single-byte character set) stores its content using a two-byte fixed width character set. So when I insert a character string of 1,951 (multibyte) characters the internal representation uses double the number of bytes as there are characters – so the data content will be 3,902 bytes.
• The length() and dbms_lob.getlength() functions report the number of characters not the number of bytes. (There is a lengthb() function to report the number of bytes, but it doesn’t work with multibyte character set LOBs, raising error: “ORA-22998: CLOB or NCLOB in multibyte character set not supported”). Even though our NCLOB needs 3,902 bytes for its content it is reported – just like the CLOB – with a length of 1,951.
• The sys_op_opnsize() internal function tells you about the number of bytes a column takes up in the row – though not always totally accurately, as we shall soon see – so it will tell you about the 3,902 bytes stored for the data plus the “structural” data that helps to describe the LOB. So for the row holding strings of length 1,951 we can see that the CLOB seems to take 1,951 + 97 = 2,048 bytes while the NCLOB seems to take 2 * 1951 + 97 = 3,999 bytes.
• When the total storage for a LOB column exceeds 4,000 bytes the LOB is stored “out of line” even when it has been declared as mine have with “enable storage in row”. So when we insert strings of length 1,952 the CLOB column stays in line and reports a size of 1,952 + 97 = 2.049 bytes while the NCLOB exceeds the limit (2 + 1,952 + 97 = 4001) and goes out of row, reporting an “in-row” size of 86 bytes which is (we assume) the LOB metadata.

You might note, by the way, that the avg_col_len is the average (which I’ve reported for the CLOB and NCLOB columns) of the sys_op_opnsize() values rounded up plus 1 (for the “column count” byte); and – because the number of columns in the table is small – the avg_row_len is very similar to the sum of the avg_col_len.

You should also note that the storage size of an “empty” LOB is (or seems to be) 96 bytes in this version of Oracle. That’s quite a lot of space to say that there’s no data  – but using an empty_[n]clob() to represent “nothing” does mean that you don’t have to code for “is null or is empty” and it may help you to avoid incorrect results as a consequence. In fact a block dump shows that the actual space usage for the empty_[n]clob() is only 30 bytes – so it’s not quite as bad as it seems. The error is probably based around the older code using the maximum possible length of a lob locator as an assumption rather than checking the actual size in the table.

The warning

It’s a minor variation of the standard warning: “odd little things change when you upgrade and some of them may have a big side effect”. Here are the results from 18.3 (which, amongst other details, defaults to a multi-byte character set – which I’ll check before I show you the LOB results).

SQL> select * from v$nls_parameters where parameter like '%CHARACTERSET%';

PARAMETER                        VALUE
-------------------------------- --------------------
NLS_CHARACTERSET                 AL32UTF8
NLS_NCHAR_CHARACTERSET           AL16UTF16

This affects the storage of CLOBs if you’ve previously been using a default single-byte character set – you’re suddenly going to find your LOB segments are twice as big as they used to be – even though any report of “length()” will be unchanged. But there are other changes. Here’s the output from the same script running on 18.3.0.0:

VERSION          N1 LENGTH(V1) LENGTH(C1) LENGTH(NC1) SYS_OP_OPNSIZE(V1) SYS_OP_OPNSIZE(C1) SYS_OP_OPNSIZE(NC1)
-------- ---------- ---------- ---------- ----------- ------------------ ------------------ -------------------
General           0                     0           0                                    30                  30

11.2.0.4          1       1951       1951        1951               1951               3933                3933
                  2       1952       1952        1952               1952               3935                3935

12.1.0.2          3       1951       1951        1951               1951               3933                3933
                  4       1952       1952        1952               1952               3935                3935

12.2.0.1          5       1937       1937        1937               1937               3905                3905
                  6       1938       1938        1938               1938               3907                3907

18.3.0.0          7       1984       1984        1984               1984               3999                3999
                  8       1985       1985        1985               1985                132                 132
********                                                                 ------------------ -------------------
avg                                                                              3078.77778          3078.77778

AVG_ROW_LEN
-----------
       7912

COLUMN_NAME          AVG_COL_LEN
-------------------- -----------
N1                             3
VERSION                        9
V1                          1740
C1                          3080
NC1                         3080

Looking at the details for “General” and “18.3.0.0” what can we see that’s changed?

First, the length of an empty_[n]clob is now reported correctly at 30 bytes. This might (if the value is also used internally) explain why a LOB can now be 33 characters (66 bytes) longer before it’s moved out of line – it’s a small difference, but you might be at a boundary condition where it makes a big difference (for good, or for bad – who can tell) or your system.

Secondly, the LOB metadata for an out of line LOB seems to have jumped from 86 bytes to 132 bytes. Like the empty_[n]clob() issue, this is an error. The actual space usage in row was 38 bytes – consisting of the basic 30 bytes “empty” metadata, 4 extra bytes overhead, and a 4-byte block address linking to the stored LOB value. (For larger LOBs you will probably see that the “tail” of the in-row data grows to accomodate a short list of block addresses and chunk information).

Finally, you’re allowed to guess that the rows labelled 12.2.0.1 are there to give you a hint that in that version the NCLOB moves out of line at 1,938 characters – but you’ll probably want to run the test on 12.2 to confirm that claim. This does mean, though, that an upgrade to 12.2 from a lower version might be a bigger threat than any upgrade to 18.3. You’ll also find that in 12.2 the empty_[n]clob() is reported with a length of 124. (Again, this may explain the change in the break-point for going out of line: 124 – 96 = 28, and (1952 – 28/2) = 1,938. The arithmetic is consistent with the incorrect reporting of the size of the empty LOB metadata.

So the bottom line is this – if you do a lot of work with LOBs, do some careful checking of how much space you are using, how much space you will use on the next install, how changes in character sets can affect numbers, how the statistics might change – even when collected in exactly the same way – and what this might do to execution plans.

Footnote

This testing was all done using securefile LOBs – which has been the default for some time if you don’t specify the type of LOB you want to use. The numbers, particularly the break from in-row to out-of-row, are a little different if you switch to basicfile LOBs.

A quick test on LiveSQL (19.2) suggests that nothing has changed from 18.3 to 19.3

For further reading on quirky details of LOBs – here’s the article that has a footnote reporting another interesting change in LOB handling in 18.3; and a very old note about analysing the contents of a LOB segment with a view to assessing the impact of deleting old LOBs and potentially moving the LOB segment to a tablespace of a different size.

 

 

Parse Calls

When dealing with the library cache / shared pool it’s always worth checking from time to time to see if a new version of Oracle has changed any of the statistics you rely on as indicators of potential problems. Today is also (coincidentally) a day when comments about “parses” and “parse calls” entered my field of vision from two different directions. I’ve tweeted out references to a couple of quirkly little posts I did some years ago about counting parse calls and what a parse call may entail, but I thought I’d finish the day off with a little demo of what the session cursor cache does for you when your client code issues parse calls.

There are two bit of information I want to highlight – activity in the library cache and a number that shows up in the session statistics. Here’s the code to get things going:

rem
rem     Script:         12c_session_cursor_cache.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Apr 2019
rem
rem     Note:
rem     start_1.sql contains the one line
rem          select * from t1 where n1 = 0;
rem

create table t1 
as
select 99 n1 from dual
;

execute dbms_stats.gather_table_stats(user,'t1')

spool 12c_session_cursor_cache

prompt  =======================
prompt  No session cursor cache
prompt  =======================

alter session set session_cached_cursors = 0;

set serveroutput off
set feedback off

execute snap_libcache.start_snap
execute snap_my_stats.start_snap

execute snap_libcache.start_snap
execute snap_my_stats.start_snap

@start_1000

set feedback on
set serveroutput on

execute snap_my_stats.end_snap
execute snap_libcache.end_snap


prompt  ============================
prompt  Session cursor cache enabled
prompt  ============================


alter session set session_cached_cursors = 50;

set serveroutput off
set feedback off

execute snap_libcache.start_snap
execute snap_my_stats.start_snap

execute snap_libcache.start_snap
execute snap_my_stats.start_snap

@start_1000

set feedback on
set serveroutput on

execute snap_my_stats.end_snap
execute snap_libcache.end_snap

spool off

I’ve made use of a couple of little utilities I wrote years ago to take snapshots of my session statistics and the library cache (v$librarycache) stats. I’ve also used my “repetition” framework to execute a basic query 1,000 times. The statement is a simple “select from t1 where n1 = 0”, chosen to return no rows.

The purpose of the whole script is to show you the effect of running exactly the same SQL statement many times – first with the session cursor cache disabled (session_cached_cursors = 0) then with the cache enabled at its default size.

Here are some results from an instance of 12.2.0.1 – which I’ve edited down by eliminating most of the single-digit numbers.

=======================
No session cursor cache
=======================
---------------------------------
Session stats - 23-Apr 17:41:06
Interval:-  4 seconds
---------------------------------
Name                                                                         Value
----                                                                         -----
Requests to/from client                                                      1,002
opened cursors cumulative                                                    1,034
user calls                                                                   2,005
session logical reads                                                        9,115
non-idle wait count                                                          1,014
session uga memory                                                          65,488
db block gets                                                                2,007
db block gets from cache                                                     2,007
db block gets from cache (fastpath)                                          2,006
consistent gets                                                              7,108
consistent gets from cache                                                   7,108
consistent gets pin                                                          7,061
consistent gets pin (fastpath)                                               7,061
logical read bytes from cache                                           74,670,080
calls to kcmgcs                                                              5,005
calls to get snapshot scn: kcmgss                                            1,039
no work - consistent read gets                                               1,060
table scans (short tables)                                                   1,000
table scan rows gotten                                                       1,000
table scan disk non-IMC rows gotten                                          1,000
table scan blocks gotten                                                     1,000
buffer is pinned count                                                       2,000
buffer is not pinned count                                                   2,091
parse count (total)                                                          1,035
parse count (hard)                                                               8
execute count                                                                1,033
bytes sent via SQL*Net to client                                           338,878
bytes received via SQL*Net from client                                     380,923
SQL*Net roundtrips to/from client                                            1,003

PL/SQL procedure successfully completed.

---------------------------------
Library Cache - 23-Apr 17:41:06
Interval:-      4 seconds
---------------------------------
Type      Cache                           Gets        Hits Ratio        Pins        Hits Ratio   Invalid    Reload
----      -----                           ----        ---- -----        ----        ---- -----   -------    ------
NAMESPACE SQL AREA                       1,040       1,032   1.0       1,089       1,073   1.0         0         1
NAMESPACE TABLE/PROCEDURE                   17          16    .9         101          97   1.0         0         0
NAMESPACE BODY                               9           9   1.0          26          26   1.0         0         0
NAMESPACE SCHEDULER GLOBAL ATTRIBU          40          40   1.0          40          40   1.0         0         0

PL/SQL procedure successfully completed.

The thing to notice, of course, is the large number of statistics that are (close to) multiples of 1,000 – i.e. the number of executions of the SQL statement. In particular you can see the ~1,000 “parse count (total)” which is not reflected in the “parse count (hard)” because the statement only needed to be loaded into the library cache and optimized once.

The other notable statistics come from the library cache where we do 1,000 gets and pins on the “SQL AREA” – the “get” creates a “KGL Lock” (the “breakable parse lock”) that is made visible as an entry in v$open_cursor (x$kgllk), and the the “pin” created a “KGL Pin” that makes it impossible for anything to flush the child cursor from memory while we’re executing it.

So what changes when we enabled the session cursor cache:

============================
Session cursor cache enabled
============================

Session altered.

---------------------------------
Session stats - 23-Apr 17:41:09
Interval:-  3 seconds
---------------------------------
Name                                                                         Value
----                                                                         -----
Requests to/from client                                                      1,002
opened cursors cumulative                                                    1,004
user calls                                                                   2,005
session logical reads                                                        9,003
non-idle wait count                                                          1,013
db block gets                                                                2,000
db block gets from cache                                                     2,000
db block gets from cache (fastpath)                                          2,000
consistent gets                                                              7,003
consistent gets from cache                                                   7,003
consistent gets pin                                                          7,000
consistent gets pin (fastpath)                                               7,000
logical read bytes from cache                                           73,752,576
calls to kcmgcs                                                              5,002
calls to get snapshot scn: kcmgss                                            1,002
no work - consistent read gets                                               1,000
table scans (short tables)                                                   1,000
table scan rows gotten                                                       1,000
table scan disk non-IMC rows gotten                                          1,000
table scan blocks gotten                                                     1,000
session cursor cache hits                                                    1,000
session cursor cache count                                                       3
buffer is pinned count                                                       2,000
buffer is not pinned count                                                   2,002
parse count (total)                                                          1,002
execute count                                                                1,003
bytes sent via SQL*Net to client                                           338,878
bytes received via SQL*Net from client                                     380,923
SQL*Net roundtrips to/from client                                            1,003

PL/SQL procedure successfully completed.

---------------------------------
Library Cache - 23-Apr 17:41:09
Interval:-      3 seconds
---------------------------------
Type      Cache                           Gets        Hits Ratio        Pins        Hits Ratio   Invalid    Reload
----      -----                           ----        ---- -----        ----        ---- -----   -------    ------
NAMESPACE SQL AREA                           5           5   1.0       1,014       1,014   1.0         0         0
NAMESPACE TABLE/PROCEDURE                    7           7   1.0          31          31   1.0         0         0
NAMESPACE BODY                               6           6   1.0          19          19   1.0         0         0

PL/SQL procedure successfully completed.

The first thing to note is that “parse count (total)” still shows up 1,000 parse calls. However we also see the statistic “session cursor cache hits” at 1,000. Allowing for a little noise around the edges virtually every parse call has turned into a short-cut that takes us through the session cursor cache directly to the correct cursor.

This difference shows up in the library cache activity where we still see 1,000 pins – we have to pin the cursor to execute it – but we no longer see 1,000 “gets”. In the absence of the session cursor cache the session has to keep searching for the statement then creating and holding a KGL Lock while we execute the statement – but when the cache is enabled the session will very rapidly recognise that the statement is one we are likely to re-use, so it will continue to hold the KGL lock
after we have finished executing the statement and we can record the location of the KGL lock in a session state object. After the first couple of executions of the statement we no longer have to search for the statement and attach a spare lock to it, we can simply navigate from our session state object to the cursor.

As before, the KGL Lock will show up in v$open_cursor – though this time it will not disappear between executions of the statement. Over the history of Oracle versions the contents of v$open_cursor have become increasingly helpful, so I’ll just show you what the view held for my session by the end of the test:

SQL> select cursor_type, sql_text from V$open_cursor where sid = 250 order by cursor_type, sql_text;

CURSOR_TYPE                                                      SQL_TEXT
---------------------------------------------------------------- ------------------------------------------------------------
DICTIONARY LOOKUP CURSOR CACHED                                  BEGIN DBMS_OUTPUT.DISABLE; END;
DICTIONARY LOOKUP CURSOR CACHED                                  BEGIN snap_libcache.end_snap; END;
DICTIONARY LOOKUP CURSOR CACHED                                  BEGIN snap_my_stats.end_snap; END;
DICTIONARY LOOKUP CURSOR CACHED                                  SELECT DECODE('A','A','1','2') FROM SYS.DUAL
OPEN                                                             begin         dbms_application_info.set_module(
OPEN                                                             table_1_ff_2eb_0_0_0
OPEN-RECURSIVE                                                    SELECT VALUE$ FROM SYS.PROPS$ WHERE NAME = 'OGG_TRIGGER_OPT
OPEN-RECURSIVE                                                   select STAGING_LOG_OBJ# from sys.syncref$_table_info where t
OPEN-RECURSIVE                                                   update user$ set spare6=DECODE(to_char(:2, 'YYYY-MM-DD'), '0
PL/SQL CURSOR CACHED                                             SELECT INDX, KGLSTTYP LTYPE, KGLSTDSC NAME, KGLSTGET GETS, K
PL/SQL CURSOR CACHED                                             SELECT STATISTIC#, NAME, VALUE FROM V$MY_STATS WHERE VALUE !
SESSION CURSOR CACHED                                            BEGIN DBMS_OUTPUT.ENABLE(1000000); END;
SESSION CURSOR CACHED                                            BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
SESSION CURSOR CACHED                                            BEGIN snap_libcache.start_snap; END;
SESSION CURSOR CACHED                                            BEGIN snap_my_stats.start_snap; END;
SESSION CURSOR CACHED                                            select * from t1 where n1 = 0
SESSION CURSOR CACHED                                            select /*+ no_parallel */ spare4 from sys.optstat_hist_contr

17 rows selected.

The only one of specific interest is the penultimate one in the output – its type is “SESSION CURSOR CACHED” and we can recognise our “select from t1” statement.

Describe Upgrade

Here’s an odd little change between Oracle versions that could have a stunning impact on the application performance if the thing that generates your client code happens to use an unlucky selection of constructs.  It’s possible to demonstrate the effect remarkably easily – you just have to describe a table, doing it lots of times to make it easy to see what’s happening.

rem
rem     Script:         describe_18c.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Apr 2019
rem 

create table t1 as
select  *
from    all_objects
where   rownum = 1
;

set heading off
set feedback off
set pagesize 0
set linesize 156
set trimspool on
set termout off
set serveroutput on

execute snap_rowcache.start_snap
execute snap_libcache.start_snap

start start_10000
-- start_1 contains "describe t1"

set termout on
set serveroutput on

spool temp
execute snap_rowcache.end_snap
execute snap_libcache.end_snap

spool off

The start_10000 script is my mechanism for running a simple piece of code many times, and as the comment following it says, all I’m doing is repeating “describe t1”. The calls to “snap” something are examples of procedures I use to find the changes recorded in various dynamic performance views over short periods of time (there’s an example of the code for v$mystat here) In this case, as the names suggest, the snapshots record the changes in v$rowcache (the dictionary cache) and v$librarycache (the library cache). I’ve put a simple variant of the code at the end of the blog note so you don’t have to do all the preparation if you want to run a quick test for yourself.

Here are the results I get when running the test in Oracle 18.3.0.0

---------------------------------
Dictionary Cache - 05-Apr 19:00:00
Interval:-      27 seconds
---------------------------------
Parameter                 Sub# Usage Fixed    Gets  Misses   Scans  Misses    Comp    Mods Flushes
---------                ----- ----- -----    ----  ------   -----  --------------    ---- -------
dc_objects                         0     0 260,051       0       0       0       0       0       0
dc_users                           0     0 260,000       0       0       0       0       0       0
---------------------------------
Library Cache - 05-Apr 19:00:00
Interval:-      27 seconds
---------------------------------
Type      Description              Gets        Hits Ratio        Pins        Hits Ratio   Invalid    Reload
-----     -----                    ----        ---- -----        ----        ---- -----   -------    ------
NAMESPACE TABLE/PROCEDURE        10,003      10,003   1.0     280,028     280,028   1.0         0         0

Before showing you corresponding figures from 12.2.0.1 I’ll just point out that in version 18.3.0.0 of Oracle the structure of view all_objects gives me a table of 26 columns. Think about that and the 10,000 describes while looking at the number above, then look at the corresponding 12.2.0.1 results:

---------------------------------
Dictionary Cache - 05-Apr 19:00:00 
Interval:-      28 seconds
---------------------------------
Parameter                 Usage Fixed    Gets  Misses   Scans  Misses    Comp    Mods Flushes
---------                 ----- -----    ----  ------   -----  --------------    ---- -------
dc_users                      0     0       2       0       0       0       0       0       0
dc_objects                    0     0       9       0       0       0       0       0       0

---------------------------------
Library Cache - 05-Apr 19:04:17
Interval:-      28 seconds
---------------------------------
Type      Description              Gets        Hits Ratio        Pins        Hits Ratio   Invalid    Reload
-----     -----                    ----        ---- -----        ----        ---- -----   -------    ------
NAMESPACE TABLE/PROCEDURE        10,005      10,005   1.0      20,018      20,018   1.0         0         0

The internal mechanism of the “describe” call has changed between 12.2.0.1 to 18.3.0.0.

For each describe in 18.3, for each column in the table you see a “get” on dc_users and dc_objects in v$rowcache and you see one “get” on the TABLE/PROCEDURE namespace in v$librarycache, and (2 + number of columns) “pins”. In 12.2.0.1 there are no gets on the dictionary cache and only 1 get and two pins in the library cache for each describe.

As a couple of extra checks I modified the test to query from a 12c client to and 18c server, then from an 18c client to a 12c server. The big numbers appeared in the former test (i.e. when the server is 18c) and the small number for the latter (when the server is 12c). I also tried a couple of other variations on the theme:

• If the table t1 doesn’t exist when I run the test then there are no gets on the row cache, and I see 2 gets and pins (with hits) on the library cache per describe.
• If I run the test using “decribe other_schema.t1“ the pins (and hits) on the library cache go up by 1 per describe
• If I execute “alter session set current_schema = other_schema” so that “describe t1” is actually describing a table in another schema the pins (and hits) on the library cache go up by 1 per describe
• If I run the test in the SYS schema, 18c behaves like 12c !! But SYS is often a little wierd compared to other schemas

Enabling the 10051 trace – I can see that both versions report an OPI call type = 119: “V8 Describe Any” for each call to “describe” (which, presumably, corresponds to the OCIDescribeAny() low-level function call). And that’s really where this blog started, and why lots of people might need to be aware (at least in the short term) of this change in behaviour across versions .

Welcome to the Real World.

My demonstration is clearly silly – no-one does hundreds of describes per second in a real application, surely. Well, not deliberately, and not necessarily with the intent to do a full describe, but sometimes n-tier development environments end up generating code that does things you might not expect. One such example is the way that JDBC can handle a requirement of the form:

insert into tableX( id, ......) values (my_sequence.nextval, ...) returning id into ?;

In the course of handling this requirement one of the coding strategies available to JDBC ends up executing the type 119 “V8 Describe Any” call. Imagine the effect this has when you have a couple of dozen concurrent sessions totalling a couple of million single row inserts per hour. The competition for library cache pins and row cache gets is massive – and the memory structures involved are all protected by mutexes. So when a a client of mine recently upgraded their system from 11.2.0.4 to 18.3.0.0 they saw “library cache: mutex X” waits change from a few hundred seconds per hour to tens of thousands of seconds, and “row cache mutex” leaping up  from nowhere in the “Top timed events” to reporting further even more thousands of seconds of wait time per hour.

The actual impact of this issue will depend very strongly on how much use you (or your ORM) makes of this construct. The problem may be particularly bad for my client because of the very large number of concurrent executions of a very small number of distinct statements that all address the same table. For low concurrency, or for a wide range of different tables and statements, you may not see so much contention.

If you are seeing contention for “row cache mutex” and “library cache: mutex X”, then a quick corroborative test (if you are licensed for the performance and dianostic packs) is to check the top_level_call# and top_level_call_name from v$active_session_history:

select
        top_level_call#, top_level_call_name, count(*)
from    v$active_session_history
group by
        top_level_call#, top_level_call_name
order by
        count(*)

If (119, ‘V8 Describe Any’) shows up as a significant fraction of the total then you’re probably looking at this issue.

Java is not my strong point – but here’s a trivial piece of standalone Java that you can use to demonstrate the issue if you’re familiar with running Java on the server. There are a few notes inline to explain necessary preparatory steps and code changes:

/*
        To create a class file, you need to execute
        javac temptest2.java

        This generates file temptest2.class
        If this is successful then execute
        java temptest {number of iterations} {commit frequency}

        e.g.
        java temptest2 10000 10

        To be able to compile, you need a CLASSPATH environment variable
        e.g. export CLASSPATH=$CLASSPATH:$ORACLE_HOME/jdbc/lib/ojdbc8.jar

        For java to see the created class the CLASSPATH must also include 
        the holding directory
        e.g. export CLASSPATH=$CLASSPATH:/mnt/working

        Example combined setting:
        export CLASSPATH=$CLASSPATH:$ORACLE_HOME/jdbc/lib/ojdbc8.jar:/mnt/working

        A schema will need to be created to hold two objects,
        And the connection string in the code below will need to be modified -
        and the listener has to be started and the database registered to it.

        Database objects:
        -----------------
        create sequence s1;

        create table test(
                id number, 
                code varchar2(32), 
                descr varchar2(32), 
                insert_user varchar2(32),
                insert_date date
        );

*/


import java.sql.*;
import oracle.jdbc.OracleDriver;
import java.util.Date;

public class temptest2
{
  public static void main (String arr[]) throws Exception
  {
    DriverManager.registerDriver(new oracle.jdbc.OracleDriver());
    Connection con = DriverManager.getConnection
          ("jdbc:oracle:thin:@localhost:1521:or18","test_user","test");

    Integer iters = new Integer(arr[0]);
    Integer commitCnt = new Integer(arr[1]);

    con.setAutoCommit(false);
    doInserts( con, iters.intValue(), commitCnt.intValue() );

    con.commit();
    con.close();
  }

  static void doInserts(Connection con, int count, int commitCount )
  throws Exception
  {

    int  rowcnt = 0;
    int  committed = 0;
    long start = new Date().getTime();

    for (int i = 0; i < count; i++ ) {
      PreparedStatement ps = con.prepareStatement(
           "insert into test (id, code, descr, insert_user, insert_date) " +
                     "values (s1.nextval,?,?, user, sysdate)",
           new String[]{"id"}
      );
      ps.setString(1,"PS - code" + i);
      ps.setString(2,"PS - desc" + i);
      ps.executeUpdate();

      ResultSet rs = ps.getGeneratedKeys();
      int x = rs.next() ? rs.getInt(1) : 0;
      System.out.println(x);
                
      rowcnt++;
      ps.close();

      if ( rowcnt == commitCount )
      {
        con.commit();
        rowcnt = 0;
        committed++;
      }
    }
    long end = new Date().getTime();
    con.commit();
    System.out.println
    ("pstatement " + count + " times in " + (end - start) + " milli seconds committed = "+committed);
  }
}

/*
 *
 * Sample from trace file after setting events 10046 and 10051:
 *
 * OPI CALL: type=119 argc= 7 cursor=  0 name=V8 Describe Any
 * OPI CALL: type=94 argc=38 cursor=  0 name=V8 Bundled Exec
 * PARSE #140693461998224:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3884345238,tim=1368184246
 * EXEC #140693461998224:c=0,e=135,p=0,cr=0,cu=4,mis=0,r=1,dep=0,og=1,plh=3884345238,tim=1368184411
 * OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
 * CLOSE #140693461998224:c=0,e=15,dep=0,type=3,tim=1368185231
 * OPI CALL: type=14 argc= 0 cursor=  0 name=COMMIT
 * XCTEND rlbk=0, rd_only=0, tim=1368185291
 * OPI CALL: type=119 argc= 7 cursor=  0 name=V8 Describe Any
 * OPI CALL: type=94 argc=38 cursor=  0 name=V8 Bundled Exec
 * PARSE #140693461998224:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3884345238,tim=1368187929
 * EXEC #140693461998224:c=0,e=162,p=0,cr=0,cu=4,mis=0,r=1,dep=0,og=1,plh=3884345238,tim=1368188141
 * OPI CALL: type=105 argc= 2 cursor=  0 name=Cursor close all
 * CLOSE #140693461998224:c=0,e=6,dep=0,type=3,tim=1368189336
 * OPI CALL: type=14 argc= 0 cursor=  0 name=COMMIT
 * XCTEND rlbk=0, rd_only=0, tim=1368189373
 *
*/

You’ll notice that I’ve prepared, executed and closed a statement inside a loop. The problem wouldn’t happen if I prepared the statement before the loop and closed it after the loop, doing nothing but the execute inside the loop; but the code is simply modelling the “single row processing” effect that typically appears through ORMs.

You’ll have to decide for yourself how to take snapshots of the dynamic performance views while this code is running, and how to emable tracing – but anyone who want to fiddle with the code is probably better at coding Java than I am – so it’s left as an exercise to the reader (I used a logon trigger for the traces, and snap_rowcache and snap_libcache from another session).

There is a certain cruel irony to this issue.  For years I have been telling people that

    insert into my_table(id, ...) values(my_sequence.nextval,...) returning id into :bind1;

is more efficient than:

    select my_sequence.nextval into :bind1 from dual;
    insert into my_table(id,.....) values(:bind1, ...);

If, at present, you’re using  Hibernate as your ORM it generates code that does the (inefficient, bad practice) latter and you won’t see the “describe” problem.

Footnote

If you want a very simple SQL*Plus script to see the effect – and have privileges to query v$rowcache and v$librarycache – here’s a hundred describes with a little wrapper to show the effect:

em
rem     The schema running this script must not be SYS
rem     but must be granted select on v_$rowcache and
rem     v_$librarycache. For the results to be clearly
rem     visible the test needs to be run while virtually
rem     nothing else is running on the instance.
rem
rem     In 18.3.0.0 every describe seems to access 
rem     dc_users, dc_objects, and pin the library cache
rem     once for every column in the table described
rem     (plus a fixed "overhead" of 2 pins and one get)
rem
rem     When run by SYS the counts fall back to the
rem     12.2  numbers -i.e. only two pins and one get
rem     on the libraray cache with no accesses to the 
rem     dictionary cache
rem
rem     The excess gets and pins disappear in 19.2, 
rem     thought the pin count on the library cache 
rem     goes up to 4 per describe.
rem

drop table t1 purge;
create table t1(
        n1 number,
        n2 number,
        n3 number,
        n4 number,
        n5 number,
        n6 number,
        n7 number
)
;


-- variant create table t1 as select * from all_objects where rownum = 1;


set serveroutput off
set linesize 167
set trimspool on


spool temp_desc
select namespace, gets, pins from v$librarycache where namespace = 'TABLE/PROCEDURE';
select parameter, gets from v$rowcache where parameter in ('dc_users','dc_objects') and subordinate# is null;
spool off

set termout off

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1
describe t1

set termout on
set serveroutput on

spool temp_desc append

select namespace, gets, pins from v$librarycache where namespace = 'TABLE/PROCEDURE';
select parameter, gets from v$rowcache where parameter in ('dc_users','dc_objects') and subordinate# is null;

spool off



set doc off
doc

Sample output from 18.3
=======================
NAMESPACE                                                              GETS       PINS
---------------------------------------------------------------- ---------- ----------
TABLE/PROCEDURE                                                       27449      71108


PARAMETER                              GETS
-------------------------------- ----------
dc_users                              17341
dc_objects                           115830


NAMESPACE                                                              GETS       PINS
---------------------------------------------------------------- ---------- ----------
TABLE/PROCEDURE                                                       27555      72017


PARAMETER                              GETS
-------------------------------- ----------
dc_users                              18041
dc_objects                           116533


Note change in rowcache gets - one per column per describe on each parameter.
Note change in library cache pins - (one per column + 2) per describe.

Sample output from 12.2
=======================
NAMESPACE                  GETS       PINS
-------------------- ---------- ----------
TABLE/PROCEDURE           13393      20318


PARAMETER                              GETS
-------------------------------- ----------
dc_users                               4889
dc_objects                            31413


NAMESPACE                  GETS       PINS
-------------------- ---------- ----------
TABLE/PROCEDURE           13504      20539


PARAMETER                              GETS
-------------------------------- ----------
dc_users                               4889
dc_objects                            31416


No change in v$rowcache
Only the same single get and the "+2" pins per describe in v$librarycache

#

The good news is that I sent this text to a colleague who has access to Oracle 19, and the problem goes away (almost completley) – there are just two extra pins on the library cache in Oracle 19 compared to Oracle 12, and no gets on the rowcache dc_users and dc_objects. This suggests that it’s a known issue (even though there’s no visible bug report, and the problem is still present in 18.5) so it may be possible to get a backport of the version 19 code for vesion 18 fairly quickly. If not the best temporary workaround is probably to bypass the ORM and manually code for a function call that processes an anonymous PL/SQL block – but I haven’t tested that idea yet.

There is a JDBC cursor cache available – and if this were enabled than the prepared statement that was closed by the code would be kept open by the JDBC cache (and, of course, still be present in Oracle’s v$open_cursor) and Oracle wouldn’t receive any further parse or “describe” calls. Unfortunately it seems that there’s a cursor leak (still) in the JDBC caching algorithm that will lead to sessions hitting Oracle error “ORA-01000: maximum open cursors exceeded.”

Acknowledgements.

I’d particularly like to thank Lasse Jenssen who spent a couple of hours with me (when he could have been attending some interesting sessions) at the OUG Ireland conference a few days ago, working through various tests and strategies to pin down the problem and attempt to circumvent it. (Any criticism of the Java code above should, nevertheless be aimed at me).

Update

This problem is now visible on MoS as: Bug 29628952 : INCREASED ROW CACHE GETS ON DC_OBJECTS AND DC_USERS FOR DESCRIBE IN 18C AND LATER.

It’s also visible as Bug 29628647 : INCREASED GETS FOR DC_OBJECTS AND DC_USERS FOR DESCRIBE, unfortunately this latter bug has been associated with version 19.2 – where the problem doesn’t exist so the analyst has reported back (quite corretly) with “I see no problem.”

 

sys_op_lbid

I’ve made use of the function a few times in the past, for example in this posting on the dangers of using reverse key indexes, but every time I’ve mentioned it I’ve only been interested in the “leaf blocks per key” option. There are actually four different variations of the function, relevant to different types of index and controlled by setting a flag parameter to one of 4 different values.

The call to sys_op_lbid() take 3 parameters: index (or index [sub]partition object id, a flag vlaue, and a table “rowid”, where the flag value can be one of L, R, O, or G. The variations of the call are as follows:

• L – the function will return the row directory address  (i.e. something that look like a rowid) of the first index entry in the leaf block that holds the index entry for the referenced table rowid. The effect of this is that the number of distinct values returned by calling the function for every row in the table is equal to the number of index leaf blocks which current hold an active entry.
• R – Relevant only to bitmap indexes; the function will return the row directory address of the bitmap index entry for the referenced table rowid. The effect of this is that the number of distinct values returned by calling the function for every row in the table is equal to the number of index entries in the bitmap index.
• O – Relevent only to the primary key index of an index organized table with an overflow. The function is used with a non-key column instead of a rowid and returns a rowid that corresponds to the row directory entry in the overflow segment. An interesting detail of the overflow entries is that there is an “nrid” (next rowid) pointer in the primary key index entry that does not get deleted when all the columns in the related overflow entry are set null – so you can delete all the data from the overflow (set every overflow column in every row to null) and the primary key clustering factor would not change.
• G – Relevent only to secondary indexes on an index organized table. Like the L and R options this function takes a rowid (which is a special case for IOTs) as one of its inputs and uses the block guess from the secondary index to construct a row directory entry for the first entry in the primary key leaf block that corresponds to that block guess. This serves two purposes – it allows Oracle to calculate the clustering factor of the secondary index (as you walk the secondary index in order how much do you jump around the leaf blocks of the primary key), and it allows Oracle to produce the pct_direct_access figure for the secondary index by joining the secondary index to the primary key index on primary key, and comparing the ‘G’ result for the secondary with the ‘L’ result from the primary, which gives a count of the number of times the guess is correct.

These observations can be confirmed by gathering stats on different structures with trace enabled, and doing a couple of block dumps. For reference the following is just a simple script to create an index organized table with overflow and secondary index:

rem
rem     Script:         sys_op_lbid_2.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2018
rem

create table t1(
        id      constraint t1_pk primary key,
        v1      ,
        v2      ,
        v3      ,
        padding 
)
organization index
pctthreshold 2
overflow
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
        rownum,
        lpad(rownum,30),
        lpad(rownum,30),
        lpad(rownum,40),
        rpad('x',100,'x')
from
        generator       v1,
        generator       v2
where
        rownum <= 1e4 -- > comment to avoid WordPress format issue
;

create index t1_i1 on t1(v3);

alter session set sql_trace true;

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

alter session set sql_trace false;

select
        object_id, object_name
from
        user_objects
order by
        object_id
;

The significance of the query for object_id and data_object_id shows up in the trace file (and subsequent dumps) when Oracle uses one or other of the values in its SQL and rowid construction.

Here are the interesting SQL statements generated as the stats are gathered – but cosmetically altered to be reader-friendly. In order they are:

1. Stats for primary key of IOT: using the ‘L’ option for counting leaf blocks and the ‘O’ option for the clustering factor into overflow segment.
2. Stats for secondary index of IOT: using the ‘L’ option for counting leaf blocks and the ‘G’ option for the clustering factor into the primary key index
3. Calculate pct_direct_access: the ‘L’ option gives the actual leaf block in the primary key index, the ‘G’ option gives the leaf block guessed by the secondary index

select 
        /*+ index(t,t1_pk) */ 
        count(*) as nrw,
        count(distinct sys_op_lbid(351334,'L',t.rowid)) as nlb,
        null as ndk,
        (sys_op_lbid(351334,'O',V1),1) as clf
from
        t1 t 
where 
        id is not null
;


select 
        /*+ index(t,t1_i1) */ 
        count(*) as nrw,
        count(distinct sys_op_lbid(351335,'L',t.rowid)) as nlb,
        null as ndk,
        sys_op_countchg(sys_op_lbid(351335,'G',t.rowid),1) as clf
from
        t1 t 
where 
        v3 is not null
;


select
        case when count(*) = 0
                then 100
                else round(
                        count(
                                case when substr(gdba,7,9)=substr(lbid,7,9)
                                        then 1
                                        else null
                                end
                        )/count(*)*100
                )
        end
from    (
        select
                /*+
                        ordered
                        use_hash(i.t1 t2)
                        index_ffs(t2,t1_pk)
                */
                sys_op_lbid(351334,'L',t2.rowid) lbid,
                gdba
        from (
                select
                        /*+ index_ffs(t1,t1_i1) */
                        sys_op_lbid(351335,'G',t1.rowid) gdba,
                        t1.ID
                from
                        t1 t1
                ) i,
`               t1 t2
        where
                i.id = t2.id
        )
;

The strange substr(,7,9) that appears in the join between the primary key index and the secondary index is needed because the ‘G’ option uses the object_id of the table to turn an absolute block guess into a rowid while the ‘L’ option is using the data_object_id of the primary key index to turn its block addrss into a rowid. (This means there may be variants of this SQL for IOTs using partitioning.)

 

Append hint

One of the questions that came up on the CBO Panel Session at the UKOUG Tech2018 conference was about the /*+ append */ hint – specifically how to make sure it was ignored when it came from a 3rd party tool that was used to load data into the database. The presence of the hint resulted in increasing amounts of space in the table being “lost” as older data was deleted by the application which then didn’t reuse the space the inserts always went above the table’s highwater mark; and it wasn’t possible to change the application code.

The first suggestion aired was to create an SQL Patch to associate the hint /*+ ignore_optim_embedded_hints */ with the SQL in the hope that this would make Oracle ignore the append hint. This won’t work, of course, because the append hint is not an optimizer hint, it’s a “behaviour” hint.

There are, however, various things that will make the append hint invalid – sometimes to the great surprise of the people using it. The three things I can think of at present are:

• row-level triggers
• enabled foreign key constraints
• non-unique indexes enforcing unique constraints

It’s been some time since I last ran a detailed check so I’m not going to guarantee that the following claims are still true – if it matters to you then it’s easy enough to create a little test of (say) 10,000 rows inserted into a non-empty, indexed table.

• Row level triggers turn array processing into single row processing, so there’s a significant increase in redo generation.
• Non-unique indexes enforcing unique constraints have (small but) potentially undesirable effects on the optimizer and on run-time and may turn array processing into single row processing.
• Foreign key constraint require checking which may have some impact, but doesn’t turn array processing into single row processing.

Of the three options the foreign key constraint seemed to me to be the best strategy to disable the hint with minimal side effects, so my answer was:

“Create a new table with no data and a primary key constraint; add an invisible column to the target table, index it (online) and add a foreign key constraint from the column to the new table”.

My thinking on this was that the foreign key will disable the append hint. The column will always be null which means it will always satisfy the foreign key constraint without being checked and it won’t introduce any index maintenance overheads. Net effect: /*+ append */ is disabled with no extra overheads.

Footnote

The append hint is also ignored if the table is an Index Organized Table (IOT), but changing a heap table to an IOT is probably not a sensible choice if all you want to do is disable the hint – the potential for unexpected client side anomalies is too high, and if the table is heavily indexed the processing overhead for the secondary indexes could be fairly significant.

If I recall correctly the person asking the question said that the “do nothing” trigger option sounded like something they would be most comfortable with and they’d live with the overheads. I understand the feeling – an invisible column with an invisible index and extra foreign key constraint sounds too close to the boundary where mixing and matching simple features ends up hitting some unexpected behaviour (i.e. a bug).

Update 14th March 2019

A note on tweeter has reminded me that distributed transactions introduce another limitation.  Inserting across a database link will work only if the insert is into a local table; the first insert below will append, the second will not.

insert /*+ append */ into local_table select * from table@remote_location;

insert /*+ append */ into table@remote_location select * from local_table;

There are a couple more limitations given in the comments – disable table locking, and adding a security policy (VPD / RLS / FGAC / OLS).

DML Tablescans

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.

 

Row Migration

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.

 

 

Counting Rows

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

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.)

Index Splits – 3

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.

Index Splits – 2

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.

 

Index splits

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.

 

 

Direct IOT

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.

Validate FK

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).