Extracting Application / User SQLs from a TraceFile

The tkprof utility has an option to extract Application / User (i.e. other than "recursive") SQLs from a Trace File and place them in another file for review.
Such a file can be used to "playback" all the SQLs of a user session -- e.g. when attempting load / performance testing.
Note that it does NOT capture user "think" time -- the time that occurs on the client side (or application server) and is a SQL*Net wait on the database server.

For example, I have run these SQLs in a session that is being traced (the tracing can be level 1 tracing without WAITs and BINDs) :

select Table_name,Num_Rows from User_Tables order by 1;
select num_rows, blocks from user_tables where table_name = 'SOURCE_TABLE';
select COUNT(DISTINCT(OWNER)) FROM SOURCE_TABLE; 

I then review the Trace file for the session, adding the paramater "record=":

ora10204>tkprof ort24fs_ora_5117.trc my_session.prf record=Session_SQLs.sql

TKPROF: Release 10.2.0.4.0 - Production on Sun Mar 28 20:05:18 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.


ora10204>
ora10204>
ora10204>cat Session_SQLs.sql
select Table_name,Num_Rows from User_Tables order by 1 ;
select num_rows, blocks from user_tables where table_name = 'SOURCE_TABLE' ;
select COUNT(DISTINCT(OWNER)) FROM SOURCE_TABLE ;
ora10204> 

I can see the actual SQLs, not including the recursive SQLs.

Thus if you have a very large trace file of a session having run dozens of SQL statements, you can either review the tkprof output file (my_session.prf in my example above) or use the output of the record output -- the latter presents the SQL in a "cleaner" fashion.

.
.
.

A large index for an empty table ?

A post by Jonathan Lewis explaining the "Index Too Big" issue.

.

.

.

ALTER INDEX indexname REBUILD.

What does an ALTER INDEX indexname REBUILD do ? When would it be used ?


See this test case :

These are my two tables and their indexes :

QL> select table_name, blocks, num_rows,sample_size from user_tables
2  where table_name like 'STORES_LIST%';

TABLE_NAME                         BLOCKS   NUM_ROWS SAMPLE_SIZE
------------------------------ ---------- ---------- -----------
STORES_LIST                          4930     405884      405884
STORES_LIST_2                        4930     405884      405884

SQL> select table_name, index_name, num_rows, leaf_blocks from user_indexes
2  where table_name like 'STORES_LIST%';

TABLE_NAME                     INDEX_NAME                       NUM_ROWS LEAF_BLOCKS
------------------------------ ------------------------------ ---------- -----------
STORES_LIST                    STORES_LIST_CNTRY_STT_NDX          405884        1709
STORES_LIST_2                  STORES_LIST_2_CNTRY_STT_NDX        405884        1709

SQL> 

STORES_LIST is a list of Stores. STORES_LIST_2 is a replica of the table.
The Index that is present is on COUNTRY+STATE.

You can see that both the tables are of exactly the same size.
The Indexes on the two tables are also of the same size.


What happens when I REBUILD the two indexes ?

SQL> alter session set sql_trace=TRUE;

Session altered.

SQL> alter index stores_list_cntry_stt_ndx rebuild;

Index altered.

SQL> alter index stores_list_2_cntry_stt_ndx rebuild;

Index altered.

SQL> 

A tkprof on the trace file shows :

alter index stores_list_cntry_stt_ndx rebuild


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.05          0         10          0           0
Execute      1      2.42       2.72          1       1789       2818           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.44       2.77          1       1799       2818           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64



alter index stores_list_2_cntry_stt_ndx rebuild


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.03       0.03          0          1          0           0
Execute      1      2.22       2.63          1       4924       2817           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.26       2.67          1       4925       2817           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64 

Why did the rebuild of stores_list_2_cntry_stt_ndx have to read so many more blocks (4,924 versus 1,789 in "consistent get" mode)?





..........

The answer is in the fact that there is a difference between the two REBUILDs.





..........


What I hadn't presented was this done just before the REBUILD :

SQL> alter index stores_list_2_cntry_stt_ndx unusable;

Index altered.

SQL> select table_name,index_name, status from user_indexes
where table_name like 'STORES_LIST%';

TABLE_NAME                     INDEX_NAME                     STATUS
------------------------------ ------------------------------ --------
STORES_LIST                    STORES_LIST_CNTRY_STT_NDX      VALID
STORES_LIST_2                  STORES_LIST_2_CNTRY_STT_NDX    UNUSABLE

SQL> 

Index STORES_LIST_2_CNTRY_STT_NDX had actually been marked UNUSABLE. A REBUILD of this index was executed by reading the *table* in it's entirety.
On the other hand, a REBUILD of STORES_LIST_CNTRY_STT_NDX was executed by re-reading only the Index. It was still valid and usable.

Thus, I have presented a case where an ALTER INDEX indexname REBUILD may either only read the index (STORES_LIST_CNTRY_STT_NDX) which can be very fast or reads the whole table again (STORES_LIST_2_CNTRL_STT_NDX).

The difference is in the fact that the latter case was working with an Index that had been marked UNUSABLE. An UNUSABLE index is not updated when DML occurs against the table. Therefore, Oracle cannot and does not guarantee that the Index has all the table rows captured with their corresponding Key Values. A Rebuild of such an Index can only be executed by re-reading the Table in it's entirety.
On the other hand a REBUILD of a VALID Index (STORES_LIST_CNTRY_STT_NDX, the index on the first table) can read the index alone (locking the table to prevent rows being changed while the index is being read, unless the "ONLINE" keyword is added to the ALTER INDEX ... command). It is assured that the Index, being VALID, is consistent with the table.


When and why would an Index (or a Partition of a Partitioned Index) be marked UNUSABLE ?
1. If it is LOCAL (Partitioned) Index on a Partitioned Table and DDL (e.g an ALTER TABLE ... PARTITON ... command) is executed against the Table.

2. If it is a GLOBAL (non-Partitioned) Index on a Partitioned Table and DDL (e.g. an ALTER TABLE ... PARTITION ... command) is executed against the Table.

3. If it (whether an Index or an Index Partition) is explicitly set to UNUSABLE -- which may be done a in DataWarehouse prior to loading a large batch of rows, with the proviso the the Index / Index Partition is rebuilt manually or by a script at the end of the data load.

4. If a "DIRECT=true" (i.e. direct path load) SQLLoader sesssion with the option "SKIP_INDEX_MAINTENANCE=true" is executed to insert rows into the table. This may be done when loading a very large batch of rows -- like the previous method, something that may be used in aDataWarehouse.

In all of such cases, the Index or Index Partition is rebuilt with the "ALTER INDEX indexname PARTITION [partitionname] rebuild" which sets the Index / Index Partition status back from UNUSABLE to VALID.
.
.
.

Adaptive Cursor Sharing explained

The Oracle Database Optimizer team explain when Adaptive Cursor Sharing can be used.

Now, if only you could have better control over which statements should be re-parsed, instead of leaving it to an "automaton".

.

.

.

An "unknown" error ?

Herod T has returned to Oracle Blogging. However, I came across this post on an ORA-07445 error on his blog when I re-visited it today.

.
.
.

Misinterpreting RESTORE DATABASE VALIDATE

The documentation on the RMAN command RESTORE ... VALIDATE (link to the 10.2 documentation) is likely to be misunderstood. It says "Lets RMAN decide which backup sets, datafile copies, and archived logs need to be restored, and then scans them to verify their contents. No files are restored. Use VALIDATE to verify that the backups required to restore the specified files are intact and usable."
However, the fact of the matter is that a RESTORE DATABASE VALIDATE only checks the BackupSets corresponding to a Database Backup. You must remember that BackupSets corresponding to ArchiveLog Backup(s) are *separate*. These are NOT validated by a RESTORE DATABASE VALIDATE command. Furthermore, ArchiveLogs are required at the RECOVER phase. Therefore, in principle, there is no reason for a RESTORE VALIDATE to check ArchiveLogs as they are not required in the RESTORE phase ! (I know : Many DBAs will not agree with the last sentence !. But it is mportant to realise the difference between RESTORE and RECOVER).

If you want to validate ArchiveLog backups, you must run a separate RESTORE ARCHIVELOG .... VALIDATE command (specifying ALL or FROM ... UNTIL ... clauses for the range of ArchiveLogs).


In this example, I show how a RESTORE DATABASE VALIDATE alone is not sufficient. The DBA may have assumed that it checks for ArchiveLogs as well.


Create an RMAN Backup

ora10204>NLS_DATE_FORMAT=DD_MON_HH24_MI_SS;export NLS_DATE_FORMAT
ora10204>rman target /

Recovery Manager: Release 10.2.0.4.0 - Production on Sun Mar 7 22:54:29 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

connected to target database: ORT24FS (DBID=4163910544)

RMAN> backup database plus archivelog;


Starting backup at 07_MAR_22_54_39
current log archived
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=138 devtype=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: sid=137 devtype=DISK
channel ORA_DISK_1: starting archive log backupset
channel ORA_DISK_1: specifying archive log(s) in backup set
input archive log thread=1 sequence=68 recid=643 stamp=713055279
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_54_42
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_54_43
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225441_5s7hklr9_.bkp tag=TAG20100307T225441 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:02
Finished backup at 07_MAR_22_54_43

Starting backup at 07_MAR_22_54_43
using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
input datafile fno=00001 name=/oracle_fs/Databases/ORT24FS/system01.dbf
input datafile fno=00002 name=/oracle_fs/Databases/ORT24FS/undotbs01.dbf
input datafile fno=00010 name=/oracle_fs/Databases/ORT24FS/index_tbs_01.dbf
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_54_44
channel ORA_DISK_2: starting full datafile backupset
channel ORA_DISK_2: specifying datafile(s) in backupset
input datafile fno=00004 name=/oracle_fs/Databases/ORT24FS/users01.dbf
input datafile fno=00003 name=/oracle_fs/Databases/ORT24FS/sysaux01.dbf
input datafile fno=00005 name=/oracle_fs/Databases/ORT24FS/example01.dbf
input datafile fno=00009 name=/oracle_fs/Databases/ORT24FS/table_tbs_01.dbf
channel ORA_DISK_2: starting piece 1 at 07_MAR_22_54_44
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_55_49
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp tag=TAG20100307T225444 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:01:05
channel ORA_DISK_2: finished piece 1 at 07_MAR_22_56_54
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp tag=TAG20100307T225444 comment=NONE
channel ORA_DISK_2: backup set complete, elapsed time: 00:02:10
Finished backup at 07_MAR_22_56_55

Starting backup at 07_MAR_22_56_55
current log archived
using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting archive log backupset
channel ORA_DISK_1: specifying archive log(s) in backup set
input archive log thread=1 sequence=69 recid=645 stamp=713055302
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_56_55
channel ORA_DISK_2: starting archive log backupset
channel ORA_DISK_2: specifying archive log(s) in backup set
input archive log thread=1 sequence=73 recid=653 stamp=713055402
input archive log thread=1 sequence=74 recid=655 stamp=713055415
channel ORA_DISK_2: starting piece 1 at 07_MAR_22_56_55
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_56_56
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp tag=TAG20100307T225655 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_2: finished piece 1 at 07_MAR_22_56_56
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvy_.bkp tag=TAG20100307T225655 comment=NONE
channel ORA_DISK_2: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_1: starting archive log backupset
channel ORA_DISK_1: specifying archive log(s) in backup set
input archive log thread=1 sequence=70 recid=647 stamp=713055325
input archive log thread=1 sequence=71 recid=649 stamp=713055333
input archive log thread=1 sequence=72 recid=651 stamp=713055358
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_56_57
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_56_58
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hos0q_.bkp tag=TAG20100307T225655 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:02
Finished backup at 07_MAR_22_56_58

Starting Control File and SPFILE Autobackup at 07_MAR_22_56_58
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/autobackup/2010_03_07/o1_mf_s_713055418_5s7hotwl_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 07_MAR_22_57_02

RMAN>  

We can see that the ArchiveLog Sequence# at the beginning of the backup was 68. By the time the backup completed, it had gone to 72. There had been some transactions and log switches (causing new ArchiveLogs) while the Database (i.e. Datafiles) Backup was running.

22:53:58 SQL> show user
USER is "HEMANT"
22:54:41 SQL> create table abc_1 as select * from dba_objects;
 
Table created.

22:54:53 SQL> alter system switch logfile;

System altered.

22:55:06 SQL> create table abc_4 as select * from abc;

Table created.

22:55:20 SQL> alter system switch logfile;

System altered.

22:55:24 SQL> alter system switch logfile;

System altered.

22:55:33 SQL> insert into abc_4 select * from abc;

0 rows created.

22:55:41 SQL> alter system switch logfile;

System altered.

22:55:57 SQL> insert into abc_1 select * from dba_objects;

50745 rows created.

22:56:21 SQL> commit;  
alter s
Commit complete.

22:56:36 SQL> ystem switch logfile;

System altered.

22:56:40 SQL> 
22:56:57 SQL> select l.sequence#, l.status from v$log l order by 1;

 SEQUENCE# STATUS
---------- ----------------
        73 ACTIVE
        74 ACTIVE
        75 CURRENT

22:57:12 SQL>   

To "be safe" we have run another ArchiveLog Backup :

RMAN> backup archivelog all;

Starting backup at 07_MAR_22_58_31
current log archived
using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting archive log backupset
channel ORA_DISK_1: specifying archive log(s) in backup set
input archive log thread=1 sequence=68 recid=643 stamp=713055279
input archive log thread=1 sequence=69 recid=645 stamp=713055302
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_58_34
channel ORA_DISK_2: starting archive log backupset
channel ORA_DISK_2: specifying archive log(s) in backup set
input archive log thread=1 sequence=70 recid=647 stamp=713055325
input archive log thread=1 sequence=71 recid=649 stamp=713055333
input archive log thread=1 sequence=72 recid=651 stamp=713055358
input archive log thread=1 sequence=73 recid=653 stamp=713055402
channel ORA_DISK_2: starting piece 1 at 07_MAR_22_58_34
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_58_35
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp tag=TAG20100307T225834 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_2: finished piece 1 at 07_MAR_22_58_35
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp tag=TAG20100307T225834 comment=NONE
channel ORA_DISK_2: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_1: starting archive log backupset
channel ORA_DISK_1: specifying archive log(s) in backup set
input archive log thread=1 sequence=74 recid=655 stamp=713055415
input archive log thread=1 sequence=75 recid=657 stamp=713055514
channel ORA_DISK_1: starting piece 1 at 07_MAR_22_58_36
channel ORA_DISK_1: finished piece 1 at 07_MAR_22_58_37
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp tag=TAG20100307T225834 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:02
Finished backup at 07_MAR_22_58_37

Starting Control File and SPFILE Autobackup at 07_MAR_22_58_37
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/autobackup/2010_03_07/o1_mf_s_713055517_5s7hrxjg_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 07_MAR_22_58_39

RMAN>  

The Log Sequence# has gone higher.

22:59:34 SQL> select l.sequence#, l.status from v$log l order by 1;

 SEQUENCE# STATUS
---------- ----------------
        74 ACTIVE
        75 ACTIVE
        76 CURRENT

22:59:39 SQL> alter system checkpoint;

System altered.

22:59:45 SQL> select l.sequence#, l.status from v$log l order by 1;

 SEQUENCE# STATUS
---------- ----------------
        74 INACTIVE
        75 INACTIVE
        76 CURRENT

22:59:55 SQL> 

We now shutdown the database.

RMAN> shutdown

database closed
database dismounted
Oracle instance shut down

RMAN> exit


Recovery Manager complete.
ora10204> 

We delete database files to simulate loss of database.

ora10204>pwd
/oracle_fs/Databases/ORT24FS
ora10204>ls -l *.dbf
-rw-r----- 1 ora10204 dba  104865792 Mar  7 23:00 example01.dbf
-rw-r----- 1 ora10204 dba  104865792 Mar  7 23:00 index_tbs_01.dbf
-rw-r----- 1 ora10204 dba   52429312 Mar  7 23:00 redo01.dbf
-rw-r----- 1 ora10204 dba   52429312 Mar  7 22:56 redo02.dbf
-rw-r----- 1 ora10204 dba   52429312 Mar  7 22:58 redo03.dbf
-rw-r----- 1 ora10204 dba  304095232 Mar  7 23:00 sysaux01.dbf
-rw-r----- 1 ora10204 dba  985669632 Mar  7 23:00 system01.dbf
-rw-r----- 1 ora10204 dba  104865792 Mar  7 23:00 table_tbs_01.dbf
-rw-r----- 1 ora10204 dba  131080192 Mar  6 22:51 temp01.dbf
-rw-r----- 1 ora10204 dba  954212352 Mar  7 23:00 undotbs01.dbf
-rw-r----- 1 ora10204 dba 1343496192 Mar  7 23:00 users01.dbf
ora10204>rm e*.dbf i*.dbf s*.dbf t*.dbf u*.dbf
ora10204>ls -l
total 175176
-rw-r----- 1 ora10204 dba  7290880 Mar  7 23:00 control01.ctl
-rw-r----- 1 ora10204 dba  7290880 Mar  7 23:00 control02.ctl
-rw-r----- 1 ora10204 dba  7290880 Mar  7 23:00 control03.ctl
-rw-r----- 1 ora10204 dba 52429312 Mar  7 23:00 redo01.dbf
-rw-r----- 1 ora10204 dba 52429312 Mar  7 22:56 redo02.dbf
-rw-r----- 1 ora10204 dba 52429312 Mar  7 22:58 redo03.dbf
ora10204> 

We delete archivelogs to simulate loss of archivelogs from disk.

ora10204>pwd
/oracle_fs/ArchiveLogs/ORT24FS
ora10204>ls -l
total 12492
-rw-r----- 1 ora10204 dba  778752 Mar  7 22:54 1_68_709685307.dbf
-rw-r----- 1 ora10204 dba 6007296 Mar  7 22:55 1_69_709685307.dbf
-rw-r----- 1 ora10204 dba   19968 Mar  7 22:55 1_70_709685307.dbf
-rw-r----- 1 ora10204 dba    2048 Mar  7 22:55 1_71_709685307.dbf
-rw-r----- 1 ora10204 dba    1536 Mar  7 22:55 1_72_709685307.dbf
-rw-r----- 1 ora10204 dba 5901824 Mar  7 22:56 1_73_709685307.dbf
-rw-r----- 1 ora10204 dba    5120 Mar  7 22:56 1_74_709685307.dbf
-rw-r----- 1 ora10204 dba   31744 Mar  7 22:58 1_75_709685307.dbf
ora10204>rm *.dbf
ora10204> 

We delete ArchiveLog *BackupSets*. We want to see if the RECOVER DATABASE VALIDATE really checks them !

ora10204>pwd
/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07
ora10204>ls -ltr *
-rw-r----- 1 ora10204 dba     780288 Mar  7 22:54 o1_mf_annnn_TAG20100307T225441_5s7hklr9_.bkp
-rw-r----- 1 ora10204 dba  602611712 Mar  7 22:55 o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp
-rw-r----- 1 ora10204 dba 1579761664 Mar  7 22:56 o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp
-rw-r----- 1 ora10204 dba    5907968 Mar  7 22:56 o1_mf_annnn_TAG20100307T225655_5s7hoqvy_.bkp
-rw-r----- 1 ora10204 dba    6008832 Mar  7 22:56 o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp
-rw-r----- 1 ora10204 dba      24064 Mar  7 22:56 o1_mf_annnn_TAG20100307T225655_5s7hos0q_.bkp
-rw-r----- 1 ora10204 dba    5925376 Mar  7 22:58 o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp
-rw-r----- 1 ora10204 dba    6787072 Mar  7 22:58 o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp
-rw-r----- 1 ora10204 dba      37888 Mar  7 22:58 o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp
ora10204>rm o1_mf_a*.bkp
ora10204>ls -l
total 2133316
-rw-r----- 1 ora10204 dba  602611712 Mar  7 22:55 o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp
-rw-r----- 1 ora10204 dba 1579761664 Mar  7 22:56 o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp
ora10204> 

Now we use RMAN's RESTORE DATABASE VALIDATE command

ora10204>rman target /

Recovery Manager: Release 10.2.0.4.0 - Production on Sun Mar 7 23:06:00 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

connected to target database (not started)

RMAN> startup mount

Oracle instance started
database mounted

Total System Global Area     880803840 bytes

Fixed Size                     2087992 bytes
Variable Size                205521864 bytes
Database Buffers             666894336 bytes
Redo Buffers                   6299648 bytes

RMAN> restore database validate;

Starting restore at 07_MAR_23_06_18
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=157 devtype=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: sid=155 devtype=DISK

channel ORA_DISK_1: starting validation of datafile backupset
channel ORA_DISK_2: starting validation of datafile backupset
channel ORA_DISK_1: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp
channel ORA_DISK_2: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp
channel ORA_DISK_1: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp tag=TAG20100307T225444
channel ORA_DISK_1: validation complete, elapsed time: 00:00:25
channel ORA_DISK_2: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp tag=TAG20100307T225444
channel ORA_DISK_2: validation complete, elapsed time: 00:00:25
Finished restore at 07_MAR_23_06_46

RMAN>  

Surprising isn't it ? It didn't warn us that ArchiveLog BackupSets are missing.

Let's try again

RMAN> restore database validate until time "to_date('2010-03-07 22:58:37','YYYY-MM-DD HH24:MI:SS')";

Starting restore at 07_MAR_23_09_13
using channel ORA_DISK_1
using channel ORA_DISK_2

channel ORA_DISK_1: starting validation of datafile backupset
channel ORA_DISK_2: starting validation of datafile backupset
channel ORA_DISK_1: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp
channel ORA_DISK_2: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp
channel ORA_DISK_1: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp tag=TAG20100307T225444
channel ORA_DISK_1: validation complete, elapsed time: 00:00:04
channel ORA_DISK_2: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp tag=TAG20100307T225444
channel ORA_DISK_2: validation complete, elapsed time: 00:00:05
Finished restore at 07_MAR_23_09_18

RMAN>  

Hmm. The RESTORE DATABASE VALIDATE doesn't really check if ArchiveLogs required to achieve consistent recovery (whether Complete or Incomplete) are available !



Run a RESTORE and RECOVER ?

RMAN> restore database until time "to_date('2010-03-07 22:58:37','YYYY-MM-DD HH24:MI:SS')";

Starting restore at 07_MAR_23_11_17
using channel ORA_DISK_1
using channel ORA_DISK_2

channel ORA_DISK_1: starting datafile backupset restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
restoring datafile 00001 to /oracle_fs/Databases/ORT24FS/system01.dbf
restoring datafile 00002 to /oracle_fs/Databases/ORT24FS/undotbs01.dbf
restoring datafile 00010 to /oracle_fs/Databases/ORT24FS/index_tbs_01.dbf
channel ORA_DISK_1: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp
channel ORA_DISK_2: starting datafile backupset restore
channel ORA_DISK_2: specifying datafile(s) to restore from backup set
restoring datafile 00003 to /oracle_fs/Databases/ORT24FS/sysaux01.dbf
restoring datafile 00004 to /oracle_fs/Databases/ORT24FS/users01.dbf
restoring datafile 00005 to /oracle_fs/Databases/ORT24FS/example01.dbf
restoring datafile 00009 to /oracle_fs/Databases/ORT24FS/table_tbs_01.dbf
channel ORA_DISK_2: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp
channel ORA_DISK_1: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp tag=TAG20100307T225444
channel ORA_DISK_1: restore complete, elapsed time: 00:01:45
channel ORA_DISK_2: restored backup piece 1
piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp tag=TAG20100307T225444
channel ORA_DISK_2: restore complete, elapsed time: 00:02:10
Finished restore at 07_MAR_23_13_28

RMAN> recover database;

Starting recover at 07_MAR_23_13_41
using channel ORA_DISK_1
using channel ORA_DISK_2

starting media recovery

channel ORA_DISK_1: starting archive log restore to default destination
channel ORA_DISK_2: starting archive log restore to default destination
channel ORA_DISK_1: restoring archive log
archive log thread=1 sequence=70
channel ORA_DISK_2: restoring archive log
archive log thread=1 sequence=69
channel ORA_DISK_2: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp
channel ORA_DISK_1: restoring archive log
archive log thread=1 sequence=71
channel ORA_DISK_1: restoring archive log
archive log thread=1 sequence=72
ORA-19870: error reading backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp
ORA-19505: failed to identify file "/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp"
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
failover to previous backup
channel ORA_DISK_1: restoring archive log
archive log thread=1 sequence=73
channel ORA_DISK_1: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp
ORA-19870: error reading backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp
ORA-19505: failed to identify file "/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp"
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
channel ORA_DISK_2: starting archive log restore to default destination
channel ORA_DISK_2: restoring archive log
archive log thread=1 sequence=74
channel ORA_DISK_1: starting archive log restore to default destination
channel ORA_DISK_2: restoring archive log
archive log thread=1 sequence=75
channel ORA_DISK_2: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp
ORA-19870: error reading backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp
ORA-19505: failed to identify file "/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp"
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
channel ORA_DISK_1: restoring archive log
archive log thread=1 sequence=69
channel ORA_DISK_1: reading from backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp
ORA-19870: error reading backup piece /oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp
ORA-19505: failed to identify file "/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp"
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
failover to previous backup
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of recover command at 03/07/2010 23:13:47
RMAN-20506: no backup of archivelog found
RMAN-06053: unable to perform media recovery because of missing log
RMAN-06025: no backup of log thread 1 seq 69 lowscn 3064318 found to restore

RMAN>  

The RECOVER attempted to restore ArchiveLogs from BackupPieces that it assumed were present !!

RMAN> crosscheck backup;

using channel ORA_DISK_1
using channel ORA_DISK_2
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hknro_.bkp recid=474 stamp=713055284
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_nnndf_TAG20100307T225444_5s7hko8j_.bkp recid=475 stamp=713055285
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/autobackup/2010_03_07/o1_mf_s_713055418_5s7hotwl_.bkp recid=479 stamp=713055418
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/autobackup/2010_03_07/o1_mf_s_713055517_5s7hrxjg_.bkp recid=483 stamp=713055517
Crosschecked 10 objects

crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225441_5s7hklr9_.bkp recid=473 stamp=713055282
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvy_.bkp recid=476 stamp=713055415
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hoqvl_.bkp recid=477 stamp=713055415
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225655_5s7hos0q_.bkp recid=478 stamp=713055417
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtv9_.bkp recid=480 stamp=713055514
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrtr6_.bkp recid=481 stamp=713055514
crosschecked backup piece: found to be 'EXPIRED'
backup piece handle=/oracle_fs/FRAs/ORT24FS/ORT24FS/backupset/2010_03_07/o1_mf_annnn_TAG20100307T225834_5s7hrw0w_.bkp recid=482 stamp=713055516
Crosschecked 7 objects


RMAN>  

The CROSSCHECK now discovers that the BackupPieces for the ArchiveLog BackupSets are missing !


Bottom Line : The RESTORE DATABASE VALIDATE doesn't confirm that the restored database is recoverable. You must separately run RESTORE ARCHIVELOG ... VALIDATE !

RMAN> restore archivelog all validate;

Starting restore at 07_MAR_23_24_27
using channel ORA_DISK_1
using channel ORA_DISK_2

RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of restore command at 03/07/2010 23:24:28
RMAN-06026: some targets not found - aborting restore
RMAN-06025: no backup of log thread 1 seq 75 lowscn 3064629 found to restore
RMAN-06025: no backup of log thread 1 seq 74 lowscn 3064620 found to restore
RMAN-06025: no backup of log thread 1 seq 73 lowscn 3064476 found to restore
RMAN-06025: no backup of log thread 1 seq 72 lowscn 3064467 found to restore
RMAN-06025: no backup of log thread 1 seq 71 lowscn 3064463 found to restore
RMAN-06025: no backup of log thread 1 seq 70 lowscn 3064429 found to restore
RMAN-06025: no backup of log thread 1 seq 69 lowscn 3064318 found to restore
RMAN-06025: no backup of log thread 1 seq 68 lowscn 3063044 found to restore
RMAN-06025: no backup of log thread 1 seq 67 lowscn 3062407 found to restore
RMAN-06025: no backup of log thread 1 seq 66 lowscn 3062290 found to restore
RMAN-06025: no backup of log thread 1 seq 65 lowscn 3062155 found to restore
RMAN-06025: no backup of log thread 1 seq 64 lowscn 3061937 found to restore
RMAN-06025: no backup of log thread 1 seq 63 lowscn 3061572 found to restore
RMAN-06025: no backup of log thread 1 seq 62 lowscn 3057850 found to restore
RMAN-06025: no backup of log thread 1 seq 61 lowscn 2969959 found to restore
RMAN-06025: no backup of log thread 1 seq 60 lowscn 2954519 found to restore
RMAN-06025: no backup of log thread 1 seq 59 lowscn 2951005 found to restore
RMAN-06025: no backup of log thread 1 seq 58 lowscn 2947827 found to restore
RMAN-06025: no backup of log thread 1 seq 57 lowscn 2944286 found to restore
RMAN-06025: no backup of log thread 1 seq 56 lowscn 2939934 found to restore
RMAN-06025: no backup of log thread 1 seq 55 lowscn 2937195 found to restore
RMAN-06025: no backup of log thread 1 seq 54 lowscn 2882223 found to restore
RMAN-06025: no backup of log thread 1 seq 53 lowscn 2872012 found to restore
RMAN-06025: no backup of log thread 1 seq 52 lowscn 2865847 found to restore
RMAN-06025: no backup of log thread 1 seq 51 lowscn 2859351 found to restore
RMAN-06025: no backup of log thread 1 seq 50 lowscn 2852840 found to restore
RMAN-06025: no backup of log thread 1 seq 49 lowscn 2846285 found to restore
RMAN-06025: no backup of log thread 1 seq 48 lowscn 2839930 found to restore
RMAN-06025: no backup of log thread 1 seq 47 lowscn 2834297 found to restore
RMAN-06025: no backup of log thread 1 seq 46 lowscn 2828584 found to restore
RMAN-06025: no backup of log thread 1 seq 45 lowscn 2822885 found to restore
RMAN-06025: no backup of log thread 1 seq 44 lowscn 2815789 found to restore
RMAN-06025: no backup of log thread 1 seq 43 lowscn 2809530 found to restore
RMAN-06025: no backup of log thread 1 seq 42 lowscn 2803035 found to restore
RMAN-06025: no backup of log thread 1 seq 41 lowscn 2796478 found to restore
RMAN-06025: no backup of log thread 1 seq 40 lowscn 2789872 found to restore
RMAN-06025: no backup of log thread 1 seq 39 lowscn 2785329 found to restore
RMAN-06025: no backup of log thread 1 seq 38 lowscn 2785249 found to restore
RMAN-06025: no backup of log thread 1 seq 37 lowscn 2785175 found to restore
RMAN-06025: no backup of log thread 1 seq 36 lowscn 2785101 found to restore
RMAN-06025: no backup of log thread 1 seq 35 lowscn 2783479 found to restore
RMAN-06025: no backup of log thread 1 seq 34 lowscn 2777838 found to restore
RMAN-06025: no backup of log thread 1 seq 33 lowscn 2772060 found to restore
RMAN-06025: no backup of log thread 1 seq 32 lowscn 2766294 found to restore
RMAN-06025: no backup of log thread 1 seq 31 lowscn 2766115 found to restore
RMAN-06025: no backup of log thread 1 seq 30 lowscn 2766041 found to restore
RMAN-06025: no backup of log thread 1 seq 29 lowscn 2765896 found to restore
RMAN-06025: no backup of log thread 1 seq 28 lowscn 2765626 found to restore
RMAN-06025: no backup of log thread 1 seq 27 lowscn 2758329 found to restore
RMAN-06025: no backup of log thread 1 seq 26 lowscn 2752032 found to restore
RMAN-06025: no backup of log thread 1 seq 25 lowscn 2745302 found to restore
RMAN-06025: no backup of log thread 1 seq 24 lowscn 2738701 found to restore
RMAN-06025: no backup of log thread 1 seq 23 lowscn 2732175 found to restore
RMAN-06025: no backup of log thread 1 seq 22 lowscn 2729394 found to restore
RMAN-06025: no backup of log thread 1 seq 21 lowscn 2729288 found to restore
RMAN-06025: no backup of log thread 1 seq 20 lowscn 2729177 found to restore
RMAN-06025: no backup of log thread 1 seq 19 lowscn 2729066 found to restore
RMAN-06025: no backup of log thread 1 seq 18 lowscn 2725897 found to restore
RMAN-06025: no backup of log thread 1 seq 17 lowscn 2720244 found to restore
RMAN-06025: no backup of log thread 1 seq 16 lowscn 2714572 found to restore
MAN-06025: no backup of log thread 1 seq 15 lo
RMAN>  

OR

RMAN> restore archivelog from sequence 69 until sequence 73 validate;

Starting restore at 07_MAR_23_38_43
using channel ORA_DISK_1
using channel ORA_DISK_2

RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of restore command at 03/07/2010 23:38:44
RMAN-06026: some targets not found - aborting restore
RMAN-06025: no backup of log thread 1 seq 73 lowscn 3064476 found to restore
RMAN-06025: no backup of log thread 1 seq 72 lowscn 3064467 found to restore
RMAN-06025: no backup of log thread 1 seq 71 lowscn 3064463 found to restore
RMAN-06025: no backup of log thread 1 seq 70 lowscn 3064429 found to restore
RMAN-06025: no backup of log thread 1 seq 69 lowscn 3064318 found to restore

RMAN> 

Bottom Line : The RESTORE DATABASE VALIDATE doesn't confirm that the restored database is recoverable. You must separately run RESTORE ARCHIVELOG ... VALIDATE !
(The CROSSCHECK doesn't read the whole backuppiece to check for corruption, it only checks the header of each backuppiece, so the RESTORE ... VALIDATE is still preferred).

.
.
.