Pythian Blog: Technical Track

When RMAN Validate Creates New Files

by Jared Still on Mar 19, 2014 12:00:00 AM

While doing some testing I found something happening with RMAN that was unexpected. After making an RMAN backup, I would run the VALIDATE RECOVERY FILES command. When it completed I found there were twice as many backup files as when I started. Please note that this is Oracle 11.2.0.3 - that will be important later on. Here is the list of current backup files: [code lang="sql"] RMAN crosscheck backup; using channel ORA_DISK_1 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/orcl-rman-db-3ip3dlau_1_1.bkup RECID=112 STAMP=842454367 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/orcl-rman-db-3jp3dlcv_1_1.bkup RECID=113 STAMP=842454432 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/orcl-rman-arch-3lp3dlgs_1_1.bkup RECID=114 STAMP=842454556 Crosschecked 3 objects [/code] Following are some pertinent parameters: [code lang="sql"] 12:46:52 SYS@js01 AS SYSDBA show parameter db_recovery_file_dest NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_recovery_file_dest string /u01/app/oracle/fra db_recovery_file_dest_size big integer 4G 12:47:00 SYS@js01 AS SYSDBA show parameter log_archive_dest_1 NAME TYPE VALUE ------------------------------------ ----------- ---------------------------------- log_archive_dest_1 string LOCATION=USE_DB_RECOVERY_FILE_DEST [/code] Now see what happens when VALIDATE RECOVERY FILES is run. Listings may be edited for brevity. [code lang="sql"] RMAN validate recovery files; Starting validate at 18-MAR-14 using channel ORA_DISK_1 specification does not match any datafile copy in the repository channel ORA_DISK_1: starting validation of archived log channel ORA_DISK_1: specifying archived log(s) for validation input archived log thread=1 sequence=1212 RECID=581 STAMP=842454820 input archived log thread=1 sequence=1213 RECID=582 STAMP=842454821 ... input archived log thread=1 sequence=1232 RECID=601 STAMP=842531265 input archived log thread=1 sequence=1233 RECID=602 STAMP=842531265 channel ORA_DISK_1: validation complete, elapsed time: 00:00:01 List of Archived Logs ===================== Thrd Seq Status Blocks Failing Blocks Examined Name ---- ------- ------ -------------- --------------- --------------- 1 1212 OK 0 97494 /u01/app/oracle/fra/JS01/archivelog/2014_03_17/o1_mf_1_1212_9lgwwng0_.arc 1 1213 OK 0 97494 /u01/app/oracle/fra/JS01/archivelog/2014_03_17/o1_mf_1_1213_9lgwwnqx_.arc ... 1 1232 OK 0 13 /u01/app/oracle/fra/JS01/archivelog/2014_03_18/o1_mf_1_1232_9lk7kkvh_.arc 1 1233 OK 0 1 /u01/app/oracle/fra/JS01/archivelog/2014_03_18/o1_mf_1_1233_9lk7kkww_.arc channel ORA_DISK_1: input backup set: count=114, stamp=842454366, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/rman/orcl-rman-db-3ip3dlau_1_1.bkup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140317T150606_9lk8nfr3_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:35 channel ORA_DISK_1: input backup set: count=115, stamp=842454431, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/rman/orcl-rman-db-3jp3dlcv_1_1.bkup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140317T150606_9lk8ojtw_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:01 channel ORA_DISK_1: input backup set: count=117, stamp=842454556, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/rman/orcl-rman-arch-3lp3dlgs_1_1.bkup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140317T150915_9lk8okwy_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:03 Finished validate at 18-MAR-14 [/code] Notice that for each existing backup file an exact copy was made. This was verified by using md5sum to compare the file check sums. [code lang="sql"] == as shown by md5sum, these are exact duplicates [oracle@dev ]$ md5sum /u01/app/oracle/rman/orcl-rman-db-3ip3dlau_1_1.bkup /u01/app/oracle/rman/orcl-rman-db-3jp3dlcv_1_1.bkup /u01/app/oracle/rman/orcl-rman-arch-3lp3dlgs_1_1.bkup 21b1c12d47216ce8ac2413e8c7e3fc6e /u01/app/oracle/rman/orcl-rman-db-3ip3dlau_1_1.bkup 7524091d41785c793ff7f3f504b76082 /u01/app/oracle/rman/orcl-rman-db-3jp3dlcv_1_1.bkup 974bb354db9eb49770991334c891add5 /u01/app/oracle/rman/orcl-rman-arch-3lp3dlgs_1_1.bkup [oracle@dev ]$ md5sum /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140317T150606_9lk8nfr3_.bkp /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140317T150606_9lk8ojtw_.bkp /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140317T150915_9lk8okwy_.bkp 21b1c12d47216ce8ac2413e8c7e3fc6e /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140317T150606_9lk8nfr3_.bkp 7524091d41785c793ff7f3f504b76082 /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140317T150606_9lk8ojtw_.bkp 974bb354db9eb49770991334c891add5 /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140317T150915_9lk8okwy_.bkp [/code] It then occurred to me that maybe this behavior was for some reason due to creating backups outside the FRA, and Oracle for some reason wanted a copy of each file in the FRA. If so this would probably be a bug, but I thought it interesting enough to run a test. The following shows that all previous backups were removed, new ones created, as well as space consumed in the FRA. [code lang="sql"] == Delete all backups, and create backups in FRA only RMAN list backup; specification does not match any backup in the repository RMAN crosscheck backup; using channel ORA_DISK_1 specification does not match any backup in the repository ====== create new backups in FRA RMAN backup database; Starting backup at 18-MAR-14 using channel ORA_DISK_1 channel ORA_DISK_1: starting full datafile backup set channel ORA_DISK_1: specifying datafile(s) in backup set input datafile file number=00004 name=/u01/oradata/JS01/datafile/o1_mf_users_8g69rzg7_.dbf input datafile file number=00003 name=/u01/oradata/JS01/datafile/o1_mf_undotbs1_8g69rgd1_.dbf input datafile file number=00002 name=/u01/oradata/JS01/datafile/o1_mf_sysaux_8g69qxt0_.dbf input datafile file number=00001 name=/u01/oradata/JS01/datafile/o1_mf_system_8g69qb0g_.dbf input datafile file number=00005 name=/u01/oradata/JS01/datafile/o1_mf_atg_data_8hk7kc7f_.dbf channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: finished piece 1 at 18-MAR-14 piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp tag=TAG20140318T125302 comment=NONE channel ORA_DISK_1: backup set complete, elapsed time: 00:00:25 channel ORA_DISK_1: starting full datafile backup set channel ORA_DISK_1: specifying datafile(s) in backup set including current control file in backup set including current SPFILE in backup set channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: finished piece 1 at 18-MAR-14 piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk91s40_.bkp tag=TAG20140318T125302 comment=NONE channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01 Finished backup at 18-MAR-14 RMAN backup archivelog all delete input; Starting backup at 18-MAR-14 current log archived using channel ORA_DISK_1 channel ORA_DISK_1: starting archived log backup set channel ORA_DISK_1: specifying archived log(s) in backup set input archived log thread=1 sequence=1212 RECID=581 STAMP=842454820 input archived log thread=1 sequence=1213 RECID=582 STAMP=842454821 ... input archived log thread=1 sequence=1233 RECID=602 STAMP=842531265 input archived log thread=1 sequence=1234 RECID=603 STAMP=842532824 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: finished piece 1 at 18-MAR-14 piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk928t8_.bkp tag=TAG20140318T125344 comment=NONE channel ORA_DISK_1: backup set complete, elapsed time: 00:00:03 channel ORA_DISK_1: deleting archived log(s) archived log file name=/u01/app/oracle/fra/JS01/archivelog/2014_03_17/o1_mf_1_1212_9lgwwng0_.arc RECID=581 STAMP=842454820 archived log file name=/u01/app/oracle/fra/JS01/archivelog/2014_03_17/o1_mf_1_1213_9lgwwnqx_.arc RECID=582 STAMP=842454821 ... archived log file name=/u01/app/oracle/fra/JS01/archivelog/2014_03_18/o1_mf_1_1233_9lk7kkww_.arc RECID=602 STAMP=842531265 archived log file name=/u01/app/oracle/fra/JS01/archivelog/2014_03_18/o1_mf_1_1234_9lk928kg_.arc RECID=603 STAMP=842532824 Finished backup at 18-MAR-14 RMAN crosscheck backup; using channel ORA_DISK_1 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp RECID=145 STAMP=842532783 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk91s40_.bkp RECID=146 STAMP=842532809 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk928t8_.bkp RECID=147 STAMP=842532824 Crosschecked 3 objects 12:54:40 SYS@js01 AS SYSDBA @fra FILE_TYPE PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES -------------------- ------------------ ------------------------- --------------- CONTROL FILE 0 0 0 REDO LOG 0 0 0 ARCHIVED LOG 0 0 0 BACKUP PIECE 35.24 0 3 IMAGE COPY 0 0 0 FLASHBACK LOG 0 0 0 FOREIGN ARCHIVED LOG 0 0 0 7 rows selected. [/code] Again there are three backup files, this time in the FRA. The files are using 35% of the FRA space. Let's run another VALIDATE RECOVERY FILES and find out what happens. [code lang="sql"] RMAN validate recovery files; Starting validate at 18-MAR-14 using channel ORA_DISK_1 specification does not match any archived log in the repository specification does not match any datafile copy in the repository channel ORA_DISK_1: input backup set: count=140, stamp=842532782, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk955rv_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:15 channel ORA_DISK_1: input backup set: count=141, stamp=842532808, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk91s40_.bkp piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk95nvg_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:01 channel ORA_DISK_1: input backup set: count=142, stamp=842532824, piece=1 channel ORA_DISK_1: starting piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk928t8_.bkp piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk95oxv_.bkp comment=NONE channel ORA_DISK_1: finished piece 1 at 18-MAR-14 channel ORA_DISK_1: backup piece complete, elapsed time: 00:00:03 Finished validate at 18-MAR-14 RMAN crosscheck backup; using channel ORA_DISK_1 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp RECID=145 STAMP=842532783 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk955rv_.bkp RECID=148 STAMP=842532917 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk91s40_.bkp RECID=146 STAMP=842532809 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_ncsnf_TAG20140318T125302_9lk95nvg_.bkp RECID=149 STAMP=842532932 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk928t8_.bkp RECID=147 STAMP=842532824 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_annnn_TAG20140318T125344_9lk95oxv_.bkp RECID=150 STAMP=842532933 Crosschecked 6 objects 12:54:41 SYS@js01 AS SYSDBA @fra FILE_TYPE PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES -------------------- ------------------ ------------------------- --------------- CONTROL FILE 0 0 0 REDO LOG 0 0 0 ARCHIVED LOG 0 0 0 BACKUP PIECE 70.47 35.24 6 IMAGE COPY 0 0 0 FLASHBACK LOG 0 0 0 FOREIGN ARCHIVED LOG 0 0 0 7 rows selected. [/code] That is pretty clear - there are duplicates of each file. This is also shown by the FRA now being 70% consumed by backup pieces, whereas previously on 35% of the FRA was used. This seems like a bug, and a brief search of My Oracle Support finds this relevant document: Bug 14248496 RMAN 'validate recovery files' creates a piece copy for every execution This fits the situation pretty well, and the version of this database, 11.2.0.3, is one of the affected versions. As per the doc this bug is fixed in 11.2.0.4 The next step of course is to try this same operation in 11.2.0.4. This is also a Linux database running on Linux 6 - the only difference is that the database version is 11.2.0.4. [code lang="sql"] RMAN crosscheck backup; using channel ORA_DISK_1 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/rman-db-02p3ggdi_1_1.bkup RECID=1 STAMP=842547637 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/rman-db-03p3gggk_1_1.bkup RECID=2 STAMP=842547732 crosschecked backup piece: found to be 'AVAILABLE' backup piece handle=/u01/app/oracle/rman/rman-db-04p3ggjt_1_1.bkup RECID=3 STAMP=842547838 Crosschecked 3 objects RMAN validate recovery files; Starting validate at 18-MAR-14 using channel ORA_DISK_1 specification does not match any archived log in the repository specification does not match any datafile copy in the repository skipping backup sets; RECOVERY FILES, RECOVERY AREA or DB_RECOVERY_FILE_DEST option cannot validate backup set Finished validate at 18-MAR-14 [/code] That wasn't exactly promising - the VALIDATE RECOVERY FILES now just exits with a message that backup sets cannot be validated with this command. Apparently 'fixing' the bug was just a matter of disabling this bit of functionality. This is at odds with the Oracle 11g Documentation for RMAN VALIDATE From the section "RECOVERY FILES"
Validates all recovery files on disk, whether they are stored in the fast recovery area or other locations on disk. Recovery files include full and incremental backup sets, control file autobackups, archived redo log files, and data file copies. Flashback logs are not validated.
The Oracle 12c Documentation for 12c RMAN VALIDATE says the same thing, that is that backup sets are included in the files to be validated. Clearly the intent seems to have been for this to work with VALIDATE RECOVERY FILES, but for some reason the fix was simply to disable the functionality. So, what can you use instead? Now the VALIDATE BACKUPSET command must be used to validate the backups. This is not nearly as convenient as simply issuing the VALIDATE RECOVERY FILES command, as VALIDATE BACKUPSET takes a mandatory argument, which is the primary key of the backup set. The documentation recommends using the LIST BACKUPSET command, but this is rather inconvenient as the keys must be parsed from report text as seen. [code lang="sql"] RMAN list backupset; List of Backup Sets ================== BS Key Type LV Size Device Type Elapsed Time Completion Time ------- ---- -- ---------- ----------- ------------ --------------- 1 Full 9.36M DISK 00:00:04 18-MAR-14 BP Key: 1 Status: AVAILABLE Compressed: NO Tag: TAG20140318T170034 Piece Name: /u01/app/oracle/rman/rman-db-02p3ggdi_1_1.bkup SPFILE Included: Modification time: 18-MAR-14 SPFILE db_unique_name: ORCL Control File Included: Ckp SCN: 1014016 Ckp time: 18-MAR-14 BS Key Type LV Size Device Type Elapsed Time Completion Time ------- ---- -- ---------- ----------- ------------ --------------- 2 Full 1.07G DISK 00:01:36 18-MAR-14 BP Key: 2 Status: AVAILABLE Compressed: NO Tag: TAG20140318T170212 Piece Name: /u01/app/oracle/rman/rman-db-03p3gggk_1_1.bkup List of Datafiles in backup set 2 File LV Type Ckp SCN Ckp Time Name ---- -- ---- ---------- --------- ---- 1 Full 1014604 18-MAR-14 /u02/app/oracle/oradata/orcl/system01.dbf 2 Full 1014604 18-MAR-14 /u02/app/oracle/oradata/orcl/sysaux01.dbf 3 Full 1014604 18-MAR-14 /u02/app/oracle/oradata/orcl/undotbs01.dbf 4 Full 1014604 18-MAR-14 /u02/app/oracle/oradata/orcl/users01.dbf 5 Full 1014604 18-MAR-14 /u02/app/oracle/oradata/orcl/example01.dbf BS Key Type LV Size Device Type Elapsed Time Completion Time ------- ---- -- ---------- ----------- ------------ --------------- 3 Full 9.36M DISK 00:00:02 18-MAR-14 BP Key: 3 Status: AVAILABLE Compressed: NO Tag: TAG20140318T170212 Piece Name: /u01/app/oracle/rman/rman-db-04p3ggjt_1_1.bkup SPFILE Included: Modification time: 18-MAR-14 SPFILE db_unique_name: ORCL Control File Included: Ckp SCN: 1014639 Ckp time: 18-MAR-14 [/code] This is fine for manually validating just a few files, but is really not a workable solution for programmatically validating backup sets. Fortunately there is a better method - just use the v$backup_set_details view. [code lang="sql"] 1 select session_key, session_recid, session_stamp, bs_key, recid 2 from v$backup_set_details 3* order by session_key 15:58:37 dev.jks.com - jkstill@js01 SQL / SESSION_KEY SESSION_RECID SESSION_STAMP BS_KEY RECID ----------- ------------- ------------- ---------- ---------- 469 469 842532214 106 106 469 469 842532214 107 107 469 469 842532214 105 105 3 rows selected. RMAN> validate backupset 105; Starting validate at 18-MAR-14 using channel ORA_DISK_1 channel ORA_DISK_1: starting validation of datafile backup set channel ORA_DISK_1: reading from backup piece /u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp channel ORA_DISK_1: piece handle=/u01/app/oracle/fra/JS01/backupset/2014_03_18/o1_mf_nnndf_TAG20140318T125302_9lk90z0k_.bkp tag=TAG20140318T125302 channel ORA_DISK_1: restored backup piece 1 channel ORA_DISK_1: validation complete, elapsed time: 00:00:07 Finished validate at 18-MAR-14 -- the same was done for BS_KEY values 106 and 107 [/code] It is usually a good idea to investigate when something is found to work differently than expected. It was certainly beneficial in this case, as I was developing code on 11.2.0.3 that would later run on 11.2.0.4. While that bit of code would not work as expected on 11.2.0.4, it would also not cause an error, and probably not be noticed until it caused a recovery problem. Using VALIDATE BACKUPSET is a workable solution, but not nearly as convenient as using VALIDATE RECOVERY FILES. Perhaps there will be a fix for it in future releases.

No Comments Yet

Let us know what you think

See all

See all

Subscribe by email
Follow us
Love Your Data
Pythian Logo

© 2024 All rights reserved.