Journal table — Behaviour and Issues

Journal Tables are like any other IOT tables. I had explained their strcture in the recent post.  This post will cover following points

1. Behaviour of journal table.
2. Effects of killing index in between.

Please click here to understand the basic structure of journal table.

Behaviour of Journal Table

As discussed earlier, journal tables are created when we issue alter index command and gets dropped only after the job completes successfully or cleans or cancelled successfully.  Whenever we kill our session or cancel our job, oracle tries to clean the journal table . If you have killed your job (CTL C), oracle tries to get a latch and then merge the entries and then drop the journal table.

 In case it does not, it will try fixed number of times and will then fail. This behaviour is explained in detail in later section. However, we must verify that journal tables are no longer present.

Test Case:-

From session 1 insert a row  and issue rebuild comand from session 2 and then hit ctl c to cancel the job.

Session1>insert into mytab select * from mytab where rownum<2;

Session2>alter index mytab_idx rebuild online;
alter index mytab_idx rebuild online
*
ERROR at line 1:
ORA-01013: user requested cancel of current operation<

/*it will error out after 2000 retries or 20000 milli seconds. Discussed later */

Lets check if the journal table exists or not.

sesion2>select object_name,object_type,object_id from dba_objects where object_name='MYTAB_IDX';

OBJECT_NAME          OBJECT_TYPE           OBJECT_ID
-------------------- -------------------- ----------
MYTAB_IDX            INDEX                     98701

1 row selected.

session2>select object_name,object_type from dba_objects where object_name='SYS_JOURNAL_98701';

OBJECT_NAME          OBJECT_TYPE
-------------------- --------------------
SYS_JOURNAL_98701    TABLE

1 row selected.

As suspected , oracle timesout and left the cleaning part. All the transaction entries will now go into the journal table from now since the trigger has not been changed back to point to the index. Its still pointing to the journal table. As we can see,if the index rebuild job does not perform cleaning, the entries will stuck in journal table and we have to take manual steps to recover it.

session1>select * from SYS_JOURNAL_98701;

session1>insert into mytab(owner,object_name) values ('AFTER INDEX','CANCEL');

1 row created.
session1>commit;

Commit complete.

C0                   C1         C2    OPCODE     PARTNO RID
-------------------- ---------- ----- ---------- ------ ------------------
AFTER INDEX          CANCEL           I               0 D/////AAEAAAwQHAAL

1 row selected.

Effects of killing index in between

As we had already discussed that even after killing index job, oracle sometimes does not able to drop the journal table. Oracle will try exactly 2000 times with avg waitng time of 10 millli second (20,000 milli seconds in all), in case all the blocking sessions are inactive,  to acquire a latch to clean the journal table.

Test Case

Lets insert a row without commiting and start rebuilding from next session.

Session1>insert into mytab select * from mytab where rownum<2;

1 row created.

Session2>alter index mytab_idx rebuild online; 

Lets check the status from session 3 using our ndx-progress.sql

SESSION3>@ndx-progress
Enter value for sid: 2178

SID              ---->2178
SERIAL           ---->6537
MODULE           ---->SQL*Plus
MACHINE          ---->db-fc-admin-6001.iad6.amazon.com
USERNAME         ---->SUBHATIA_DBA
OSUSER           ---->subhatia
SQL TEXT         ---->alter index mytab_idx rebuild online
SQL ID           ---->7sk4sratkuvq8
JOURNAL NAME     ---->SYS_JOURNAL_98701
TABLE NAME       ---->MYTAB
EVENT_NAME       ---->enq: TX - row lock contention
IDLE SINCE       ---->223
CPU TIME         ---->35995
ELAPSED TIME     ---->219143299
JOURNAL COUNT    ---->0
STAGE            ---->Waiting for first latch.
LONGOPS          ---->INDEX REBUILD NOT STARTED YET
PROGRESS         ---->No Tx started after index rebuild has commited yet. There are 0 rows in journal table
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2154    9407    INACTIVE                249             0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE

NO POTENTIAL BLOCKERS FOUND FOR THE LAST LATCH

As expected, our insert has blocked the index rebuild. Lets cancel the job(ctl c) and check whats happening now using ndx-progress.

Yes, ndx-progress can report that one too (amazing).

click here for ndx-progress

SESSION3>@ndx-progress
Enter value for sid: 2178
Index Rebuild has been cancelled. Cleaning going on
SID              ---->2178
SERIAL           ---->6537
MODULE           ---->SQL*Plus
MACHINE          ---->db-fc-admin-6001.iad6.amazon.com
USERNAME         ---->SUBHATIA_DBA
OSUSER           ---->subhatia
SQL TEXT         ---->alter index mytab_idx rebuild online
SQL ID           ---->7sk4sratkuvq8
JOURNAL NAME     ---->SYS_JOURNAL_98701
TABLE NAME       ---->MYTAB
EVENT_NAME       ---->index (re)build online cleanup
IDLE SINCE       ---->2116
CPU TIME         ---->2164672
ELAPSED TIME     ---->2113894321
JOURNAL COUNT    ---->0
------------SESSIONS BLOCKING CLEANING PROCESS-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2154    9407    INACTIVE                2145            0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------CLEANUP PROCESS TIMOUT-------------
EVENT                                   TOTAL WAITS             TOTAL TIMEOUTS          TIME WAITED             AVG WAIT                MAX WAIT
index (re)build online cleanup          1967                    1967                    19799                   10.07                   10                  10

On checking the status, index job was cancelled but journal entry was still there

Session2>alter index mytab_idx rebuild online;
alter index mytab_idx rebuild online
*
ERROR at line 1:
ORA-01013: user requested cancel of current operation
SESSION3>select event,total_waits,total_timeouts,time_waited,average_wait,max_wait from v$session_event where sid=2178 and event='index (re)build online cleanup';
EVENT                          TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT
------------------------------ ----------- -------------- ----------- ------------ ----------
index (re)build online cleanup        2000           2000       20131        10.07         10
1 row selected.

As we can check, oracle tries for 2000  times but timeout each time. it kept tring for 2000*10 ms and then error out.

Journal Table — What are those

Many DBA’s have tendency to hit CTL C or kill the session, when there session does not comes out. Ever tries doing that with index rebuild and you will find that your index is stuck in journal table. This post is intended to describe the nature of journal table and how to clear the mess.

 It’s been divided into following sections

1. Structure and understanding of journal table
2. Behaviour of journal table.
3. Effect of killing the index rebuild in between.
4. Clearing the journal table.

Structure of Journal Table 

 Oracle creates journal table inside the owner schema as soon as we issue “alter index rebuild online”. It doesn’t matter if oracle has acquired the first latch or not. The entries of all the transactions started after we issue the command will be logged into the journal table. Journal table is the index organized table and their name will essentially be SYS_JOURNAL_<index object_id>.

To understand index rebuilding check the following link.

Index Rebuild Online

The structure is as follows

  As you might have noticed, there is no “U” for update in opcode since update essentially is Delete+ Insert. Two entries will be recorded for each update statement in the journal table. 

Name                    Null?    Type
C0                      NOT NULL VARCHAR2(30) -->first column of index

C1                      NOT NULL VARCHAR2(128) -->second column of index(composite index)
C2                      NOT NULL VARCHAR2(30) -->third column of index (composite index)
OPCODE                           CHAR(1) -->I for insert, D for delete.
PARTNO                           NUMBER
RID                     NOT NULL ROWID -->rowid from 7th char to end

 C0,C1,C2(columns of index) and RID will form the primary key of the journal table and will have a unique index with the name SYS_IOT_TOP_<journal object id>

The columns of journal table(c0,c1,c2) will have same data type as of base table and will always be not null irrespective of constarints on base table.

TEST CASE

I have created a table mytab (select * from dba_objects) and created a composite index mytab_idx on (owner,object_name,subobject_name).

As I started the rebuild, i could see following entries in my schema.

session4> select object_name,object_type,object_id from dba_objects where owner='SUBHATIA_DBA';

OBJECT_NAME                                        OBJECT_TYPE          OBJECT_ID
-------------------------------------------------- ------------------- ----------
MYTAB                                              TABLE                    98699
SYS_JOURNAL_98701                                  TABLE                   101871
SYS_IOT_TOP_101871                                 INDEX                   101872
MYTAB_IDX                                          INDEX                    98701

4 rows selected.

As we can confirm the name of the journal table is SYS_JOURNAL_98701 (where 98701 is object id of index) and IOT index is SYS_IOT_TOP_101871  where 101871 is object_id of journal table.

Usage of Journal Tables

When we rebuild index online, oracle does not read from the existing index. Instead it reads the base table. So whats the use of existiing index.

Well, oracle put the existing index into read only mode and records all the new transaction entries into the journal table.

Journal table is like any other IOT table. So whenever, any select statement needs to traverse a row, it gets the rowid from the new journal table and then access the table using that rowid.

Question1) Does journal table is always there in the database

Answer) Journal tables are created as we issue the rebuild command and gets dropped as soon as the command finishes.

Question 2) Does journal table record entries of transactions which starts before the alter index rebuild command was issued.

Answer) No, it does not. It will only capture entries of those transactions that have started after we fired rebuild. Oracle doesn’t know you are going to fire rebuild command.

Question3) Does journal table records entries of transactions started after rebuild only after we commit.

Answer) Journal table is like any other table. In case you performed some DML while index rebuid is going on and does not commit, you will be able to see those entries into the journal table from same session but others won’t. Others will see only if you commit them. Oracle follows basic ACID principle for journal tables too.

Test case

Lets verify all the above points

Are journal tables there forever??

Currently I have only 2 objects in my schema. 

session4>select object_name,object_type,object_id from dba_objects where owner='SUBHATIA_DBA';

OBJECT_NAME                                        OBJECT_TYPE          OBJECT_ID
-------------------------------------------------- ------------------- ----------
MYTAB_IDX                                          INDEX                    98701
MYTAB                                              TABLE                    98699

2 rows selected.

Lets insert few rows from 1st session to block the rebuild and issue alter index command from 2nd session

SESSION1>insert into mytab select * from mytab where rownum<5;
4 rows created.
/*alter index from session 2 */
session2>alter index mytab_idx rebuild online;  -->will get stuck

/*lets check again from session 1 */

session1>select object_name,object_type,object_id from dba_objects where owner='SUBHATIA_DBA';

OBJECT_NAME                                        OBJECT_TYPE          OBJECT_ID
-------------------------------------------------- ------------------- ----------
MYTAB                                              TABLE                    98699
SYS_JOURNAL_98701                                  TABLE                   101877
SYS_IOT_TOP_101877                                 INDEX                   101878
MYTAB_IDX                                          INDEX                    98701

4 rows selected.

Does journal table record entries of transactions which starts before the alter index rebuild command was issued??

Check the count of journal table from the session holding the lock.

SESSION1>select count(*) from SYS_JOURNAL_98701;

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

1 row selected.

Does journal table records entries of transactions started after rebuild only after we commit??

 Lets open a new session and insert few rows without committing.

session4>insert into mytab select * from mytab where rownum<5;

4 rows created.

session4>select count(*) from SYS_JOURNAL_98701;

  COUNT(*)
----------
         4

1 row selected.

/*lets query from some another session*/

SESSION1>select count(*) from SYS_JOURNAL_98701;

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

1 row selected.

/*Lets commit and again check count from another session */

SESSION1>select count(*) from SYS_JOURNAL_98701;

  COUNT(*)
----------
         4

1 row selected.

Understanding of Journal Table

When we say, journal table hold entries then the next obvious question is what entries. How does it store and what does it mean.Moreover, is there any mechanism to understand those.  

The answer is YES, we can.

Lets try out this test case.

Insert a row from session1 to block the index rebuild and start rebuilding index from another session.  

SESSION1>insert into mytab select * from mytab where rownum<5;

4 rows created.
/* Start rebuild from Session 2. Your session will stuck here even if its a pretty small index*/
session2>alter index mytab_idx rebuild Online;
/*Open a new session and insert a row */
session3>insert into mytab(owner,object_name,subobject_name) values('SUMIT','RANDOM','RANDOM');
1 row created.
session3>SELECT * FROM SYS_JOURNAL_98701;

C0                             C1                   C2                             O     PARTNO RID
------------------------------ -------------------- ------------------------------ - ---------- ------------------
SUMIT                          RANDOM               RANDOM                         I          0 D/////AAEAAAwQHAAU

 /*Let's update a row as well */
session3>update mytab set owner='DBA' where owner='SUMIT' AND object_name='RANDOM';

1 row updated.

session3>SELECT * FROM SYS_JOURNAL_98701;

C0         C1         C2         O     PARTNO RID
---------- ---------- ---------- - ---------- ------------------
DBA        RANDOM     RANDOM     I          0 D/////AAEAAAwQHAAU
SUMIT      RANDOM     RANDOM     D          0 D/////AAEAAAwQHAAU

2 rows selected.

Here we can see 2 entries. But there should be 3. Remember update=D+I.

Oracle knew we have updated the row which we just inserted and the entry was already there. So it removes the earlier entry and added 2 new entries for update only.

Now, the entry for Sumit is marked as “D” wich was earlier “I” and a new entry “DBA”  has been added as “I”.

Last question, why oracle has not stored initial 6 letters of rowid and can we trace it back.

Yes, we can trace it back. We can use following query (but it is a bit slower)

session3>select owner,object_name,SUBOBJECT_NAME from mytab where substr(rowid,7)='AAEAAAwQHAAU';

OWNER                OBJECT_NAME                                        SUBOBJECT_NAME
-------------------- -------------------------------------------------- ------------------------------
DBA                  RANDOM                                             RANDOM

1 row selected.

Oracle is not showing inital 6 letters because those always refer to object id.

We can use this method which is relatively faster.

session3>select substr(rowid,1,6) from  mytab  where rownum<2;

SUBSTR(ROWID,1,6)
------------------
AAAYGL

1 row selected.
session3>select owner,object_name,SUBOBJECT_NAME from mytab where rowid='AAAYGLAAEAAAwQHAAU';

OWNER                OBJECT_NAME                                        SUBOBJECT_NAME
-------------------- -------------------------------------------------- ------------------------------
DBA                  RANDOM                                             RANDOM

1 row selected.

Online Index Rebuild oracle 11g–>Behind the scene

Index are used to speed up the select statements.
But over a period of time, they may get fragmented because of constant DML’s occurring on the table. These bloated indexes may slow down the select or may cause plan flips too.

One way to avoid all these is to rebuild indexes.However, many of us might have faced issues while rebuilding indexes. Sometimes, it causes performance issues (due to enq TM contention) or the command won’t come out.

Ever wonder, why the index rebuilding is suddenly taking such a long time. Why my session is not coming out or exactly where is it stuck.

This post is intended to explore the internals of online index rebuild in oracle11g. I have developed a customized script which will tell exactly where the session is stuck.

http://fordba.wordpress.com/2011/03/30/ndx-progress-sql/

The script is just an anonymous plsql block and does not perform any DDL/DML.

It queries various v$ views to present the current picture before you and does not cause or have any adverse impact

For online index rebuild oracle requires 2 latches. One at the beginning and one at the end of the operation.

Online Index Rebuild Stages (No Parallel)

During Online index rebuild oracle performs following in the given order :-

1. Create the journal table (inside index owner schema) SYS_JOURNAL_<objectid_index>
2. Wait for the first latch (enq: TX – row lock contention)
3. As soon as it gets latch, will perform db file sequential read to merge journal entries
4. Will start scattered read of the base table
5. Will again perform the sequential read to merge the journal entries which got generated during scattered read.
6. Will perform direct path read temp.
7. wait for the end latch

The good thing about index rebuild in 11g is , it does not cause locking for the DML’s (enq TM contention, which was there in 10g).

Test Case

Environment:- Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 – 64bit Production

1. Create a new table and insert few records.

SESSION1>CREATE TABLE mytab as select * from dba_objects;
Table created.

SESSION1>insert into mytab select * from mytab;
12459 rows created.

SESSION1>/
12459 rows created.
SESSION1>create index mytab_idx on myt(owner,OBJECT_NAME,SUBOBJECT_NAME);

Index created.

You may want to insert more rows to grow the size of index.

2. Insert a new records into the table.

SESSION1>insert into mytab select * from mytab where rownum<10;
9 rows created.

3. Open a new session (note down its sid) and issue alter index command.

SESSION2>select sid from v$mystat where rownum<2;
SID
----------
2195
1 row selected.
SESSION2>ALTER INDEX MYTAB_IDX REBUILD ONLINE;

4. Open a new session to see exactly whats happening.

SESSION3>@ndx-progress.sql
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->0
STAGE            ---->Waiting for first latch.
PROGRESS         ---->No Tx started after index rebuild has commited yet. There are 0 rows in journal table
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2161    19807   INACTIVE                425             0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
NO POTENTIAL BLOCKERS FOUND FOR THE LAST LATCH

5. In the above output, you can see the session is waiting on enq: TX – row lock contention and has not acquired the first latch.

It will keep on waiting for all the transactions which have started before issueing index rebuild.

For any transactions started after index rebuild comand issued, they will cause locking at the last stage when end latch is required.

In case they commit, there entries will go into the journal table.

Lets open another session and insert few rows and wait for 30 seconds(This is the limit i set in my script to find potential blockers)

SESSION4>insert into mytab select * from mytab where rownum<101;
100 rows created.

6. Lets check whats happening again. The journal count is still 0, since session 4 has not commited yet and the session is appearing on potential blockers list

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->0
STAGE            ---->Waiting for first latch.
PROGRESS         ---->No Tx started after index rebuild has commited yet. There are 0 rows in journal table
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2161    19807   INACTIVE                1015            0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2164    36539   INACTIVE                130             0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com

7. Lets commit from session 4 and see the difference in count of journal table. It will disappear from potential blockers list as it has committed and there will be entries into the journal table

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->100
STAGE            ---->Waiting for first latch.
PROGRESS         ---->Few Tx started after index rebuild command have been commited and there is/are 100 rows into journal table
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2161    19807   INACTIVE                1134            0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com

------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
NO POTENTIAL BLOCKERS FOUND FOR THE LAST LATCH

8. So far we have observed that index is stuck. Lets insert few more rows (100k approx) so that we could observe step3 else we wont able to catch the initial db file sequential read merging and check the status.

SESSION4>insert into mytab select * from mytab where rownum<100001;
100000 rows created.
SESSION4>commit;
Commit complete.

——————————-check from session 3———————-

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->100100
STAGE            ---->Waiting for first latch.
PROGRESS         ---->Few Tx started after index rebuild command have been commited and there is/are 100100 rows into journal table
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2161    19807   INACTIVE                1717            0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
NO POTENTIAL BLOCKERS FOUND FOR THE LAST LATCH

9. Insert few more rows again from session 4, to ensure we block the last latch too.

SESSION4>insert into mytab select * from mytab where rownum<100;
99 rows created.

10. Lets commit from session 1 to release initial lock and check status from session 3.

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->db file sequential read
JOURNAL COUNT    ---->0
STAGE            ---->First latch acquired.db file sequential read going on. Direct path read pending after this step.
PROGRESS         ---->All Tx started before index rebuild have been commited (first latch acquired and cleared) and no entries into journal table now.

As we can see, oracle always merge the journal table entries before performing scatterd read(FTS on base table).

Once that gets completed, oracle will start scattered read. Scattered read does not need any lock, so at this time our session 4 wont lock the index rebuild. it will lock during last phase.

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->db file scattered read
JOURNAL COUNT    ---->0
STAGE            ---->First latch acquired. FTS going on
PROGRESS         ---->All Tx started before index rebuild have been commited (first latch acquired and cleared) and no entries into journal table now.

Once that is done,oracle will perform sequential read and direct path read temp to merge entries generated during scattered read and then will wait for end latch.

Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE
SQL ID IS        ---->drs3mtb5w9knb
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->0
STAGE            ---->Operation completed.Waiting for ending latch
PROGRESS         ---->All Tx started before index rebuild have been commited (first latch acquired and cleared) and no entries into journal table now.

------------SESSIONS BLOCKING LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2164    36539   INACTIVE                367             0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com

Once commit, index rebuild fiishes

Online Index Rebuild Stages (Parallel Clause)

Oracle performs following sequence of events with parallel clause

1. Create the journal table (inside index owner schema) SYS_JOURNAL_<objectid_index>
2. Wait for the “first latch” (enq: TX – row lock contention)
3. As soon as it gets latch, will perform , it will spawn its slave process
4. Slave process will perform db file sequential read to merge the journal table entries
5. Each slave process will perform scattered read for its bunch of blocks.
6. Slave process will again perform the sequential read to merge the journal entries which got generated during scattered read.
7. slave process job will end here here.
8. Master process will wait for the “end latch”.

Test Case

Insert few records from the first session to block index rebuild.

SESSION1>insert into mytab select * from mytab where rownum<101;
100 rows created.

Open another session and rebuild index with parallel clause

SESSION2>ALTER INDEX MYTAB_IDX REBUILD ONLINE parallel 4;

Checking the status

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE parallel 4
SQL ID IS        ---->7qr6scnthqh0f
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->enq: TX - row lock contention
JOURNAL COUNT    ---->0
STAGE            ---->Waiting for first latch.
PROGRESS         ---->No transaction started after rebuiding has committed.
------------SESSIONS BLOCKING FIRST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
2161    19807   INACTIVE                152             0               NONE            9babjv8yq8ru3           SQL*Plus        db-fc-admin-6001.iad6.amazon.com
------------SESSIONS THAT MAY BLOCK LAST LATCH ARE-------------
SID     SERIAL  STATUS          LAST_CALL_ET            COMMAND         SQL_ID          PREV_SQL_ID             MODULE          MACHINE
NO POTENTIAL BLOCKERS FOUND FOR THE LAST LATCH

As we commit the first session, parallel process will start the processing.

SESSION3>/
Enter value for sid: 2195
SQL TEXT IS      ---->ALTER INDEX MYTAB_IDX REBUILD ONLINE parallel 4
SQL ID IS        ---->7qr6scnthqh0f
JOURNAL TABLE IS ---->SYS_JOURNAL_98701
TABLE NAME IS    ---->MYTAB
EVENT_NAME IS    ---->PX Deq: Execute Reply
JOURNAL COUNT    ---->0
STAGE            ---->First latch acquired. Parallel processing going on
------------TOTAL SLAVES ARE-------------
SID     SERIAL  DEGREE          REQ_DEGREE              EVENT
2149    46710   4               4               direct path read temp
2154    22192   4               4               PX Deq: Execution Msg
2156    23451   4               4               PX Deq: Execution Msg
2157    2939    4               4               PX Deq: Execution Msg
2159    55050   4               4               direct path read temp
2168    5080    4               4               direct path read temp
2184    46569   4               4               direct path read temp
2193    3495    4               4               PX Deq: Execution Msg
------------LONGOPS SLAVES ARE-------------
SID     SERIAL  TOTALWORK               SOFAR           TIME REMAINING                  ELAPSED SECONDS         OPNAME                  EVENT
2168    5080    40531                   16913           20                              14                      Sort Output             direct path read temp
2149    46710   37403                   16918           17                              14                      Sort Output             direct path read temp
2159    55050   32739                   16872           14                              15                      Sort Output             direct path read temp
2184    46569   30720                   17012           11                              14                      Sort Output             direct path read temp

xplanprofile.sql

Xplanprofile.sql :- This script is used to generate profile by using explain plan.

/*
Name :- xplanprofile.sql
Db Version :- 11.1.0.7
Author :- Sumit Bhatia
Version :- 1.1
Purpose :- Create a profile
Input :- original sql_id and original plan_hash_value
*/
set feedback off
set echo off
set timing off
set pagesize 0
set heading off verify off
accept orig_sql_id prompt 'enter original sql_id:- '
accept plan_hash prompt'enter bad plan hash value to be tuned :- '
prompt '===================OUTPUT========================='
select chr(10) from dual;

select 'declare' from dual;
select 'ar_profile_hints sys.sqlprof_attr;' from dual;
select 'begin' from dual;
select chr(9)||'ar_profile_hints := sys.sqlprof_attr(' from dual;
select chr(9)||chr(9)||'''BEGIN_OUTLINE_DATA'',' from dual;

SELECT chr(9)||chr(9)||''''||regexp_replace(extractvalue(value(d), '/hint'),'''','''''')||''','
 from
 xmltable('/*/outline_data/hint'
 passing (
 select
 xmltype(other_xml) as xmlval
 from
 plan_table
 where
 other_xml is not null
 and
 rownum=1
 )
 )
d;

select chr(9)||chr(9)||'''END_OUTLINE_DATA'''||chr(10)||');'||chr(10)||'for sql_rec in ('||chr(10)||chr(9)||'select t.sql_id, t.sql_text'||chr(10)||chr(9)||' from dba_hist_sqltext t, dba_hist_sql_plan p' ||chr(10)||chr(9)|| 'where t.sql_id = p.sql_id and p.sql_id = ''&orig_sql_id'' and p.plan_hash_value = &plan_hash and p.parent_id is null'||chr(10)||chr(9)||chr(9)||') loop'||chr(10)||chr(9)||' DBMS_SQLTUNE.IMPORT_SQL_PROFILE('||chr(10)||chr(9)||chr(9)||'sql_text => sql_rec.sql_text,profile => ar_profile_hints,name => ''PROFILE_''||sql_rec.sql_id'||CHR(10)||chr(9)||chr(9)||chr(9)||chr(9)||chr(9)||');'||chr(10)||chr(9)||'end loop;'||chr(10)||'end;'||chr(10)||'/' FROM DUAL;
prompt '===================OUTPUT========================='
set heading on
set pages 500
undef sql_id
undef child_no

Oldprofile.sql

OldProfile.sql:- This script can be used to force oracle to use the given plan by creating profile over top of it.

/*
Name :- Oldprofile.sql
Db Version :- 11.1.0.7
Author :- Sumit Bhatia
Version :- 1.1
Purpose :- Create a profile to force the old plan
Input :- sql_id, old plan hash value, bad plan hash value
*/
set feedback off
set echo off
set timing off
set pagesize 0
set heading off verify off
accept sql_id prompt ‘enter sql_id:- ‘
accept old_plan_hash_value prompt’enter old plan hash value:- ‘
accept plan_hash prompt’enter bad plan hash value to be tuned :- ‘
prompt ‘===================OUTPUT=========================’
select chr(10) from dual;

select ‘declare’ from dual;
select ‘ar_profile_hints sys.sqlprof_attr;’ from dual;
select ‘begin’ from dual;
select chr(9)||’ar_profile_hints := sys.sqlprof_attr(‘ from dual;
select chr(9)||chr(9)||”’BEGIN_OUTLINE_DATA”,’ from dual;

SELECT chr(9)||chr(9)||””||regexp_replace(extractvalue(value(d), ‘/hint’),””,”””)||”’,’
from
xmltable(‘/*/outline_data/hint’
passing (
select
xmltype(other_xml) as xmlval
from
dba_hist_sql_plan
where
sql_id like nvl(‘&sql_id’,sql_id)
and plan_hash_value=&old_plan_hash_value
and other_xml is not null
and rownum < 2
)
)
d;

select chr(9)||chr(9)||”’END_OUTLINE_DATA”’||chr(10)||’);’||chr(10)||’for sql_rec in (‘||chr(10)||chr(9)||’select t.sql_id, t.sql_text’||chr(10)||chr(9)||’ from dba_hist_sqltext t, dba_hist_sql_plan p’ ||chr(10)||chr(9)|| ‘where t.sql_id = p.sql_id and p.sql_id = ”&sql_id” and p.plan_hash_value = &plan_hash and p.parent_id is null’||chr(10)||chr(9)||chr(9)||’) loop’||chr(10)||chr(9)||’ DBMS_SQLTUNE.IMPORT_SQL_PROFILE(‘||chr(10)||chr(9)||chr(9)||’sql_text => sql_rec.sql_text,profile => ar_profile_hints,name => ”PROFILE_”||sql_rec.sql_id’||CHR(10)||chr(9)||chr(9)||chr(9)||chr(9)||chr(9)||’);’||chr(10)||chr(9)||’end loop;’||chr(10)||’end;’||chr(10)||’/’ FROM DUAL;
prompt ‘===================OUTPUT=========================’
set heading on
set pages 500
undef sql_id
undef old_plan_hash_value
undef plan_hash

planprofile.sql

Profile.sql:- This script can be used to convert baseline into profile. Output can be directly pasted to create a profile.

/*
Name :- PlanProfile.sql
Db Version :- 11.1.0.7
Author :- Sumit Bhatia
Version :- 1.1
Purpose :- Create a profile from baseline
Input :- sql_id, baseline plan name, bad plan hash value
*/
set feedback off
set echo off
set timing off
set pagesize 0 lines 500
set heading off verify off
accept sql_id prompt ‘enter sql_id to be fixed:- ‘
accept plan prompt’baseline plan name:- ‘
accept plan_hash prompt’enter bad plan hash value to be tuned :- ‘
prompt ‘===================OUTPUT=========================’
select chr(10) from dual;

select ‘declare’ from dual;

select ‘ar_profile_hints sys.sqlprof_attr;’ from dual;

select ‘begin’ from dual;
select chr(9)||’ar_profile_hints := sys.sqlprof_attr(‘ from dual;
select chr(9)||chr(9)||”’BEGIN_OUTLINE_DATA”,’ from dual;
SELECT chr(9)||chr(9)||””||regexp_replace(extractValue(value(h),’.'),””,”””)||”’,’ FROM sys.sqlobj$data od, sys.sqlobj$ so, table(xmlsequence(extract(xmltype(od.comp_data),’/outline_data/hint’))) h WHERE so.name = ‘&plan’ AND so.signature = od.signature AND so.category = od.category AND so.obj_type = od.obj_type AND so.plan_id = od.plan_id;

select chr(9)||chr(9)||”’END_OUTLINE_DATA”’||chr(10)||’);’||chr(10)||’for sql_rec in (‘||chr(10)||chr(9)||’select t.sql_id, t.sql_text’||chr(10)||chr(9)||’ from dba_hist_sqltext t, dba_hist_sql_plan p’ ||chr(10)||chr(9)|| ‘where t.sql_id = p.sql_id and p.sql_id = ”&sql_id” and p.plan_hash_value = &plan_hash and p.parent_id is null’||chr(10)||chr(9)||chr(9)||’) loop’||chr(10)||chr(9)||’ DBMS_SQLTUNE.IMPORT_SQL_PROFILE(‘||chr(10)||chr(9)||chr(9)||’sql_text => sql_rec.sql_text,profile => ar_profile_hints,name => ”PROFILE_”||sql_rec.sql_id’||CHR(10)||chr(9)||chr(9)||chr(9)||chr(9)||chr(9)||’);’||chr(10)||chr(9)||’end loop;’||chr(10)||’end;’||chr(10)||’/’ FROM DUAL;
prompt ‘===================OUTPUT=========================’
set heading on
set pages 500
undef sql_id
undef plan
undef plan_hash

Profile.sql

Profile.sql:- This script can be used to tune bad performing queries. Output can be directly paste to create a profile

/*
Name :- Profile.sql
Db Version :- 11.1.0.7
Author :- Sumit Bhatia
Version :- 1.1
Purpose :- Create a profile
Input :- Hinted sql_id, child number, original sql_id and original plan_hash_value
*/
set feedback off
set echo off
set timing off
set pagesize 0
set heading off verify off
accept sql_id prompt 'enter hinted sql_id:- '
accept child_no prompt'enter child number:- '
accept orig_sql_id prompt 'enter original sql_id:- '
accept plan_hash prompt'enter bad plan hash value to be tuned :- '
prompt '===================OUTPUT========================='
select chr(10) from dual;

select 'declare' from dual;
select 'ar_profile_hints sys.sqlprof_attr;' from dual;
select 'begin' from dual;
select chr(9)||'ar_profile_hints := sys.sqlprof_attr(' from dual;
select chr(9)||chr(9)||'''BEGIN_OUTLINE_DATA'',' from dual;

SELECT chr(9)||chr(9)||''''||regexp_replace(extractvalue(value(d), '/hint'),'''','''''')||''','
 from
 xmltable('/*/outline_data/hint'
 passing (
 select
 xmltype(other_xml) as xmlval
 from
 v$sql_plan
 where
 sql_id like nvl('&sql_id',sql_id)
 and child_number = &child_no
 and other_xml is not null
 )
 )
d;

select chr(9)||chr(9)||'''END_OUTLINE_DATA'''||chr(10)||');'||chr(10)||'for sql_rec in ('||chr(10)||chr(9)||'select t.sql_id, t.sql_text'||chr(10)||chr(9)||' from dba_hist_sqltext t, dba_hist_sql_plan p' ||chr(10)||chr(9)|| 'where t.sql_id = p.sql_id and p.sql_id = ''&orig_sql_id'' and p.plan_hash_value = &plan_hash and p.parent_id is null'||chr(10)||chr(9)||chr(9)||') loop'||chr(10)||chr(9)||' DBMS_SQLTUNE.IMPORT_SQL_PROFILE('||chr(10)||chr(9)||chr(9)||'sql_text => sql_rec.sql_text,profile => ar_profile_hints,name => ''PROFILE_''||sql_rec.sql_id'||CHR(10)||chr(9)||chr(9)||chr(9)||chr(9)||chr(9)||');'||chr(10)||chr(9)||'end loop;'||chr(10)||'end;'||chr(10)||'/' FROM DUAL;
prompt '===================OUTPUT========================='
set heading on
set pages 500
undef sql_id
undef child_no
undef plan_hash