In an production environment, it is a common task to take backup and restore it using RMAN. So it is important to know the Tips and techniques for monitoring a restore/recovery operation and determine whether it is indeed working, slow or hung.
In general, a restore should take approximately the same time as a backup, if not longer. Therefore, if your backup took 10 hours to complete, it will take at least 10 hours to restore to the same host.
Another good indicator is to determine the duration of your previous restore/recovery operations. Monitor the logs and views and observe the rate of change. Restore and recovery operations are quite resource intensive so it’s important to understand if the process is working or hung.
RMAN Log
By default the result of an RMAN operation is written to the standard output. There is no default log file. You will need to capture the result using either the SPOOL TRACE option, or re-direct the standard output to a file.
Example of a restore datafile session:
RMAN> spool trace to res5.out RMAN> restore datafile 5; RMAN> spool trace off
$ cat res5.out RMAN> restore datafile 5; Starting restore at 27 DEC 2011 14:05:03 [1] using target database control file instead of recovery catalog allocated channel: ORA_DISK_1 channel ORA_DISK_1: sid=143 devtype=DISK [2] channel ORA_DISK_1: starting datafile backupset restore channel ORA_DISK_1: specifying datafile(s) to restore from backup set restoring datafile 00005 to /opt/app/oracle/oradata/ORA102/example01.dbf [3] channel ORA_DISK_1: reading from backup piece /opt/app/oracle/fra/ORA102/backupset/2011_12_27/o1_mf_nnndf_TAG20111227T122122_7hl7dm2n_.bkp [4] channel ORA_DISK_1: restored backup piece 1 piece handle=/opt/app/oracle/fra/ORA102/backupset/2011_12_27/o1_mf_nnndf_TAG20111227T122122_7hl7dm2n_.bkp tag=TAG20111227T122122 channel ORA_DISK_1: restore complete, elapsed time: 00:00:15 [5] Finished restore at 27 DEC 2011 14:05:19 [6]
From the above we can see:
- date and time when the restore started
- the database’s session ID in v$session – 143
- the datafile number and name where file will be restored to
- the backuppiece name and TAG
- the time taken for the restore of this datafile, and the channel used
- date and time when restore completed
Example of a recovery session:
RMAN> recover datafile 5; Starting recover at 27 DEC 2011 14:05:55 using channel ORA_DISK_1 starting media recovery channel ORA_DISK_1: starting archive log restore to default destination [1] channel ORA_DISK_1: restoring archive log [2] archive log thread=1 sequence=77 ... channel ORA_DISK_1: restoring archive log archive log thread=1 sequence=89 channel ORA_DISK_1: reading from backup piece /opt/app/oracle/fra/ORA102/backupset/2011_12_27/o1_mf_annnn_TAG20111227T135926_7hlf4jrk_.bkp channel ORA_DISK_1: restored backup piece 1 piece handle=/opt/app/oracle/fra/ORA102/backupset/2011_12_27/o1_mf_annnn_TAG20111227T135926_7hlf4jrk_.bkp tag=TAG20111227T135926 channel ORA_DISK_1: restore complete, elapsed time: 00:01:35 ... channel default: deleting archive log(s) archive log filename=/opt/app/oracle/fra/ORA102/archivelog/2011_12_27/o1_mf_1_88_7hlfmkr4_.arc recid=116 stamp=770998049 channel default: deleting archive log(s) [3] archive log filename=/opt/app/oracle/fra/ORA102/archivelog/2011_12_27/o1_mf_1_89_7hlfmbd8_.arc recid=104 stamp=770998043 media recovery complete, elapsed time: 00:00:01 [4] Finished recover at 27 DEC 2011 14:07:32 [5]
- the archivelogs are restored to default archive destination. Prior to the restore you must ensure that there is space available for the restore of these archivelogs.
- the archivelogs are restored from backup if they are not already on disk.
- once recovery is completed RMAN will automatically remove them from disk.
- time taken to recover this datafile.
- date and time when recover completed.
Alert.log
Restore Operation
Only RMAN restore operations are written to the alert.log. User-managed restore sessions will not appear in the alert.log as they are performed outside of Oracle.
Do not be alarmed if you see corruption errors in the alert.log during the RMAN RESTORE operation. Before restoring a datafile, RMAN will check for its existence and validity. If the file is already on disk but invalid or corrupted we report it. For example, at Sun Sep 27 08:25:54 2015 we see corruption being reported for datafile 1043:
Hex dump of (file 1043, block 1) in trace file /backup/claprd01/diag/rdbms/claprd01/CLAPRD01/trace/CLAPRD01_ora_14287316.trc Corrupt block relative dba: 0x05000001 (file 1043, block 1) Bad header found during kcvxfh v8 Data in bad block: type: 0 format: 2 rdba: 0x05000001 last change scn: 0x0000.00000000 seq: 0x1 flg: 0x05 spare1: 0x0 spare2: 0x0 spare3: 0x0 consistency value in tail: 0x00000001 check value in block header: 0x4a7 computed block checksum: 0x0 Reading datafile '+SYSFILES/epicaccess50.dbf' for corruption at rdba: 0x05000001 (file 1043, block 1) Reread (file 1043, block 1) found same corrupt data (no logical check) Sun Sep 27 08:25:54 2015
Later on we see the file is restored from valid backup and no further corruptions are reported on this datafile:
Sun Sep 27 08:39:08 2015 Full restore complete of datafile 1043 +SYSFILES/epicaccess50.dbf. Elapsed time: 1:27:39 checkpoint is 90364602816 last deallocation scn is 45006515743
Recovery Operation
All recovery sessions, whether user-managed or RMAN will also be written to the alert.log. This is an example of a RMAN recovery session:
Tue Dec 27 14:05:55 EST 2011 alter database recover datafile list clear Tue Dec 27 14:05:55 EST 2011Completed: alter database recover datafile list clear Tue Dec 27 14:05:55 EST 2011 alter database recover if needed datafile 5 Media Recovery Start parallel recovery started with 2 processesORA-279 signalled during: alter database recover if needed datafile 5 ... Tue Dec 27 14:05:56 EST 2011 The input backup piece /opt/app/oracle/fra/ORA102/backupset/2011_12_27/o1_mf_annnn_TAG20111227T135926_7hlf4jrk_.bkp is in compressed format.Tue Dec 27 14:07:23 EST 2011 [1] Archivelog restore complete. Elapsed time: 0:00:01 [2] Archivelog restore complete. Elapsed time: 0:00:01 ... Tue Dec 27 14:07:31 EST 2011 alter database recover logfile '/opt/app/oracle/fra/ORA102/archivelog/2011_12_27/o1_mf_1_77_7hlfmdc7_.arc' ... Tue Dec 27 14:07:31 EST 2011 Media Recovery Log /opt/app/oracle/fra/ORA102/archivelog/2011_12_27/o1_mf_1_77_7hlfmdc7_.arc ORA-279 signalled during: alter database recover logfile '/opt/app/oracle/fra/ORA102/archivelog/2011_12_27 /o1_mf_1_77_7hlfmdc7_.arc' [3] ... Tue Dec 27 14:07:31 EST 2011 Media Recovery Log /opt/app/oracle/fra/ORA102/archivelog/2011_12_27/o1_mf_1_87_7hlfmk96_.arc Tue Dec 27 14:07:31 EST 2011 Recovery of Online Redo Log: Thread 1 Group 1 Seq 88 Reading mem 0 Mem# 0: /opt/app/oracle/oradata/ORA102/redo01.log [4] Tue Dec 27 14:07:31 EST 2011 Recovery of Online Redo Log: Thread 1 Group 2 Seq 89 Reading mem 0 Mem# 0: /opt/app/oracle/oradata/ORA102/redo02.log Tue Dec 27 14:07:31 EST 2011 Media Recovery Complete (ORA102)[5]
- this was in fact a compressed backuppiece. This information is only displayed in the alert.log rather than the RMAN restore log.
- the time taken to restore the archivelog.
- ORA-279 is informational – confirming the archivelog required for recovery.
- for complete recovery, Oracle will also need to apply the redo from the online logs.
- end of recovery.
User Managed Recovery Log
This is an example of a user-managed recovery. We are performing the recovery via SQL*Plus:
$ sqlplus SQL*Plus: Release 10.2.0.5.0 - Production on Wed Dec 28 09:59:41 2011 Copyright (c) 1982, 2010, Oracle. All Rights Reserved. Enter user-name: / as sysdba Connected to: Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production With the Partitioning, Data Mining and Real Application Testing options SQL> alter database datafile 5 offline; [1] Database altered. SQL> recover datafile 5; [2] ORA-00279: change 2989857 generated at 12/27/2011 12:50:00 needed for thread 1 ORA-00289: suggestion : /opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_79_7hnmjl2y_.arc ORA-00280: change 2989857 for thread 1 is in sequence #79 [3] Specify log: {<RET>=suggested | filename | AUTO | CANCEL} ORA-00279: change 2989860 generated at 12/27/2011 12:50:01 needed for thread 1 ORA-00289: suggestion : /opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_80_7hnmjmbc_.arc ORA-00280: change 2989860 for thread 1 is in sequence #80 ORA-00278: log file '/opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_79_7hnmjl2y_.arc' no longer needed for this recovery [4] Specify log: {<RET>=suggested | filename | AUTO | CANCEL} auto [5] ORA-00279: change 2989874 generated at 12/27/2011 12:50:39 needed for thread 1 ORA-00289: suggestion : /opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_81_7hnmjmkf_.arc ORA-00280: change 2989874 for thread 1 is in sequence #81 ORA-00278: log file '/opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_80_7hnmjmbc_.arc' no longer needed for this recovery ... ORA-00279: change 2991001 generated at 12/27/2011 12:58:00 needed for thread 1 ORA-00289: suggestion : /opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_87_7hnmjoc7_.arc ORA-00280: change 2991001 for thread 1 is in sequence #87 ORA-00278: log file '/opt/app/oracle/fra/ORA102/archivelog/2011_12_28/o1_mf_1_86_7hnmjkm0_.arc' no longer needed for this recovery Log applied. Media recovery complete. [6] SQL> SQL> alter database datafile 5 online; [7] Database altered.
- take the datafile offline in preparation for a restore from your user-managed backup
- once the datafile is restored from your user-managed backup, recover it
- the first archivelog required to recover this file
- we have pressed the ENTER key, hence asking Oracle to apply the log requested
- if there are a lot of archivelogs to apply and they are all in the archive directory, use the AUTO option for Oracle to apply the rest of the required archivelogs. Otherwise you will need to manually specify each archivelog requested, or press ENTER when prompted for each archivelog
- recovery is now complete
- place the datafile online, thus making it available for use again
Operating System Utilities
The file being restored should be increasing in size until its actual size. The timestamp should also be changing as the file is being updated by Oracle. Use an operating system utility such as “ls -lt” to see this information.
$ ls -ltr [full path and file name being restored]
For example:
$ ls -ltr /database/db251/asbs/BLOB_DOC_IMAGES_B12.dbf
You can also use operating system utilities such as vmstat, sar and iostat to monitor resource utilization. Is the hardware working to its full capacity? Where is the bottleneck? Are there other I/O intensive operations happening on the host? Install Oracle’s OSWatcher utility for more information if required.
If the files are being restored to ASM you should also be able to check its existence in ASM as well. Note however that you may only be able to see it in ASM once it has been fully restored.
Data Dictionary Views
All RMAN operations will have a corresponding database session. Therefore you can query the data dictionary to check its progress.
1. RMAN sessions
SQL> -- RMAN sessions
set linesize 100 trimspool on
COLUMN sid FORMAT 9999
COLUMN serial# ALIAS SER# FORMAT 99999
COLUMN spid FORMAT 9999
COLUMN username FORMAT a10
COLUMN status FORMAT a2
COLUMN program FORMAT a32
COLUMN logon_time form a15
COLUMN module form a30
COLUMN action form a35
COLUMN process form a14
SELECT
s.sid ,
s.serial# "ser#",
s.username,
to_char(s.logon_time,'DD-MM-RR hh24:mi') logon_time,
s.osuser,
s.process,
p.spid ,
s.machine,
substr(s.status,1,1) status,
s.program
FROM v$session s, v$process p
WHERE upper(s.program) like '%RMAN%'
AND s.paddr = p.addr (+)
ORDER by s.logon_time, s.sid
/
2. The percentage of work completed
Run the following queries at least 3 times, at 5 minute intervals to see progress/change.
SQL>set echo on feedback on
column path format a50
set header off
select
sl.sofar, sl.totalwork,
round(sl.sofar/sl.totalwork*100,2) "% Complete"
from v$session_longops sl, v$session s, v$process p
where p.addr = s.paddr
and sl.sid=s.sid
and sl.serial#=s.serial#
and opname LIKE 'RMAN%'
and opname NOT LIKE '%aggregate%'
and totalwork != 0
and sofar <> totalwork;
3. Session Waits
Are there any sessions in wait and what is it waiting for? Run the following queries at least 3 times, at 5 minute intervals to see progress/change.
set linesize 200 trimspool on col event form a25 col p1text form a15 col p1 form 999999 col p2text form a15 col p2 form 999999 col p3text form a10 col p3 form 9999 col waited form 9999 col waiting form 9999 select sid, event, p1text, p1, p2text, p2, p3text, p3, wait_time waited, seconds_in_wait waiting from gv$session_wait where event not like 'SQL*Net%' and event not like '%timer%' and event not like 'rdbms%' and event not like 'pipe%' and event not like 'DIAG%' and event not like 'Streams AQ%' and event not like 'VKTM%' and state = 'WAITING' order by seconds_in_wait /
4. Recovery Progress
What is the recovery progress? V$RECOVERY_PROGRESS is only populated when RECOVERY is in progress. A restore operation will not populate this view. So if you think a recovery process is slow – is it really at the recovery phase, or still restoring from RMAN backuppieces?
This is an example of a recovery progress:
22:27:38 SQL> select START_TIME,TYPE,ITEM,UNITS,SOFAR,TOTAL from v$recovery_progress; START_TIME TYPE ITEM UNITS SOFAR TOTAL --------------------------- --------------- -------------------------------- ------------------------ ---------- ---------- 12-nov-14 16:08:10 Media Recovery Average Apply Rate KB/sec 29713 0 12-nov-14 16:08:10 Media Recovery Redo Applied Megabytes 660747 0 12-nov-14 16:08:10 Media Recovery Last Applied Redo SCN+Time 0 0 12-nov-14 11:28:16 Media Recovery Checkpoint Time per Log Seconds 6 6 12-nov-14 11:28:16 Media Recovery Standby Apply Lag Seconds 0 0
Redo recovery rate is determined by a number of factors:
1. PARALLEL_EXECUTION_MESSAGE_SIZE
The default value for this parameter may not be big enough, thus consider increasing to its maximum operating system dependent value:
SQL> show parameter PARALLEL_EXECUTION_MESSAGE_SIZE SQL> alter system set parallel_execution_message_size=65535 scope=spfile;
This parameter change needs the database to be restarted/remounted.
2. native I/O rates at the hardware level – consult with your system administrator/hardware vendor for this.
3. recovery parallelism – This is operating system dependent – Oracle will startup the required number of parallel processes to perform this task. If you feel the need to manually specify this, then the commands are:
SQL> RECOVER datafile x,y,z parallel (degree 32);
OR
SQL> recover parallel 32;
4. if after tuning the above, redo apply rate is still not acceptable then you can temporarily set db_block_checking to false to try and boost recovery performance.
Media Management Logs
If restoring from tape, confirm that it is indeed restoring from tape rather than waiting on the media manager to service the request. Is the tape busy or idle? Ask your media management support team to confirm the rate at which data is being read from tape.