Oracle Scratchpad

October 23, 2019

Clustering_Factor

Filed under: CBO,Indexing,Oracle — Jonathan Lewis @ 9:56 pm BST Oct 23,2019

A few days ago I published a little note of a script I wrote some time ago to estimate the clustering_factor of an index before it had been built. At the time I pointed out that one of its limitations was that it would not handle cases where you were planning to set the table_cached_blocks preference, but a couple of days later I decided that I’d write another version of the code that would cater for the new feature – and that’s how I made an embarrassing discovery.

Having reviewed a number of notes I’ve published about the table_cached_blocks preference and its impact on the clustering_factor I’ve realised the what I’ve written has always been open to two interpretations – the one that I had in mind as I was writing, and the correct one.  I made this discovery because I had written a simple SQL statement – using the match_recognize() mechanism – to do what I considered to  be the appropriate calculation. After testing the query with a few sets of sample data that produced the correct results I emailed Stew Ashton (my “go-to” person for match_recognize() questions) asking if he would do a sanity check on the code because it was rather slow and I wondered if there was a better way of writing it.

His reply was roughly:

“I’ve read the notes you and Richard Foote have written about the clustering_factor and table_cached_blocks, and this isn’t doing what your description says it should.”

Then he explained what he had inferred from what I had written … and it made more sense than what I had been thinking when I wrote it. He also supplied some code to implement his interpretation – so I designed a couple of data models that would produce the wrong prediction for whichever piece of code implemented the wrong interpretation. His code gave the right answers, mine didn’t.

So here’s the difference in interpretation – the wrong one first – using 16 as a discussion value for the table_cached_blocks:

  • WRONG interpretation:  As you walk through index entries in order remember the last 16 rowids (that’s rowid for the rows in the table that the index is pointing to) you’ve seen. If the current rowid has a block id component that doesn’t match the block id from one of the remembered 16 rowids then increment the counter for the clustering_factor.
    • The simplicity of this algorithm means you can fix a “circular” array of 16 entries and keep walking around the circle overwriting the oldest entry each time you read a new one. It’s a pity that it’s the wrong idea because there’s a simple (though massively CPU -intensive match_recognize() strategy for implementing it – and if you were using an internal library mechanism during a proper gather_index_stats() it could be incredibly efficient.
  • RIGHT interpretation: set up an array for 16 block ids, each with an associated “row-number”. Walk through the index in order – giving each entry a row-number as you go. Extract the block id from the current entry and search through the array for a matching block id.  If you find a match then update its entry with the current row-number (so you can remembr how recently you saw the block id); if you don’t find a match then replace the entry that has the smallest (i.e. greatest distance into the past) row-number with the current block id and row-number and increment the counter for the clustering_factor.

The first piece of code that Stew Ashton sent me was an anonymous PL/SQL block that included some hard-coded fragments and embedded SQL to use a test table and index that I had defined, but he then sent a second piece of code that creates a generic function that uses dynamic SQL to construct a query against a table and an index definition that you want to test. The latter is the code I’ve published (with permission) below:


create or replace function predict_clustering_factor(
/*
Function to predict the clustering factor of an index,
taking into account the intended value of
the TABLE_CACHED_BLOCKS parameter of DBMS_STATS.SET_TABLE_PREFS.

Input is the table name, the list of column names
and the intended value of TABLE_CACHED_BLOCKS.

The function collects the last N block ids (not the last N entries).
When there is no more room, it increments the clustering factor
and replaces the least recently used block id with the current one.

Note: here a "block id" is a rowid with the row_number portion set to 0.
It is effectively a "truncated" rowid.
*/
  p_table_name in varchar2,
  p_column_list in varchar2,
  p_table_cached_blocks in number
) return number authid current_user is

  rc sys_refcursor;
  type tt_rids is table of rowid;
  lt_rids tt_rids;
  
  type t_block_list is record(
    rid rowid,
    last_hit number
  );

  type tt_block_list is table of t_block_list;
  lt_block_list tt_block_list := new tt_block_list();

  l_rid rowid;
  l_clustering_factor number := 0;
  b_block_found boolean;
  l_rn number := 0;
  l_oldest_hit number;
  i_oldest_hit binary_integer := 0;
  
  function truncated_rid(p_rid in rowid) return rowid is
    rowid_type number;
    object_number NUMBER;
    relative_fno NUMBER;
    block_number NUMBER;
    row_number NUMBER;
    rid rowid;

  begin

    DBMS_ROWID.ROWID_INFO (
      p_rid,
      rowid_type,
      object_number,
      relative_fno,
      block_number,
      row_number
    );

    rid := DBMS_ROWID.ROWID_CREATE (
      rowid_type,
      object_number,
      relative_fno,
      block_number,
      0
    );

    return rid;

  end truncated_rid;
  
begin
  if p_table_cached_blocks != trunc(p_table_cached_blocks)
  or p_table_cached_blocks not between 1 and 255 then
    raise_application_error(
      -20001, 
      'input parameter p_table_cached_blocks must be an integer between 1 and 255'
    );
  end if;

  open rc for 'select rowid from '||p_table_name||' order by '||p_column_list||', rowid';
  loop
    fetch rc bulk collect into lt_rids limit 1000;

    for irid in 1..lt_rids.count loop
      l_rn := l_rn + 1;
      l_rid := truncated_rid(lt_rids(irid));
      b_block_found := false;
      l_oldest_hit := l_rn;

      if l_rn = 1 then
        l_clustering_factor := l_clustering_factor + 1;
        lt_block_list.extend;
        lt_block_list(1).rid := l_rid;
        lt_block_list(1).last_hit := l_rn;

      else

        for i in 1..lt_block_list.count loop
          if l_oldest_hit > lt_block_list(i).last_hit then
            l_oldest_hit := lt_block_list(i).last_hit;
            i_oldest_hit := i;
          end if;
          if lt_block_list(i).rid = l_rid then
            b_block_found := true;
            lt_block_list(i).last_hit := l_rn;
            exit;
          end if;
        end loop;

        if not b_block_found then
          l_clustering_factor := l_clustering_factor + 1;
          if lt_block_list.count < p_table_cached_blocks then
            lt_block_list.extend;
            lt_block_list(lt_block_list.count).rid := l_rid;
            lt_block_list(lt_block_list.count).last_hit := l_rn; 
          else         
            lt_block_list(i_oldest_hit).rid := l_rid;
            lt_block_list(i_oldest_hit).last_hit := l_rn;
          end if;
        end if;

      end if;

    end loop;
    exit when rc%notfound;
  end loop;

  close rc;
  return l_clustering_factor;

exception when others then
  if rc%isopen then
    close rc;
  end if;
  raise;

end predict_clustering_factor;
/

After executing the above to create the function, here’s an example of usage:

rem
rem     Script:         clustering_factor_est_2.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Oct 2019
rem
rem     Last tested
rem             19.3.0.0
rem             12.2.0.1
rem

create table t1
as
with generator as (
        select
                rownum id
        from dual
        connect by
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
        rownum                                  id,
        cast(rownum as varchar2(10))            v1,
        trunc(dbms_random.value(0,10000))       rand,
        rpad('x',100,'x')                       padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e6 -- > comment to avoid WordPress format issue
/

-- -------------------------------------------------------------------

SQL> execute dbms_output.put_line('Predicted cf for t1(rand, id): ' || predict_clustering_factor('t1','rand, id',16))
Predicted cf for t1(rand, id): 997218
Elapsed: 00:00:07.54

SQL> execute dbms_output.put_line('Predicted cf for t1(rand, id): ' || predict_clustering_factor('t1','rand, id',255))
Predicted cf for t1(rand, id): 985607
Elapsed: 00:00:50.61

You’ll notice that the larger the setting for the “table_cached_blocks” parameter the more time it takes to predict the clustering_factor – and it was all CPU time in my example. This isn;t surprising given the need to search through an array holding the previous history. In this example the table t1 holds 1,000,000 rows, and the number and scatter of distinct values is so arranged that the code will hardly ever find a cached block id – essentially it’s the sort of index that isn’t going to cause much of confusion to the optimizer and isn’t likely to need special attention to make the optimizer use it when it should and ignore it when it’s inappropriate.

Finally a cut-n-paste to show the accuracy of the two predictions:

SQL> create index t1_i on t1(rand, id);
Elapsed: 00:00:02.96

SQL> execute dbms_stats.set_table_prefs(null,'t1','table_cached_blocks',16)
Elapsed: 00:00:00.01

SQL> execute dbms_stats.gather_index_stats(null,'t1_i')
Elapsed: 00:00:09.55

SQL> select clustering_factor from user_indexes where index_name = 'T1_I';

CLUSTERING_FACTOR
-----------------
           997218

Elapsed: 00:00:00.11

SQL> execute dbms_stats.set_table_prefs(null,'t1','table_cached_blocks',255)
Elapsed: 00:00:00.01

SQL> execute dbms_stats.gather_index_stats(null,'t1_i')
Elapsed: 00:00:07.80

SQL> select clustering_factor from user_indexes where index_name = 'T1_I';

CLUSTERING_FACTOR
-----------------
           985607

Elapsed: 00:00:00.00

Both match perfectly – but you might notice that creating the index and gathering the stats was much faster than predicting the clustering factor for the case where we set table_cached_blocks = 255.

(If you’re wondering, my “simple but irrelevant” match_recognize() query took 370 CPU second to complete for table_cached_blocks = 200 – and a limit on march_recognize() meant that 200 was the maximum value I was allowed to use – so now you know why I emailed Stew Ashton (and just for lagniappe. he also told me about a simple workaround for the 200 limit)).

 

 

October 16, 2019

Clustering_Factor

Filed under: Indexing,Oracle — Jonathan Lewis @ 2:07 pm BST Oct 16,2019

Originally drafted July 2018

“How do you find out what the clustering_factor of an index would be without first creating the index ?”

I’m not sure this is really a question worth asking or answering[1], but since someone asked it (and given the draft date I have no idea who, where, when or why), here’s an answer for simple heap tables in the good old days before Oracle made public the table_cached_blocks preference. It works by sorting the columns you want in the index together with the table rowid, and then comparing the file/block component of the rowid (cutting the relevant characters from the string representation of the rowid) with the previous one to see if the current row is in the same block as the previous row.  If the row is in a different block we count one, otherwise zero.  Finally we sum the ones.

In the demo I’ve copied a little data from view all_objects, with the intention of creating an index on object_name. After running my counting query I’ve then created the index and checked its clustering_factor to show that I’ve got a match.


rem
rem     Script: clustering_factor_est.sql
rem     Author: J.P.Lewis
rem     Dated:  July 2018
rem

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

prompt  ====================
prompt  Tablescan with lag()
prompt  ====================

select
        sum(count_chg)
from    (
        select
                case
                        when substrb(rowid,1,15) <> lag(substrb(rowid,1,15),1,'000000000') over(order by object_name, rowid)
                                then 1
                                else 0
                end     count_chg
        from
                t1
        where
                object_name is not null
        )
;

prompt  ======================
prompt  create index and check
prompt  ======================

create index t1_i1 on t1(object_name);

select  clustering_factor
from    user_indexes 
where   table_name = 'T1'
and     index_name = 'T1_I1'
;

Pasting the output from running the above:


Table created.

====================
Tablescan with lag()
====================

SUM(COUNT_CHG)
--------------
          3901

1 row selected.

======================
create index and check
======================

Index created.


CLUSTERING_FACTOR
-----------------
             3901

1 row selected.


This will work for a global index on a partitioned table, but will give meaningless answers for globally partitioned indexes and local indexes. Furthermore it’s not a mechanism that lends itself to calculating the clustering_factor if you’ve set the table_cached_blocks preference to a value other than 1.

[1] Given the amount of work it would take to run the query to check the clustering_factor you might as well create the index (invisible, perhaps and nologging if that doesn’t cause problems) – which also gives you the option for setting the table_cached_blocks and gathering_stats to see how the clustering_factor varies.

Update (shortly after posting)

It has occurred to me that if you have a “nosegment” index that you’ve been using to test whether or not the optimizer would use it IF you created it, then the one piece of information that is missing from the data dicionary for that index is its clustering_factor (For a multicolumn index you can get a valid value for distinct_keys by creating a column group on the set of columns – which would otherwise be faked when you create the nosegment index.) This code might allow you to write a clustering_factor to the index definition that would give you a better idea of whether the optimizer would use it if you created it.  (To be tested.)

Update (a few days later)

I’ve modified the principle query in three ways:

  • changed the substr() to substrb()
  • changed the extract from the rowid to be (1,15) instead of (7,9) – so that I have the (data_object_id, file_id, block_id) not just (file_id, block_id)
  • added a (redundant) predicate  “object_name is not null” to the inline query

 

 

 

August 23, 2019

Optimizer Tricks 1

Filed under: CBO,Execution plans,Indexing,Oracle — Jonathan Lewis @ 12:39 pm BST Aug 23,2019

I’ve got a number of examples of clever little tricks the optimizer can do to transform your SQL before starting in on the arithmetic of optimisation. I was prompted to publish this one by a recent thread on ODC. It’s worth taking note of these tricks when you spot one as a background knowledge of what’s possible makes it much easier to interpret and trouble-shoot from execution plans. I’ve labelled this one “#1” since I may publish a few more examples in the future, and then I’ll have to catalogue them – but I’m not making any promises about that.

Here’s a table definition, and a query that’s hinted to use an index on that table.


rem
rem     Script:         optimizer_tricks_01.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Aug 2019
rem     Purpose:        
rem
rem     Last tested 
rem             19.3.0.0
rem             11.2.0.4
rem

create table t1 (
        v1      varchar2(10),
        v2      varchar2(10),
        v3      varchar2(10),
        padding varchar2(100)
);

create index t1_i1 on t1(v1, v2, v3);


explain plan for
select
        /*+ index(t1 (v1, v2, v3)) */
        padding 
from 
        t1
where
        v1 = 'ABC'
and     nvl(v3,'ORA$BASE') = 'SET2'
;

select * from table(dbms_xplan.display);

The query uses the first and third columns of the index, but wraps the 3rd column in an nvl() function. Because of the hint the optimizer will generate a plan with an index range scan, but the question is – what will the Predicate Information tell us about Oracle’s use of my two predicates:


Plan hash value: 3320414027

---------------------------------------------------------------------------------------------
| Id  | Operation                           | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |       |     1 |    66 |     0   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T1    |     1 |    66 |     0   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | T1_I1 |     1 |       |     0   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("V1"='ABC')
       filter(NVL("V3",'ORA$BASE')='SET2')

The nvl() test is used during the index range scan (from memory I think much older versions of Oracle would have postponed the predicate test until they had accessed the table itself). This means Oracle will do a range scan over the whole section of the index where v1 = ‘ABC’, testing every index entry it finds against the nvl() predicate.

But what happens if we modify column v3 to be NOT NULL? (“alter table t1 modify v3 not null;”) Here’s the new plan:


Plan hash value: 3320414027

---------------------------------------------------------------------------------------------
| Id  | Operation                           | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |       |     1 |    66 |     0   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T1    |     1 |    66 |     0   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | T1_I1 |     1 |       |     0   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("V1"='ABC' AND "V3"='SET2')
       filter("V3"='SET2')


The optimizer will decide that with the NOT NULL status of the column the nvl() function can be eliminated and the predicate can be replaced with a simple column comparison. At this point the v3 predicate can now be used to reduce the number of index entries that need to be examined by using a type of skip-scan/iterator approach, but Oracle still has to test the predciate against the index entries it walks through – so the predicate still appears as a filter predicate as well.

You might notice, by the way, that the Plan hash value does not change as the predicate use changes – even though the change in use of predicates could make a huge difference to the performance. (As indicated in the comments at the top of the script, I’ve run this model against 11.2.0.4 – which is the version used in the ODC thread – and 19.3.0.0: the behaviour is the same in both versions, and the Plan hash value doesn’t change from version to version.)

Footnote

The reason why I decided to publish this note is that the original thread on the ODC forums reported the Following contradictory details – an index definition and the optimizer’s use of that index as shown in the predicate section of the plan:


Index column name      Column position
---------------------- ----------------
FLEX_VALUE_SET_ID      1
PARENT_FLEX_VALUE      2
RANGE_ATTRIBUTE        3
CHILD_FLEX_VALUE_LOW   4
CHILD_FLEX_VALUE_HIGH  5
ZD_EDITION_NAME        6

---------------------------------------------------------------------------
|* 17 |      INDEX RANGE SCAN             | FND_FLEX_VALUE_NORM_HIER_U1   |
---------------------------------------------------------------------------
  17 - access("FLEX_VALUE_SET_ID"=:B1 AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET2')  
       filter((NVL("ZD_EDITION_NAME",'ORA$BASE')='SET2'  ..... lots more bits of filter predicate.

Since the expression nvl(zd_edition_name, ‘ORA$BASE’) = ‘SET2’ appears as an access predicate and a filter predicate it must surely be a column in the index. So either this isn’t the definition of the index being used or, somehow, there’s a trick that allows zd_edition_name to appear as a column name in the index when it really means nvl(zd_edition_name,’ORA$BASE’) at run-time. (And if there is I want to know what it is – edition-based redefinition and tricks with virtual columns spring to mind, but I avoid thinking about complicated explanations when a simpler one might be available.)

 

June 26, 2019

Glitches

Filed under: 12c,Bugs,Execution plans,Function based indexes,Indexing,Oracle — Jonathan Lewis @ 5:11 pm BST Jun 26,2019

Here’s a question just in from Oracle-L that demonstrates the pain of assuming things work consistently when sometimes Oracle development hasn’t quite finished a bug fix or enhancement. Here’s the problem – which starts from the “scott.emp” table (which I’m not going to create in the code below):

rem
rem     Script:         fbi_fetch_first_bug.sql
rem     Author:         Jonathan Lewis
rem     Dated:          June 2019
rem 

-- create and populate EMP table from SCOTT demo schema

create index e_sort1 on emp (job, hiredate);
create index e_low_sort1 on emp (lower(job), hiredate);

set serveroutput off
alter session set statistics_level = all;
set linesize 156
set pagesize 60

select * from emp where job='CLERK'         order by hiredate fetch first 2 rows only; 
select * from table(dbms_xplan.display_cursor(null,null,'cost allstats last outline alias'));

select * from emp where lower(job)='clerk' order by hiredate fetch first 2 rows only; 
select * from table(dbms_xplan.display_cursor(null,null,'cost allstats last outline alias'));

Both queries use the 12c “fetch first” feature to select two rows from the table. We have an index on (job, hiredate) and a similar index on (lower(job), hiredate), and given the similarity of the queries and the respective indexes (get the first two rows by hiredate where job/lower(job) is ‘CLERK’/’clerk’) we might expect to see the same execution plan in both cases with the only change being the choice of index used. But here are the plans:


select * from emp where job='CLERK'         order by hiredate fetch
first 2 rows only

Plan hash value: 92281638

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name    | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |         |      1 |        |     2 (100)|      2 |00:00:00.01 |       4 |
|*  1 |  VIEW                         |         |      1 |      2 |     2   (0)|      2 |00:00:00.01 |       4 |
|*  2 |   WINDOW NOSORT STOPKEY       |         |      1 |      3 |     2   (0)|      2 |00:00:00.01 |       4 |
|   3 |    TABLE ACCESS BY INDEX ROWID| EMP     |      1 |      3 |     2   (0)|      3 |00:00:00.01 |       4 |
|*  4 |     INDEX RANGE SCAN          | E_SORT1 |      1 |      3 |     1   (0)|      3 |00:00:00.01 |       2 |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=2)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "EMP"."HIREDATE")<=2)
   4 - access("JOB"='CLERK')


select * from emp where lower(job)='clerk' order by hiredate fetch
first 2 rows only

Plan hash value: 4254915479

-------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name        | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |             |      1 |        |     1 (100)|      2 |00:00:00.01 |       2 |       |       |          |
|*  1 |  VIEW                                 |             |      1 |      2 |     1   (0)|      2 |00:00:00.01 |       2 |       |       |          |
|*  2 |   WINDOW SORT PUSHED RANK             |             |      1 |      1 |     1   (0)|      2 |00:00:00.01 |       2 |  2048 |  2048 | 2048  (0)|
|   3 |    TABLE ACCESS BY INDEX ROWID BATCHED| EMP         |      1 |      1 |     1   (0)|      4 |00:00:00.01 |       2 |       |       |          |
|*  4 |     INDEX RANGE SCAN                  | E_LOW_SORT1 |      1 |      1 |     1   (0)|      4 |00:00:00.01 |       1 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=2)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "EMP"."HIREDATE")<=2)
   4 - access("EMP"."SYS_NC00009$"='clerk')


As you can see, with the “normal” index Oracle is able to walk the index “knowing” that the data is appearing in order, and stopping as soon as possible (almost) – reporting the WINDOW operation as “WINDOW NOSORT STOPKEY”. On the other hand with the function-based index Oracle retrieves all the data by index, sorts it, then applies the ranking requirement – reporting the WINDOW operation as “WINDOW SORT PUSHED RANK”.

Clearly it’s not going to make a lot of difference to performance in this tiny case, but there is a threat that the whole data set for ‘clerk’ will be accessed – and that’s the first performance threat, with the additional threat that the optimizer might decide that a full tablescan would be more efficient than the index range scan.

Can we fix it ?

Yes, Bob, we can. The problem harks back to a limitation that probably got fixed some time between 10g and 11g – here are two, simpler, queries against the emp table and the two new indexes, each with the resulting execution plan when run under Oracle 10.2.0.5:


select ename from emp where       job  = 'CLERK' order by hiredate;
select ename from emp where lower(job) = 'clerk' order by hiredate;

---------------------------------------------------------------------------------------
| Id  | Operation                   | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |         |     3 |    66 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| EMP     |     3 |    66 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | E_SORT1 |     3 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("JOB"='CLERK')


--------------------------------------------------------------------------------------------
| Id  | Operation                    | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |             |     3 |    66 |     3  (34)| 00:00:01 |
|   1 |  SORT ORDER BY               |             |     3 |    66 |     3  (34)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| EMP         |     3 |    66 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | E_LOW_SORT1 |     3 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access(LOWER("JOB")='clerk')

The redundant SORT ORDER BY is present in 10g even for a simple index range scan. By 11.2.0.4 the optimizer was able to get rid of the redundant step, but clearly there’s a little gap in the code relating to the over() clause that hasn’t acquired the correction – even in 18.3.0.0 (or 19.2 according to a test on https://livesql.oracle.com).

To fix the 10g problem you just had to include the first column of the index in the order by clause: the result doesn’t change, of course, because you’re simply prefixing the required columns with a column which holds the single value you were probing the index for but suddenly the optimizer realises that it can do a NOSORT operation – so the “obvious” guess was to do the same for this “first fetch” example:

select * from emp where lower(job)='clerk' order by lower(job), hiredate fetch first 2 rows only;

--------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name        | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |             |      1 |        |     3 (100)|      2 |00:00:00.01 |       4 |
|*  1 |  VIEW                         |             |      1 |      2 |     3  (34)|      2 |00:00:00.01 |       4 |
|*  2 |   WINDOW NOSORT STOPKEY       |             |      1 |      1 |     3  (34)|      2 |00:00:00.01 |       4 |
|   3 |    TABLE ACCESS BY INDEX ROWID| EMP         |      1 |      1 |     2   (0)|      3 |00:00:00.01 |       4 |
|*  4 |     INDEX RANGE SCAN          | E_LOW_SORT1 |      1 |      1 |     1   (0)|      3 |00:00:00.01 |       2 |
--------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("from$_subquery$_002"."rowlimit_$$_rownumber"<=2)
   2 - filter(ROW_NUMBER() OVER ( ORDER BY "EMP"."SYS_NC00009$","EMP"."HIREDATE")<=2)
   4 - access("EMP"."SYS_NC00009$"='clerk')

It’s just one of those silly little details where you can waste a HUGE amount of time (in a complex case) because it never crossed your mind that something that clearly ought to work might need testing for a specific use case – and I’ve lost count of the number of times I’ve been caught out by this type of “not quite finished” anomaly.

Footnote

If you follow the URL to the Oracle-L thread you’ll see that Tanel Poder has supplied a couple of MoS Document Ids discussing the issue and warning of other bugs with virtual column / FBI translation, and has shown an alternative workaround that takes advantage of a hidden parameter.

 

May 29, 2019

Timestamp Oddity

Filed under: Function based indexes,Indexing,Oracle — Jonathan Lewis @ 6:17 pm BST May 29,2019

[Editorial note: this is something I started writing in 2013, managed to complete in 2017, and still failed to publish. It should have been a follow-on to another posting on the oddities of timestamp manipulation.]

Just as national language support used to be, timestamps and time-related columns are still a bit of a puzzle to the Oracle world – so much so that OEM could cripple a system if it was allowed to do the check for “failed logins over the last 30 minutes”. And, just like NLS, it’s one of those things that you use so rarely that you keep forgetting what went wrong the last time you used it. Here’s one little oddity that I reminded myself about recently:

rem
rem     Script:         timestamp_anomaly.sql
rem     Author:         Jonathan Lewis
rem     Dated:          April 2013
rem
create table t1 (
        ts_tz   timestamp(9) with time zone,
        ts_ltz  timestamp(9) with local time zone
);

insert into t1 values(systimestamp, systimestamp);
commit;

alter table t1 add constraint ts_ltz_uk unique (ts_ltz);
alter table t1 add constraint ts_tz_uk  unique (ts_tz);


Nothing terribly difficult – just a table with two variants on the timestamp data type and a unique constraint on both: except for one problem. Watch what happens as I create the unique constraints:

SQL> alter table t1 add constraint ts_ltz_uk unique (ts_ltz);

Table altered.

SQL> alter table t1 add constraint ts_tz_uk  unique (ts_tz);
alter table t1 add constraint ts_tz_uk  unique (ts_tz)
                                        *
ERROR at line 1:
ORA-02329: column of datatype TIME/TIMESTAMP WITH TIME ZONE cannot be unique or a primary key

Slightly unexpected – unless you’ve memorized the manuals, of course, which I hadn’t. I wonder if you can create a unique index on timestamp with time zone:


SQL> create unique index ts_tz_uk on t1(ts_tz);

Index created.

You can’t have a unique constraint, but you CAN create a unique index! How curious – did that really happen ?

SQL> select index_name, column_name from user_ind_columns where table_name = 'T1';

INDEX_NAME           COLUMN_NAME
-------------------- --------------------
TS_LTZ_UK            TS_LTZ
TS_TZ_UK             SYS_NC00003$

The index is on a column called SYS_NC00003$ – which looks suspiciously like one of those “function-based-index” things:


SQL> select * from user_ind_expressions where table_name = 'T1';

INDEX_NAME           TABLE_NAME           COLUMN_EXPRESSION                        COLUMN_POSITION
-------------------- -------------------- ---------------------------------------- ---------------
TS_TZ_UK             T1                   SYS_EXTRACT_UTC("TS_TZ")                               1

Oracle has silently invoked the sys_extract_utc() function on our (free-floating) timestamp column to normalize it to UTC. This is really not very friendly but it does make sense, of course – it would be rather expensive to enforce uniqueness if there were (at least) 24 different ways of storing the same absolute value – and 24 is a conservative estimate.

 

 

March 11, 2019

sys_op_lbid

Filed under: Indexing,Infrastructure,IOT,Oracle,Statistics — Jonathan Lewis @ 1:23 pm GMT Mar 11,2019

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

 

January 31, 2019

Descending Problem

Filed under: Execution plans,Indexing,Oracle,Performance,Troubleshooting — Jonathan Lewis @ 3:34 pm GMT Jan 31,2019

I’ve written in the past about oddities with descending indexes ( here, here, and here, for example) but I’ve just come across a case where I may have to introduce a descending index that really shouldn’t need to exist. As so often happens it’s at the boundary where two Oracle features collide. I have a table that handles data for a large number of customers, who record a reasonable number of transactions per year, and I have a query that displays the most recent transactions for a customer. Conveniently the table is partitioned by hash on the customer ID, and I have an index that starts with the customer_id and transaction_date columns. So here’s my query or, to be a little more accurate, the client’s query – simplified and camouflaged:


select  /*+ gather_plan_statistics */
        *
from    (
             select
                    v1.*,
                    rownum rn
             from   (
                             select   /*
                                         no_eliminate_oby
                                         index_rs_desc(t1 (customer_id, transaction_date))
                                      */
                                      t1.*
                             from     t1
                             where    customer_id = 50
                             and      transaction_date >= to_date('1900-01-01','yyyy-mm-dd')
                             order by transaction_date DESC
                ) v1
                where  rownum <= 10 -- > comment to avoid WordPress format issue
         )
where    rn >= 1
;

You’ll notice some hinting – the /*+ gather_plan_statistics */ will allow me to report the rowsource execution stats when I pull the plan from memory, and the hints in the inline view (which I’ve commented out in the above) will force a particular execution plan – walking through the index on (company_id, transaction_date) in descending order.

If I create t1 as a simple (non-partitioned) heap table I get the following plan unhinted (I’ve had to edit a “less than or equal to” symbol to avoid a WordPress format issue):

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                |       |      1 |        |    14 (100)|     10 |00:00:00.01 |      14 |
|*  1 |  VIEW                           |       |      1 |     10 |    14   (0)|     10 |00:00:00.01 |      14 |
|*  2 |   COUNT STOPKEY                 |       |      1 |        |            |     10 |00:00:00.01 |      14 |
|   3 |    VIEW                         |       |      1 |     10 |    14   (0)|     10 |00:00:00.01 |      14 |
|   4 |     TABLE ACCESS BY INDEX ROWID | T1    |      1 |    340 |    14   (0)|     10 |00:00:00.01 |      14 |
|*  5 |      INDEX RANGE SCAN DESCENDING| T1_I1 |      1 |     10 |     3   (0)|     10 |00:00:00.01 |       4 |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN">=1)
   2 - filter(ROWNUM .LE. 10)
   5 - access("CUSTOMER_ID"=50 AND "TRANSACTION_DATE" IS NOT NULL AND "TRANSACTION_DATE">=TO_DATE('
              1900-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))


Notice the descending range scan of the index – just as I wanted it – the minimal number of buffer visits, and only 10 rows (and rowids) examined from the table. But what happens if I recreate t1 as a hash-partitioned table with local index – here’s the new plan, again without hinting the SQL:


----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                      | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                               |       |      1 |        |   207 (100)|     10 |00:00:00.01 |     138 |       |       |          |
|*  1 |  VIEW                                          |       |      1 |     10 |   207   (1)|     10 |00:00:00.01 |     138 |       |       |          |
|*  2 |   COUNT STOPKEY                                |       |      1 |        |            |     10 |00:00:00.01 |     138 |       |       |          |
|   3 |    VIEW                                        |       |      1 |    340 |   207   (1)|     10 |00:00:00.01 |     138 |       |       |          |
|*  4 |     SORT ORDER BY STOPKEY                      |       |      1 |    340 |   207   (1)|     10 |00:00:00.01 |     138 |  2048 |  2048 | 2048  (0)|
|   5 |      PARTITION HASH SINGLE                     |       |      1 |    340 |   206   (0)|    340 |00:00:00.01 |     138 |       |       |          |
|   6 |       TABLE ACCESS BY LOCAL INDEX ROWID BATCHED| T1    |      1 |    340 |   206   (0)|    340 |00:00:00.01 |     138 |       |       |          |
|*  7 |        INDEX RANGE SCAN                        | T1_I1 |      1 |    340 |     4   (0)|    340 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN">=1)
   2 - filter(ROWNUM. LE. 10)
   4 - filter(ROWNUM .LE. 10)
   7 - access("CUSTOMER_ID"=50 AND "TRANSACTION_DATE">=TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND "TRANSACTION_DATE" IS NOT NULL)

Even though the optimizer has recognised that is will be visiting a single partition through a local index it has not chosen a descending index range scan, though it has used the appropriate index; so it’s fetched all the relevant rows from the table in the wrong order then sorted them discarding all but the top 10. We’ve done 138 buffer visits (which would turn into disk I/Os, and far more of them, in the production system).

Does this mean that the optimizer can’t use the descending index when the table is partitioned – or that somehow the costing has gone wrong. Here’s plan with the hints in place to see what happens when we demand a descending range scan:


----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name  | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |       |      1 |        |   207 (100)|     10 |00:00:00.01 |       8 |
|*  1 |  VIEW                                 |       |      1 |     10 |   207   (1)|     10 |00:00:00.01 |       8 |
|*  2 |   COUNT STOPKEY                       |       |      1 |        |            |     10 |00:00:00.01 |       8 |
|   3 |    VIEW                               |       |      1 |    340 |   207   (1)|     10 |00:00:00.01 |       8 |
|   4 |     PARTITION HASH SINGLE             |       |      1 |    340 |   206   (0)|     10 |00:00:00.01 |       8 |
|   5 |      TABLE ACCESS BY LOCAL INDEX ROWID| T1    |      1 |    340 |   206   (0)|     10 |00:00:00.01 |       8 |
|*  6 |       INDEX RANGE SCAN DESCENDING     | T1_I1 |      1 |    340 |     4   (0)|     16 |00:00:00.01 |       3 |
----------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN">=1)
   2 - filter(ROWNUM .LE. 10)
   6 - access("CUSTOMER_ID"=50 AND "TRANSACTION_DATE" IS NOT NULL AND "TRANSACTION_DATE">=TO_DATE('
              1900-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

The optimizer is happy to oblige with the descending range scan – we can see that we’ve visited only 8 buffers, and fetched only 10 rows from the table. The cost, however, hasn’t made any allowance for the limited range scan. Check back to the plan for the simple (non-partitioned) table and you’ll see that the optimizer did allow for the reduced range scan. So the problem here is a costing one – we have to hint the index range scan if we want Oracle limit the work it does.

You might notice, by the way that the number of rowids returned in the index range scan descending operation is 16 rather than 10 – a little variation that didn’t show up when the table wasn’t partitioned. I don’t know why this happened, but when I changed the requirement to 20 rows the range scan returned 31 rowids, when I changed it to 34 rows the range scan returned 46 rows, and a request for 47 rows returned 61 index rowids – you can see the pattern, the number of rowids returned by the index range scan seems to be 1 + 15*N.

Footnote:

If you want to avoid hinting the code (or adding an SQL patch) you need only re-create the index with the transaction_date column declared as descending (“desc”), at which point the optimizer automatically chooses the correct strategy and the run-time engine returns exactly 10 rowids and doesn’t need to do any sorting. But who wants to create a descending index when they don’t really need it !

If you want to reproduce the experiments, here’s the script to create my test data.


rem
rem     Script:         pt_ind_desc_bug.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2018
rem     Purpose:        
rem
rem     Last tested 
rem             18.3.0.0
rem             12.2.0.1
rem             12.1.0.2
rem

create table t1 (
        customer_id,
        transaction_date,
        small_vc,
        padding 
)
partition by hash(customer_id) partitions 4
nologging
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
        mod(rownum,128)                         customer_id,
        (trunc(sysdate) - 1e6) + rownum         transaction_date,
        lpad(rownum,10,'0')                     v1,
        lpad('x',100,'x')                       padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e6 -- > comment to avoid WordPress format issue
;

create index t1_i1 on t1(customer_id, transaction_date) 
local 
nologging
;

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

I’ve run this test on 12.1.0.2, 12.2.0.1, and 18.3.0.0 – the behaviour is the same in all three versions.

Update (1st Feb 2019)

As the client reminded me after reading the post, it’s worth pointing out that for more complex SQL you still have to worry about the errors in the cardinality and cost calculations that could easily push the optimizer into the wrong join order and/or join method – whether you choose to hint the ascending index or create a descending index.  Getting the plan you want for this type of “pagination” query can be a messy process.

December 18, 2018

NULL predicate

Filed under: CBO,Execution plans,Indexing,Oracle — Jonathan Lewis @ 1:13 pm GMT Dec 18,2018

People ask me from time to time if I’m going to write another book on the Cost Based Optimizer – and I think the answer has to be no because the product keeps growing so fast it’s not possible to keep up and because there are always more and more little details that might have been around for years and finally show up when someone asks me a question about some little oddity I’ve never noticed before.

The difficult with the “little oddities” is the amount of time you could spend trying to work out whether or not they matter and if it’s worth writing about them. Here’s a little example to show what I mean – first the data set:


rem
rem     Script:         null_filter.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Dec 2018
rem     Purpose:
rem
rem     Last tested
rem             18.3.0.0
rem             12.1.0.2
rem

create table t1
nologging
as
select  *
from    all_objects
where   rownum <= 50000 -- > comment to avoid wordpress format issue
;

insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
commit;

create index t1_i1 on t1(object_type, data_object_id, object_id, created);

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

It’s a simple data set with a single index. The only significant thing about the index is that the second column (data_object_id) is frequently null. This leads to a little quirk in the execution plans for a very similar pair of statements:


set serveroutput off
alter session set statistics_level = all;

select
        object_name, owner
from
        t1
where
        object_type = 'TABLE'
and     data_object_id = 20002
and     object_id = 20002
and     created > trunc(sysdate - 90)
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

select
        object_name, owner
from
        t1
where
        object_type = 'TABLE'
and     data_object_id is null
and     object_id = 20002
and     created > trunc(sysdate - 90)
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

How much difference would you expect in the execution plans for these two queries? There is, of course, the side effect of the “is null” predicate disabling the “implicit column group” that is the index distinct_keys value, but in this case I’ve got a range-based predicate on one of the columns so Oracle won’t be using the distinct_keys anyway.

Of course there’s the point that you can’t use the equality operator with null, you have to use “is null” – and that might make a difference, but how? Here are the two execution plan:


----------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |       |      1 |        |      0 |00:00:00.01 |       3 |      1 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T1    |      1 |      1 |      0 |00:00:00.01 |       3 |      1 |
|*  2 |   INDEX RANGE SCAN                  | T1_I1 |      1 |      1 |      0 |00:00:00.01 |       3 |      1 |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("OBJECT_TYPE"='TABLE' AND "DATA_OBJECT_ID"=20002 AND "OBJECT_ID"=20002 AND
              "CREATED">TRUNC(SYSDATE@!-90))

-------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |       |      1 |        |      0 |00:00:00.01 |       3 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T1    |      1 |      1 |      0 |00:00:00.01 |       3 |
|*  2 |   INDEX RANGE SCAN                  | T1_I1 |      1 |      1 |      0 |00:00:00.01 |       3 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("OBJECT_TYPE"='TABLE' AND "DATA_OBJECT_ID" IS NULL AND "OBJECT_ID"=20002 AND
              "CREATED">TRUNC(SYSDATE@!-90))
       filter(("OBJECT_ID"=20002 AND "CREATED">TRUNC(SYSDATE@!-90)))

The query with the predicate “data_object_id is null” repeats the object_id and sysdate predicates as access predicates and filter predicates. This seems a little surprising and a potential performance threat. In the first query the run_time engine will hit the correct index leaf block in exactly the right place very efficiently and then walk along it supplying every rowid to the parent operator until it hits the end of the range.

With the “is null” plan the run-time engine will be checking the actual value of object_id and created for every index entry on the way – how much extra CPU will this use and, more importantly, might Oracle start with the first index entry where object_type = ‘TABLE’ and data_object_id is null and walk through every index entry that has that null checking for the correct object_id as it goes ?

That last question is the reason for running the query with rowsource execution stats enabled. The first query did a single physical read while the second didn’t have to, but the more important detail is that both queries did the same number of buffer gets – and there is, by the way, a set of eight rows where the object_id and data_object_id are  20,002, but they were created several years ago so the index range scan returns no rows in both cases.

Based on that comparison, how do we show that Oracle has not walked all the way from the first index entry where object_type = ‘TABLE’ and data_object_id is null checking every entry on the way or, to put it another way, has Oracle really managed to prune down the index range scan to the minimum “wedge” indicated by the presence of the predicates “OBJECT_ID”=20002 AND “CREATED”>TRUNC(SYSDATE@!-90) as access predicates?

Let’s just count the number of leaf blocks that might be relevant, using the sys_op_lbid() function (last seen here) that Oracle uses internally to count the number of leaf blocks in an index. First we get the index object_id, then we scan it to see how many leaf blocks hold entries that match our object_type and data_object_id predicates but appear in the index before our target value of 20,002:


column object_id new_value m_index_id

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

select  distinct sys_op_lbid(&m_index_id, 'L', rowid)
from    t1
where   object_type    = 'TABLE'
and     data_object_id is null
and     object_id      < 20002
;


SYS_OP_LBID(159271
------------------
AAAm4nAAFAAACGDAAA
AAAm4nAAFAAACF9AAA
AAAm4nAAFAAACGCAAA
AAAm4nAAFAAACF/AAA
AAAm4nAAFAAACF+AAA
AAAm4nAAFAAACGFAAA
AAAm4nAAFAAACGEAAA
AAAm4nAAFAAACGGAAA

8 rows selected.


This tells us that there are 8 leaf blocks in the index that we would have to range through before we found object_id 20,002 and we would have seen 8 buffer gets, not 3 in the rowsource execution stats, if Oracle had not actually been clever with its access predicates and narrowed down the wedge of the index it was probing.

Bottom line: for a multi-column index there seems to be a difference in execution plans between “column is null” and “column = constant” when the column is one of the earlier columns in the index – but even though the “is null” option results in some access predicates re-appearing as filter predicates in the index range scan the extra workload is probably not significant – Oracle still uses the minimum number of index leaf blocks in the index range scan.

Update (May 2019)

Randolf Geist has written a blog note that extends this pattern to something that introduces a much bigger threat of a performance issue even though the SQL is only marginally more complex than the example above.

 

November 30, 2018

Index rebuild bug

Filed under: Bugs,Indexing,Oracle — Jonathan Lewis @ 1:02 pm GMT Nov 30,2018

I tweeted a reference yesterday to a 9 year old article about index rebuilds, and this led me on to look for an item that I thought I’d written on a related topic. I hadn’t written it (so there’s another item on my todo list) but I did discover a draft I’d written a few years ago about an unpleasant side effect relating to rebuilding subpartitions of local indexes on composite partitoned tables. It’s probably the case that no-one will notice they’re suffering from it because it’s a bit of an edge case – but you might want to review the things your system does.

Here’s the scenario: you have a large table that is composite partitioned with roughly 180 daily partitions and 512 subpartitions (per partition). For some strange reason you have a couple of local indexes on the table that have been declared unusable – hoping, perhaps, that no-one ever does anything that makes Oracle decide to rebuild all the unusable bits.

One day you decide to rebuild just one subpartition of one of the indexes that isn’t marked as unusable. You might be planning to rebuild every single subpartition of that index overnight, but you’re going to start with just one to see how long it takes. Something very strange happens – and here’s a simple model to demonstrate:

rem
rem     Script:         index_rebuild_pt_bug.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Feb 2015
rem
rem     Last tested
rem             18.3.0.0
rem             12.1.0.1
rem             11.2.0.4
rem

create table interval_hash (
        n1 number,
        n2 number,
        n3 number
)
segment creation immediate
partition by range(n1) interval (1)
subpartition by hash (n2) subpartitions 16 (
        partition p1 values less than (2) 
)
;


begin
        for i in 1 .. 16 loop
                for j in 1..64 loop
                        insert into interval_hash i(n1, n2, n3) values (i, j, j + 64*(i-i));
                end loop;
        end loop;

        commit;
end;
/

create index ih_i1 on interval_hash(n1) local;
create index ih_i2 on interval_hash(n2) local;
create index ih_i3 on interval_hash(n3) local;

alter index ih_i1 unusable;
alter index ih_i2 unusable;

The code creates a table which extends as data arrives to have 16 partitions with 16 subpartitions each – for a total of 256 data segments. After loading the data I’ve created 3 local indexes on the table and made two of them unusable.

After setting up the table and indexes I’ve identified one subpartition of the table by name, enabled tracing, and rebuilt the corresponding subpartition of the index which is currently usable (the same effect appears if I rebuild a partition of one of the unusable indexes, but the phenomenon is slightly more surprising if you rebuild a usable subpartition). Here’s the code for the rebuild:


column max_subp new_value m_subp

select
        max(partition_name) max_subp
from
        user_segments
where
        segment_name = 'INTERVAL_HASH'
;

alter session set events '10046 trace name context forever, level 4';

alter index ih_i3 rebuild subpartition &m_subp;

alter session set events '10046 trace name context off';

Would you expect to find anything interesting in the trace file after running it through tkprof ? Here’s the most frequently executed SQL statement I found when running this test on an instance of Oracle 18.3:


tkprof or18_ora_24939.trc temp sort=execnt

SQL ID: 0yn07bvqs30qj Plan Hash: 866645418

select pctfree_stg, pctused_stg, size_stg,initial_stg, next_stg, minext_stg,
  maxext_stg, maxsiz_stg, lobret_stg,mintim_stg, pctinc_stg, initra_stg,
  maxtra_stg, optimal_stg, maxins_stg,frlins_stg, flags_stg, bfp_stg, enc_stg,
   cmpflag_stg, cmplvl_stg,imcflag_stg, ccflag_stg, flags2_stg
from
 deferred_stg$  where obj# =:1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    512      0.02       0.03          0          0          0           0
Fetch      512      0.00       0.00          0       1536          0         512
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1025      0.03       0.03          0       1536          0         512

This query runs once for every single subpartition of the two unusable indexes. (There’s another statement that runs once for every partition of the two unusable indexes to provide the object numbers of the subpartitions and that shouldn’t be forgotten). In my example the impact and time to run doesn’t look too bad – but when the numbers climb to a couple of hundred thousand executions before you start to rebuild the first subpartition you might start to worry. Depending on the state of your data dictionary, and how you got to the point where you had so many unusable segments, the time to execute could become large, and you might do most of it all over again for the next subpartition!

You might wonder why anyone would have a couple of unusable indexes. First, many years ago (in Practival Oracle 8i) I pointed out that if you wanted to create a new locally partitioned index you might want to create it unusable and then rebuild each partition in turn – that might not be a good idea any more. (The book also pointed out the requirement to think about sizing the dictionary cache (rowcache)).

Secondly, before the introduction of partial indexing it was possible to emulate the feature manually for local indexes by setting partitions and subpartition unusable and allowing the optimizer to use table expansion to pick the best plan for partitions that had different index partitions still usable.

Finally if you are using the new partial indexing feature of 12.2 where you can set the default characteristic of a partitioned table to “indexing off”, and the default characteristic of an index to “indexing partial”, the partitions of any local index that are not created are deemed to be deferred – but you won’t see the effect in my example unless you modify it to include partial indexes and include an “alter system flush shared pool” just before the rebuild.

Footnote

I’ve found this bug (or something very similar) on MoS: Bug 17335646 : ALTER INDEX IDX REBUILD SUBPARTITION SP VISITS EVERY INDEX AND SUBPARTION. However the bug was recorded against 11.2.0.3 and its status is: “31 – Could Not Reproduce. To Filer”. It does seem to be terribly easy to reproduce, though, provided you have a large number of unusable subpartitions in your indexes – so it’s possible the original bug appeared even when there were no unusable subpartitions (the customer comments about the bug don’t give any suggestion that there might be unusable indexes in place – and it seems unlikely that the 22 indexes mentioned were all unusable).

 

 

 

 

 

November 13, 2018

Index Splits – 3

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

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

Full dump


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



Summary

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

------

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

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

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

------

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

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

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

------

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

------

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

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

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

------

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

------

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

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

------

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

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

------

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

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

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

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

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

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

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

October 30, 2018

Index Splits – 2

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

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

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

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

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


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

drop table t2 purge;

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

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

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

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

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

pause

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

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


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

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

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

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

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


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


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

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

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

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

 

October 29, 2018

Index splits

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

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

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

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


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

start setenv
set timing off
set feedback off

define m_limit = 292

drop table t1 purge;

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

column object_id new_value m_index_id

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

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


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

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


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

alter system switch logfile;
execute snap_my_stats.start_snap;

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

execute snap_my_stats.end_snap

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

execute dump_log

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

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


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

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


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


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

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


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

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

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

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


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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Footnote

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

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

 

 

October 22, 2018

Column Groups

Filed under: Bugs,CBO,extended stats,Indexing,Oracle,Statistics — Jonathan Lewis @ 5:36 pm BST Oct 22,2018

Sometimes a good thing becomes at bad thing when you hit some sort of special case – today’s post is an example of this that came up on the Oracle-L listserver a couple of years ago with a question about what the optimizer was doing. I’ll set the scene by creating some data to reproduce the problem:

rem
rem     Script:         distinct_key_prob.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Apr 2016
rem     Purpose:
rem
rem     Last tested
rem             19.1.0.0  (Live SQL, with some edits)
rem             18.3.0.0
rem             12.2.0.1
rem             12.1.0.2
rem             11.2.0.4
rem

drop table t1 purge;

create table t1
nologging
as
with generator as (
        select  --+ materialize
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > commment to avoid wordpress format issue
)
select
        cast(mod(rownum-1,10) as number(8,0))   non_null,
        cast(null as number(8,0))               null_col,
        cast(lpad(rownum,10) as varchar2(10))   small_vc,
        cast(rpad('x',100) as varchar2(100))    padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e6 -- > commment to avoid wordpress format issue
;

create index t1_i1 on t1(null_col, non_null);

begin

/*
        dbms_output.put_line(
                dbms_stats.create_extended_stats(user,'t1','(non_null, null_col)')
        );
*/

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

So I have a table with 1,000,000 rows; one of its columns is always null and another has a very small number of distinct values and is never null (though it hasn’t been declared as not null). I’ve created an index that starts with the “always null” column (in a production system we’d really be looking at a column that was “almost always” null and have a few special rows where the column was not null, so an index like this can make sense).

I’ve also got a few lines, commented out, to create extended stats on the column group (non_null, null_col) because any anomaly relating to the handling of the number of distinct keys in a multi-column index may also be relevant to column groups. I can run two variations of this code, one with the index, one without the index but with the column group, and see the same cardinality issue appearing in both cases.

So let’s execute a couple of queries – after setting up a couple of bind variables – and pull their execution plans from memory:


variable b_null    number
variable b_nonnull number

exec :b_null    := 5
exec :b_nonnull := 5

set serveroutput off

prompt  ===================
prompt  Query null_col only
prompt  ===================

select  count(small_vc)
from    t1
where
        null_col = :b_null
;

select * from table(dbms_xplan.display_cursor(null,null,'-plan_hash'));

prompt  =========================
prompt  Query (null_col,non_null)
prompt  =========================

select  count(small_vc)
from    t1
where
        null_col = :b_null
and     non_null = :b_nonnull
;

select * from table(dbms_xplan.display_cursor(null,null,'-plan_hash'));

The optimizer has statistics that tell it that null_col is always null so its estimate of rows where null_col = 5 should be zero (which will be rounded up to 1); and we have an index starting with null_col so we might expect the optimizer to use an index range scan on that index for these queries. Here are the plans that actually appeared:


SQL_ID  danj9r6rq3c7g, child number 0
-------------------------------------
select count(small_vc) from t1 where  null_col = :b_null

--------------------------------------------------------------------------------------
| Id  | Operation                    | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |       |       |       |     2 (100)|          |
|   1 |  SORT AGGREGATE              |       |     1 |    24 |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1    |     1 |    24 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | T1_I1 |     1 |       |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("NULL_COL"=:B_NULL)



SQL_ID  d8kbtq594bsp0, child number 0
-------------------------------------
select count(small_vc) from t1 where  null_col = :b_null and non_null =
:b_nonnull

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |  2189 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    27 |            |          |
|*  2 |   TABLE ACCESS FULL| T1   |   100K|  2636K|  2189   (4)| 00:00:11 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(("NULL_COL"=:B_NULL AND "NON_NULL"=:B_NONNULL))

Take a careful look at what we’ve got: the second query has to access exactly the same table rows as those identified by the first query and then apply a second predicate which may discard some of those rows – but the optimizer has changed the access path from a low-cost index-driven access to a high cost tablescan. This is clearly idiotic – there has to be a flaw in the optimizer logic in this situation.

The defect revolves around a slight inconsistency in the handling of columns groups – whether they are explicitly created, or simply inferred by reference to user_indexes.distinct_keys. The anomaly is most easily seen by explicitly creating the column group, gathering stats, and reporting from user_tab_cols.


select
        column_name, sample_size, num_distinct, num_nulls, density, histogram, data_default
from
        user_tab_cols
where
        table_name = upper('T1')
order by
        column_id

;

OLUMN_NAME                            Sample     Distinct  NUM_NULLS    DENSITY HISTOGRAM       DATA_DEFAULT
-------------------------------- ------------ ------------ ---------- ---------- --------------- --------------------------------------------
NON_NULL                            1,000,000           10          0         .1 NONE
NULL_COL                                                 0    1000000          0 NONE
SMALL_VC                            1,000,000      995,008          0 .000001005 NONE
PADDING                             1,000,000            1          0          1 NONE
SYS_STULC#01EE$DE1QB7UY1K4$PBI      1,000,000           10          0         .1 NONE            SYS_OP_COMBINED_HASH("NON_NULL","NULL_COL")

As you can see, the optimizer can note that “null_col” is always null so the arithmetic for “null_col = :bind1” is going to produce a very small cardinality estimate; on the other hand when the optimizer sees “null_col = :bind1 and non_null = :bind2” it’s going to transform this into the single predicate “SYS_STULC#01EE$DE1QB7UY1K4$PBI = sys_op_combined_hash(null_col, non_null)”, and the statistics say there are 10 distinct values for this (virtual) column with no nulls – hence the huge cardinality estimate and full tablescan.

The “slight inconsistency” in handling that I mentioned above is that if you used a predicate like “null_col is null and non_null = :bind2″ the optimizer would not use column group because of the “is null” condition – even though it’s exactly the case where the column group statistics would be appropriate. (In the example I’ve constructed the optimizer’s estimate from ignoring the column group would actually be correct – and identical to the estimate it would get from using the column group – because the column is null for every single row.)

tl;dr

Column groups can give you some very bad estimates, and counter-intuitive behaviour, if any of the columns in the group has a significant percentage of nulls; this happens because the column group makes the optimizer lose sight of the number of nulls in the underlying data set.

 

September 27, 2018

Column Group Catalog

Filed under: CBO,extended stats,Indexing,Oracle,Statistics — Jonathan Lewis @ 5:16 pm BST Sep 27,2018

I seem to have written a number of aricles about column groups – the rather special, and most useful, variant on extended stats. To make it as easy as possible to find the right article I’ve decided to produce a little catalogue (catalog) of all the relevant articles, with a little note about the topic each article covers. Some of the articles will link to others in the list, and there are a few items in the list from other blogs. There are also a few items which are the titles of drafts which have been hanging around for the last few years.

 

August 22, 2018

Descending bug

Filed under: Bugs,Execution plans,Function based indexes,Indexing,Oracle — Jonathan Lewis @ 1:20 pm BST Aug 22,2018

Following on from Monday’s posting about reading execution plans and related information, I noticed a question on the ODC database forum asking about the difference between “in ({list of values})” and a list of “column = {constant}” predicates connected by OR. The answer to the question is that there’s essentially no difference as you would be able to see from the Predicate Information of an execution plan:


SELECT  c1, c2, c3, c4, c5, c6, c7, c8..  
FROM    TAB1  
WHERE   STS IN ( 'A', 'B')  
AND     cnt < '4'  
AND     dt < sysdate  
and     rownum <=1;  
  
---------------------------------------------------------------------------------------------------------  
| Id  | Operation                     | Name                    | Rows  | Bytes | Cost (%CPU)| Time     |  
---------------------------------------------------------------------------------------------------------  
|   0 | SELECT STATEMENT              |                         |     1 |  1847 | 33399   (1)| 00:03:14 |  
|*  1 |  COUNT STOPKEY                |                         |       |       |            |          |  
|   2 |   INLIST ITERATOR             |                         |       |       |            |          |  
|*  3 |    TABLE ACCESS BY INDEX ROWID| TAB1                    |   114K|   201M| 33399   (1)| 00:03:14 |  
|*  4 |     INDEX RANGE SCAN          | TAB1_STS_IDX            |   114K|       |   723   (1)| 00:00:05 |  
---------------------------------------------------------------------------------------------------------  
  
Predicate Information (identified by operation id):  
---------------------------------------------------  
   1 - filter(ROWNUM<=1)  
   3 - filter("cnt"<'4' AND "dt"<SYSDATE@!)  
   4 - access("STS"='A' OR "STS"='B')  

Note how the predicate section tells you that the original “sts in ( ‘A’, ‘B’ )” has been transformed into “sts = ‘A’ or sts = ‘B'”.

A further point I made about IN-lists in Monday’s post was that as one step in the transformation Oracle would start by sorting the list and eliminating duplicates. It suddenly occurred to me to wonder whether Oracle would sort the list in descending order if the only relevant index were defined to start with a descending column. Naturally I had to test the idea, so here’s a suitable script to prepare some data:

rem
rem     Script:         descending_bug_06.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Aug 2018
rem     Purpose:
rem
rem     Last tested
rem             18.3.0.0        Crashes
rem             12.2.0.1        Crashes
rem             12.1.0.2        Crashes
rem             11.2.0.4        Bad Plan
rem

create table t1
nologging
pctfree 95 pctused 5
as
with generator as (
        select 
                rownum id
        from dual 
        connect by 
                level <= 1e4 -- > comment to avoid WordPress format issue
)
select
        rownum                          id,
        lpad(rownum,10,'0')             v1,
        case mod(rownum,1000)
                when 0 then 'A'
                when 3 then 'B'
                when 6 then 'C'
                       else 'D'
        end                             sts,
        case mod(rownum,1000)
                when 0 then '1'
                when 3 then '2'
                when 6 then '3'
                       else '4'
        end                             cnt,
        lpad('x',100,'x')               padding
from
        generator       v1,
        generator       v2
where
        rownum <= 1e5 -- > comment to avoid WordPress format issue
;

create index t1_i1a on t1(sts) nologging;
create index t1_i1d on t1(sts desc) nologging;

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

There is one oddity in this script – if you’ve declared every column in an index as DESC you’ve made a mistake and none of the columns should have been declared as DESC. The feature is relevant only if you want a mixture of ascending and descending columns in a single index. By making every column descending the only thing you’ve achieved is to make the index one byte per column larger for every row in the index – while introducing the opportunity of hitting various limitations and bugs.

An important detail of the script is that I’ve gathered stats after creating the objects. It’s important to do this for my demo, even in 19.3, because (a) creating the “descending” index will result in a hidden virtual column being created to represent each descending column and I want to make sure I have stats on the virtual column in my example and (b) the “stats on creation” code doesn’t generate histograms and I want a (frequency) histogram on columns sts and the hidden, virtual, descending version of the column.

After generating the data and checking that I have the correct histograms for sts and sys_nc00006$ (the relevant hidden column) I can then run the following test:

set serveroutput off
alter session set statistics_level = all;

alter index t1_i1d invisible;

select  sts, count(*)
from    t1
where   sts in ('B','C')
group by
        sts
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

alter index t1_i1d   visible;
alter index t1_i1a invisible;

select  sts, count(*)
from    t1
where   sts in ('B','C')
group by
        sts
;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

alter session set statistics_level = typical;
set serveroutput on


The code makes one index invisible then runs a query that should use an inlist iterator; then it switches indexes making the invisible one visible and vice versa and repeats the query. I’ve enabled rowsource execution statistics and pulled the execution plans from memory to make sure I don’t get fooled by any odd glitches that might exist within “explain plan”. Here are the results from 11.2.0.4 – normal index, then descending index – with a little cosmetic cleaning:


S   COUNT(*)
- ----------
B        100
C        100

SQL_ID  f20u42pmw1z6w, child number 0
-------------------------------------
select sts, count(*) from t1 where sts in ('B','C') group by  sts

-----------------------------------------------------------------------------------------
| Id  | Operation            | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |        |      1 |        |      2 |00:00:00.01 |       5 |
|   1 |  SORT GROUP BY NOSORT|        |      1 |      2 |      2 |00:00:00.01 |       5 |
|   2 |   INLIST ITERATOR    |        |      1 |        |    200 |00:00:00.01 |       5 |
|*  3 |    INDEX RANGE SCAN  | T1_I1A |      2 |    178 |    200 |00:00:00.01 |       5 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access(("STS"='B' OR "STS"='C'))


Index altered.
Index altered.


S   COUNT(*)
- ----------
C        100
B        100


SQL_ID  f20u42pmw1z6w, child number 0
-------------------------------------
select sts, count(*) from t1 where sts in ('B','C') group by  sts

-----------------------------------------------------------------------------------------
| Id  | Operation            | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |        |      1 |        |      2 |00:00:00.02 |     198 |
|   1 |  SORT GROUP BY NOSORT|        |      1 |      2 |      2 |00:00:00.02 |     198 |
|*  2 |   INDEX FULL SCAN    | T1_I1D |      1 |   1000 |    200 |00:00:00.02 |     198 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter((SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='B' OR
              SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='C'))


As expected we see counts of 100 for ‘B’s and ‘C’s, and we also see that the “sort group by nosort” operation with the descending index has produced the results in descending order. The problem though is that the optimizer has decided to use an “index full scan” on the descending index and the estimate of the rows returned is terribly wrong (and seems to be the common “5% guess” used once for each target value), and the number of buffer visits is huge compared to the result from the normal index – Oracle really did walk every leaf block in the index to get this result. The predicate section also looks rather silly – why hasn’t the optimizer produced predicates more like: “sys_nc00006$ = sys_op_descend(‘B’)” ?

In passing you’ll notice that the estimated rows in the plan using the normal index is a little low. This is the result of Oracle using a small sample (ca. 5,500 rows) in 11g to gather histogram stats. 12c will do better for a frequency histogram with the fast (“approximate_ndv”) algorithm it uses for a 100% (auto) sample size.

So 11g doesn’t do very well but we’ve got 12.1.0.2, 12.2.0.1, and (in the last couple of weeks) 18.3 to play with. Here’s the result from 12.1.0.2 and 12.2.0.1 for the query that should use the descending index:


select  sts, count(*)
*
ERROR at line 1:
ORA-00600: internal error code, arguments: [qernsRowP], [1], [], [], [], [], [], [], [], [], [], []


SQL_ID  f20u42pmw1z6w, child number 0
-------------------------------------
select sts, count(*) from t1 where sts in ('B','C') group by  sts

-----------------------------------------------------------------------------------------
| Id  | Operation            | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |        |      1 |        |      0 |00:00:00.01 |       0 |
|   1 |  SORT GROUP BY NOSORT|        |      1 |      2 |      0 |00:00:00.01 |       0 |
|   2 |   INLIST ITERATOR    |        |      1 |        |    101 |00:00:00.03 |       5 |
|*  3 |    INDEX RANGE SCAN  | T1_I1D |      2 |    200 |    101 |00:00:00.01 |       5 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access(("T1"."SYS_NC00006$"=SYS_OP_DESCEND('B') OR
              "T1"."SYS_NC00006$"=SYS_OP_DESCEND('C')))
       filter((SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='B' OR
              SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='C'))

The query crashed! The plan, however, did look appropriate – the optimizer picked an inlist iterator, picked an index range scan, got the correct estimate of rows (index entries), and did better with the predicate section (though having used a sensible predicate for the access predciate it then used the bizarre version as the filter predicate). Judging from the A-rows column the query seems to have crashed at roughly the point where the optimizer was switching from the range scan for the first iteration into the range scan for the second iteration.

And then there’s Oracle 18.3 – which does the same as the 12c versions :(

To make sure that my silly “single column so it shouldn’t be declared descending” index was the sole cause of the problem I repeated the tests using a two-column index on (sts, cnt).

Conclusion:

Descending indexes or (to be more accurate) indexes with descending columns can still produce problems even in the very latest version of Oracle.

Footnote

Oracle MoS has the wonderful “ORA-600/ORA-7445/ORA-700 Error Look-up Tool (Doc ID 153788.1)” (which doesn’t yet allow you to choose 18.3 as a version) so I used this to do a look up for ORA-00600 errors with first paremeter qernsRowP in 12.2.0.1 and got the following suggestion from doc ID 285913.1: “set event:10119 to disable no-sort fetch and then reparse the failing SQL.” The example suggested setting the event to level 12, and this solved the problem for all three failing versions – but the suggestion came with a warning: “Setting this event at system level may impact the performance of database.” The execution plan (taken, in this case, from 18.2) may explain the warning:

 

S   COUNT(*)
- ----------
B	 100
C	 100

SQL_ID	f20u42pmw1z6w, child number 0
-------------------------------------
select sts, count(*) from t1 where sts in ('B','C') group by  sts

------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |	    |	   1 |	      |      2 |00:00:00.01 |	    4 |       |       | 	 |
|   1 |  HASH GROUP BY	   |	    |	   1 |	    2 |      2 |00:00:00.01 |	    4 |  1558K|  1558K|  659K (0)|
|   2 |   INLIST ITERATOR  |	    |	   1 |	      |    200 |00:00:00.01 |	    4 |       |       | 	 |
|*  3 |    INDEX RANGE SCAN| T1_I1D |	   2 |	  200 |    200 |00:00:00.01 |	    4 |       |       | 	 |
------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access(("T1"."SYS_NC00006$"=SYS_OP_DESCEND('B') OR "T1"."SYS_NC00006$"=SYS_OP_DESCEND('C')))
       filter((SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='B' OR SYS_OP_UNDESCEND("T1"."SYS_NC00006$")='C'))


The plan has changed from using a “sort group by nosort” – which effectively means just keeping a running count as you go – to a real “hash group by” which means you have to do the hashing arithmetic for every value (though maybe there’s a deterministic trick that means Oracle won’t do the arithmetic if the next value to be hashed is the same as the previous value) and the actual memory used (659K) does seem a little extreme for counting two distinct values.

Update Aug 2019

The bug is still present in 19.3

 

 

Next Page »

Powered by WordPress.com.