07 June, 2015

RMAN -- 1 : Backup Job Details

Here's a post on how you could be misled by a simple report on the V$RMAN_BACKUP_JOB_DETAILS view.

Suppose I run RMAN Backups through a shell script.  Like this :

[oracle@localhost Hemant]$ ls -l *sh
-rwxrw-r-- 1 oracle oracle 336 Jun  7 17:30 Backup_DB_Plus_ArchLogs.sh
[oracle@localhost Hemant]$ cat Backup_DB_Plus_ArchLogs.sh
ORACLE_SID=orcl;export ORACLE_SID

rman << EOF
connect target /

spool log to Backup_DB_plus_ArchLogs.LOG

backup as compressed backupset database ;

sql 'alter system switch logfile';
sql 'alter system archive log current' ;

backup as compressed backupset archivelog all;

backup as compressed backupset current controlfile ;

EOF

[oracle@localhost Hemant]$   
[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ ./Backup_DB_Plus_ArchLogs.sh

Recovery Manager: Release 11.2.0.2.0 - Production on Sun Jun 7 17:31:06 2015

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

RMAN> 
connected to target database: ORCL (DBID=1229390655)

RMAN> 
RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> RMAN> [oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ 

I then proceed to check the results of the run in V$RMAN_BACKUP_JOB_DETAILS.

SQL> l
  1  select to_char(start_time,'DD-MON HH24:MI') StartTime, to_char(end_time,'DD-MON HH24:MI') EndTime,
  2  input_type, status
  3  from v$rman_backup_job_details
  4* where start_time > trunc(sysdate)+17.5/24
SQL> /

STARTTIME             ENDTIME               INPUT_TYPE    STATUS
--------------------- --------------------- ------------- -----------------------
07-JUN 17:31          07-JUN 17:31          DB FULL       FAILED

SQL> 

It says that I ran one FULL DATABASE Backup that failed. Is that really true ?  Let me check the RMAN spooled log.

[oracle@localhost Hemant]$ cat Backup_DB_plus_ArchLogs.LOG

Spooling started in log file: Backup_DB_plus_ArchLogs.LOG

Recovery Manager11.2.0.2.0

RMAN> 
RMAN> 
Starting backup at 07-JUN-15
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=60 device type=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: SID=59 device type=DISK
RMAN-06169: could not read file header for datafile 6 error reason 4
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of backup command at 06/07/2015 17:31:08
RMAN-06056: could not access datafile 6

RMAN> 
RMAN> 
sql statement: alter system switch logfile

RMAN> 
sql statement: alter system archive log current

RMAN> 
RMAN> 
Starting backup at 07-JUN-15
current log archived
using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting compressed archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=615 RECID=1 STAMP=881773851
channel ORA_DISK_1: starting piece 1 at 07-JUN-15
channel ORA_DISK_2: starting compressed archived log backup set
channel ORA_DISK_2: specifying archived log(s) in backup set
input archived log thread=1 sequence=616 RECID=2 STAMP=881773851
input archived log thread=1 sequence=617 RECID=3 STAMP=881773853
input archived log thread=1 sequence=618 RECID=4 STAMP=881774357
input archived log thread=1 sequence=619 RECID=5 STAMP=881774357
channel ORA_DISK_2: starting piece 1 at 07-JUN-15
channel ORA_DISK_2: finished piece 1 at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v12b_.bkp tag=TAG20150607T173112 comment=NONE
channel ORA_DISK_2: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_2: starting compressed archived log backup set
channel ORA_DISK_2: specifying archived log(s) in backup set
input archived log thread=1 sequence=620 RECID=6 STAMP=881775068
input archived log thread=1 sequence=621 RECID=7 STAMP=881775068
input archived log thread=1 sequence=622 RECID=8 STAMP=881775071
channel ORA_DISK_2: starting piece 1 at 07-JUN-15
channel ORA_DISK_1: finished piece 1 at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v10y_.bkp tag=TAG20150607T173112 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:03
channel ORA_DISK_2: finished piece 1 at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v292_.bkp tag=TAG20150607T173112 comment=NONE
channel ORA_DISK_2: backup set complete, elapsed time: 00:00:01
Finished backup at 07-JUN-15

Starting Control File and SPFILE Autobackup at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/autobackup/2015_06_07/o1_mf_s_881775075_bq83v3nr_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 07-JUN-15

RMAN> 
RMAN> 
Starting backup at 07-JUN-15
using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting compressed full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
including current control file in backup set
channel ORA_DISK_1: starting piece 1 at 07-JUN-15
channel ORA_DISK_1: finished piece 1 at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_ncnnf_TAG20150607T173117_bq83v6vg_.bkp tag=TAG20150607T173117 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 07-JUN-15

Starting Control File and SPFILE Autobackup at 07-JUN-15
piece handle=/NEW_FS/oracle/FRA/ORCL/autobackup/2015_06_07/o1_mf_s_881775080_bq83v88z_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 07-JUN-15

RMAN> 
RMAN> 

Recovery Manager complete.
[oracle@localhost Hemant]$ 

Hmm. There were *three* distinct BACKUP commands in the script file.  The first was BACKUP ... DATABASE ..., the second was BACKUP ... ARCHIVELOG ... and the third was BACKUP ... CURRENT CONTROLFILE.  All three were executed.
Only the first BACKUP execution failed.  The subsequent  two BACKUP commands succeeded.  They were for ArchiveLogs and the Controlfile.
And *yet* the view V$RMAN_BACKUP_JOB_DETAILS shows that I ran  a FULL DATABASE BACKUP that failed.  It tells me nothing about the ArchiveLogs and the ControlFile backups that did succeed !


What if I switch my strategy from using a shell script to an rman script ?

[oracle@localhost Hemant]$ ls -ltr *rmn
-rw-rw-r-- 1 oracle oracle 287 Jun  7 17:41 Backup_DB_plus_ArchLogs.rmn
[oracle@localhost Hemant]$ cat Backup_DB_plus_ArchLogs.rmn
connect target /

spool log to Backup_DB_plus_ArchLogs.TXT

backup as compressed backupset database ;

sql 'alter system switch logfile';
sql 'alter system archive log current' ;

backup as compressed backupset archivelog all;

backup as compressed backupset current controlfile;

exit

[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ rman @Backup_DB_plus_ArchLogs.rmn

Recovery Manager: Release 11.2.0.2.0 - Production on Sun Jun 7 17:42:17 2015

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

RMAN> connect target *
2> 
3> spool log to Backup_DB_plus_ArchLogs.TXT
4> 
5> backup as compressed backupset database ;
6> 
7> sql 'alter system switch logfile';
8> sql 'alter system archive log current' ;
9> 
10> backup as compressed backupset archivelog all;
11> 
12> backup as compressed backupset current controlfile;
13> 
14> exit[oracle@localhost Hemant]$ 




SQL> l
  1  select to_char(start_time,'DD-MON HH24:MI') StartTime, to_char(end_time,'DD-MON HH24:MI') EndTime,
  2  input_type, status
  3  from v$rman_backup_job_details
  4  where start_time > trunc(sysdate)+17.5/24
  5* order by start_time
SQL> /

STARTTIME             ENDTIME               INPUT_TYPE    STATUS
--------------------- --------------------- ------------- -----------------------
07-JUN 17:31          07-JUN 17:31          DB FULL       FAILED
07-JUN 17:42          07-JUN 17:42          DB FULL       FAILED

SQL> 

[oracle@localhost Hemant]$ 
[oracle@localhost Hemant]$ cat Backup_DB_plus_ArchLogs.TXT

connected to target database: ORCL (DBID=1229390655)

Spooling started in log file: Backup_DB_plus_ArchLogs.TXT

Recovery Manager11.2.0.2.0

Starting backup at 07-JUN-15
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=59 device type=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: SID=50 device type=DISK
RMAN-06169: could not read file header for datafile 6 error reason 4
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of backup command at 06/07/2015 17:42:19
RMAN-06056: could not access datafile 6

Recovery Manager complete.
[oracle@localhost Hemant]$ 

Now, this time, once the first BACKUP command failed, RMAN seems to have bailed out. It didn't even try executing the subsequent BACKUP commands !

How can V$RMAN_BACKUP_JOB_DETAILS differentiate from the two failed backups ?

SQL> l
  1  select to_char(start_time,'DD-MON HH24:MI') StartTime, to_char(end_time,'DD-MON HH24:MI') EndTime,
  2  input_bytes/1048576 Input_MB, output_bytes/1048576 Output_MB,
  3  input_type, status
  4  from v$rman_backup_job_details
  5  where start_time > trunc(sysdate)+17.5/24
  6* order by start_time
SQL> /

STARTTIME             ENDTIME                 INPUT_MB  OUTPUT_MB INPUT_TYPE    STATUS
--------------------- --------------------- ---------- ---------- ------------- -----------------------
07-JUN 17:31          07-JUN 17:31          71.5219727  34.878418 DB FULL       FAILED
07-JUN 17:42          07-JUN 17:42                   0          0 DB FULL       FAILED

SQL> 

The Input Bytes does indicate that some files were backed up in the first run. Yet, it doesn't tell us how much of those were ArchiveLogs and how much were the ControlFile.


Question 1 : How would you script your backups ?  (Hint : Differentiate between the BACKUP DATABASE and the BACKUP ARCHIVELOG runs).

Question 2 : Can you improve your Backup Reports ?

Yes, the RMAN LIST BACKUP command is useful.  But you can't select the columns, format the output or add text  as you would with a query on V$ views.

[oracle@localhost oracle]$ NLS_DATE_FORMAT=DD_MON_HH24_MI_SS;export NLS_DATE_FORMAT
[oracle@localhost oracle]$ rman target /

Recovery Manager: Release 11.2.0.2.0 - Production on Sun Jun 7 17:51:41 2015

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCL (DBID=1229390655)

RMAN> list backup completed after "trunc(sysdate)+17.5/24";

using target database control file instead of recovery catalog

List of Backup Sets
===================


BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
17      375.50K    DISK        00:00:01     07_JUN_17_31_13
        BP Key: 17   Status: AVAILABLE  Compressed: YES  Tag: TAG20150607T173112
        Piece Name: /NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v12b_.bkp

  List of Archived Logs in backup set 17
  Thrd Seq     Low SCN    Low Time        Next SCN   Next Time
  ---- ------- ---------- --------------- ---------- ---------
  1    616     14068910   07_JUN_17_10_49 14068920   07_JUN_17_10_51
  1    617     14068920   07_JUN_17_10_51 14068931   07_JUN_17_10_53
  1    618     14068931   07_JUN_17_10_53 14069550   07_JUN_17_19_17
  1    619     14069550   07_JUN_17_19_17 14069564   07_JUN_17_19_17

BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
18      1.03M      DISK        00:00:00     07_JUN_17_31_14
        BP Key: 18   Status: AVAILABLE  Compressed: YES  Tag: TAG20150607T173112
        Piece Name: /NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v292_.bkp

  List of Archived Logs in backup set 18
  Thrd Seq     Low SCN    Low Time        Next SCN   Next Time
  ---- ------- ---------- --------------- ---------- ---------
  1    620     14069564   07_JUN_17_19_17 14070254   07_JUN_17_31_08
  1    621     14070254   07_JUN_17_31_08 14070265   07_JUN_17_31_08
  1    622     14070265   07_JUN_17_31_08 14070276   07_JUN_17_31_11

BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
19      13.72M     DISK        00:00:02     07_JUN_17_31_14
        BP Key: 19   Status: AVAILABLE  Compressed: YES  Tag: TAG20150607T173112
        Piece Name: /NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_annnn_TAG20150607T173112_bq83v10y_.bkp

  List of Archived Logs in backup set 19
  Thrd Seq     Low SCN    Low Time        Next SCN   Next Time
  ---- ------- ---------- --------------- ---------- ---------
  1    615     14043833   12_JUN_23_28_21 14068910   07_JUN_17_10_49

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
20      Full    9.36M      DISK        00:00:00     07_JUN_17_31_15
        BP Key: 20   Status: AVAILABLE  Compressed: NO  Tag: TAG20150607T173115
        Piece Name: /NEW_FS/oracle/FRA/ORCL/autobackup/2015_06_07/o1_mf_s_881775075_bq83v3nr_.bkp
  SPFILE Included: Modification time: 07_JUN_17_28_15
  SPFILE db_unique_name: ORCL
  Control File Included: Ckp SCN: 14070285     Ckp time: 07_JUN_17_31_15

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
21      Full    1.05M      DISK        00:00:02     07_JUN_17_31_19
        BP Key: 21   Status: AVAILABLE  Compressed: YES  Tag: TAG20150607T173117
        Piece Name: /NEW_FS/oracle/FRA/ORCL/backupset/2015_06_07/o1_mf_ncnnf_TAG20150607T173117_bq83v6vg_.bkp
  Control File Included: Ckp SCN: 14070306     Ckp time: 07_JUN_17_31_17

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
22      Full    9.36M      DISK        00:00:00     07_JUN_17_31_20
        BP Key: 22   Status: AVAILABLE  Compressed: NO  Tag: TAG20150607T173120
        Piece Name: /NEW_FS/oracle/FRA/ORCL/autobackup/2015_06_07/o1_mf_s_881775080_bq83v88z_.bkp
  SPFILE Included: Modification time: 07_JUN_17_31_18
  SPFILE db_unique_name: ORCL
  Control File Included: Ckp SCN: 14070312     Ckp time: 07_JUN_17_31_20

RMAN> 

So, the RMAN LIST BACKUP can provide details that V$RMAN_BACKUP_JOB_DETAILS cannot provide. Yet, it doesn't tell us that a Backup failed.
.
.
.

2 comments:

Andreas said...

Have you ever tried using two run-blocks or two separate calls to rman?

Hemant K Chitale said...

Yes, a day's backup can have two or more run-blocks or rman calls. For example, you might backup archivelogs every 4 hours -- 6 calls in a day. You might even have adhoc database backups before running major update scripts.