Wednesday, March 18, 2015

RMAN PITR Background Table Recovery in Oracle 12c



Summary


This appears to be one of the more popular and cooler new features in 12c.


What isn't quite so clear is the overhead of running this process: "This example assumes you are running in archivelog mode and have adequate backups in place to allow a recovery via a point in time clone."

So below I walk through a simple example and record some of the details for the background RMAN operations being run here.

Details


First setting our test up:

SQL> conn scott/tiger
Connected.

SQL> CREATE TABLE t1 (id NUMBER);
Table created.

SQL> INSERT INTO t1 VALUES (1);
1 row created.

SQL> COMMIT;
Commit complete.

SQL> conn / as sysdba
Connected.

SQL> SELECT current_scn FROM V$DATABASE;
CURRENT_SCN
-----------
   1966405       << we are going to perform PITR to this point

SQL> conn scott/tiger
Connected.

SQL> INSERT INTO t1 VALUES (2);
1 row created.

SQL> COMMIT;
Commit complete.


Now lets perform the background RMAN PITR to restore the version of the table at SCN=1966405, in a new table called T1_PREV:

RECOVER TABLE 'SCOTT'.'T1' UNTIL SCN 1966405 AUXILIARY DESTINATION '/u01/aux'  REMAP TABLE 'SCOTT'.'T1':'T1_PREV';

Below I show the full log of the RMAN operations (with some highlights), which include
  • a full clone of the database (under /u01/aux)
  • PITR for the clone to the SCN=1966405
  • expdp of the required data/table (i.e. SCOTT.T1)
  • impdp of table into a new table (i.e. SCOTT.T1_PREV)
All this (on my very small database) this took about 2 or 3 minutes to run in total (between 9.36am and 9.39am) , during which time there was a 2nd temporary oracle instance (with 1G SGA) was running:

[oracle@ora12c66 ~]$ ps -ef|grep pmon
oracle     342 32742  0 09:37 pts/6    00:00:00 grep pmon
oracle   31873     1  0 09:06 ?        00:00:00 ora_pmon_orcl12c
oracle   32767     1  0 09:37 ?        00:00:00 ora_pmon_ersE
[oracle@ora12c66 ~]$
[oracle@ora12c66 ~]$ ps -ef|grep ersE
oracle     301     1  0 09:37 ?        00:00:00 ora_psp0_ersE
oracle     303     1  8 09:37 ?        00:00:02 ora_vktm_ersE
oracle     307     1  0 09:37 ?        00:00:00 ora_gen0_ersE
oracle     309     1  0 09:37 ?        00:00:00 ora_mman_ersE
oracle     313     1  0 09:37 ?        00:00:00 ora_diag_ersE
oracle     315     1  0 09:37 ?        00:00:00 ora_dbrm_ersE
oracle     317     1  0 09:37 ?        00:00:00 ora_dia0_ersE
oracle     319     1  0 09:37 ?        00:00:00 ora_dbw0_ersE
oracle     321     1  0 09:37 ?        00:00:00 ora_lgwr_ersE
oracle     323     1  0 09:37 ?        00:00:00 ora_ckpt_ersE
oracle     325     1  0 09:37 ?        00:00:00 ora_smon_ersE
oracle     327     1  0 09:37 ?        00:00:00 ora_reco_ersE
oracle     330     1  0 09:37 ?        00:00:00 ora_lreg_ersE
oracle     332     1 20 09:37 ?        00:00:06 ora_mmon_ersE
oracle     334     1  0 09:37 ?        00:00:00 ora_mmnl_ersE
oracle     354     1 23 09:37 ?        00:00:05 oracleersE (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle     356     1  0 09:37 ?        00:00:00 oracleersE (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle     358     1  0 09:37 ?        00:00:00 oracleersE (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
oracle     365     1  0 09:37 ?        00:00:00 ora_tmon_ersE
oracle     367     1  0 09:37 ?        00:00:00 ora_tt00_ersE
oracle     369     1  0 09:37 ?        00:00:00 ora_smco_ersE
oracle     371     1  0 09:37 ?        00:00:00 ora_fbda_ersE
oracle     373     1  0 09:37 ?        00:00:00 ora_w000_ersE
oracle     375     1  0 09:37 ?        00:00:00 ora_aqpc_ersE
oracle     379     1  0 09:37 ?        00:00:00 ora_p000_ersE
oracle     381     1  1 09:37 ?        00:00:00 ora_cjq0_ersE
oracle     383     1  0 09:37 ?        00:00:00 ora_p001_ersE
oracle     385     1  0 09:37 ?        00:00:00 ora_p002_ersE
oracle     387     1  0 09:37 ?        00:00:00 ora_p003_ersE
oracle     389     1  1 09:37 ?        00:00:00 ora_j000_ersE
oracle     391     1  0 09:37 ?        00:00:00 ora_j001_ersE
oracle     393     1  0 09:37 ?        00:00:00 ora_qm02_ersE
oracle     395     1  0 09:37 ?        00:00:00 ora_qm03_ersE
oracle     397     1  0 09:37 ?        00:00:00 ora_q002_ersE
oracle     399     1  0 09:37 ?        00:00:00 ora_q003_ersE
oracle     401     1 33 09:38 ?        00:00:02 ora_dm00_ersE
oracle     403     1 24 09:38 ?        00:00:00 ora_dw00_ersE
oracle     405 32742  0 09:38 pts/6    00:00:00 grep ersE
oracle   32767     1  0 09:37 ?        00:00:00 ora_pmon_ersE
[oracle@ora12c66 ~]$ ps -ef|grep ersE
oracle     463 32742  0 09:39 pts/6    00:00:00 grep ersE


As described above,  on the 2nd temporary server instance (db_unique_name=ersE_pitr_ORCL12C) the RMAN operation does the PITR recovery for the table "SCOTT"."T1"  to SCN 1966405  plus uses expdp and impdp to load this data back into a new "SCOTT"."T1_PREV" table   

  EXPDP> . . exported "SCOTT"."T1"                                5.015 KB       1 rows
  IMPDP> . . imported "SCOTT"."T1_PREV"                           5.015 KB       1 rows

This all worked and back in my original scott/tiger session the new i.e t1_prev appears, as if by magic:

SQL> select * from t1;
ID
----------
1
2

SQL> select * from t1_prev;
ID
----------
1




Lastly worth noting I did see some strange errors in the logs:

  EXPDP> ORA-39127: unexpected error from call to export_string :=SYS.DBMS_TRANSFORM_EXIMP.INSTANCE_INFO_EXP('AQ$_ORDERS_QUEUETABLE_S','IX',1,1,'12.01.00.00.00',newblock)
ORA-00376: file 2 cannot be read at this time
ORA-01110: data file 2: '/u01/oradata/orcl12c/example01.dbf'
ORA-06512: at "SYS.DBMS_TRANSFORM_EXIMP", line 197
ORA-06512: at line 1
ORA-06512: at "SYS.DBMS_METADATA", line 9901
ORA-39127: unexpected error from call to export_string :=SYS.DBMS_TRANSFORM_EXIMP.INSTANCE_INFO_EXP('AQ$_STREAMS_QUEUE_TABLE_S','IX',1,1,'12.01.00.00.00',newblock)
ORA-00376: file 2 cannot be read at this time
ORA-01110: data file 2: '/u01/oradata/orcl12c/example01.dbf'
ORA-06512: at "SYS.DBMS_TRANSFORM_EXIMP", line 197
ORA-06512: at line 1
ORA-06512: at "SYS.DBMS_METADATA", line 9901


but as the PITR recover worked as expected, I didn't investigate further.



Appendix A : Full Log of rman operations


Here is the full log of the RMAN operations (with some highlights)

[oracle@ora12c66 aux]$ rman target=/

Recovery Manager: Release 12.1.0.1.0 - Production on Wed Mar 18 09:36:19 2015

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

connected to target database: ORCL12C (DBID=705069227)

RMAN> RECOVER TABLE 'SCOTT'.'T1' UNTIL SCN 1966405 AUXILIARY DESTINATION '/u01/aux'  REMAP TABLE 'SCOTT'.'T1':'T1_PREV';

Starting recover at 18-MAR-15
using target database control file instead of recovery catalog
current log archived
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=55 device type=DISK
RMAN-05026: WARNING: presuming following set of tablespaces applies to specified Point-in-Time

List of tablespaces expected to have UNDO segments
Tablespace SYSTEM
Tablespace UNDOTBS1

Creating automatic instance, with SID='ersE'

initialization parameters used for automatic instance:
db_name=ORCL12C
db_unique_name=ersE_pitr_ORCL12C
compatible=12.1.0.0.0
db_block_size=8192
db_files=200
sga_target=1G
processes=80
diagnostic_dest=/u01
db_create_file_dest=/u01/aux
log_archive_dest_1='location=/u01/aux'
#No auxiliary parameter file used


starting up automatic instance ORCL12C

Oracle instance started

Total System Global Area    1068937216 bytes

Fixed Size                     2296576 bytes
Variable Size                281019648 bytes
Database Buffers             780140544 bytes
Redo Buffers                   5480448 bytes
Automatic instance created

contents of Memory Script:
{
# set requested point in time
set until  scn 1966405;
# restore the controlfile
restore clone controlfile;
# mount the controlfile
sql clone 'alter database mount clone database';
# archive current online log
sql 'alter system archive log current';
}
executing Memory Script

executing command: SET until clause

Starting restore at 18-MAR-15
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: SID=7 device type=DISK

channel ORA_AUX_DISK_1: starting datafile backup set restore
channel ORA_AUX_DISK_1: restoring control file
channel ORA_AUX_DISK_1: reading from backup piece /u01/fast_recovery_area/ORCL12C/autobackup/2015_03_18/o1_mf_s_874661278_bjlk8y4m_.bkp
channel ORA_AUX_DISK_1: piece handle=/u01/fast_recovery_area/ORCL12C/autobackup/2015_03_18/o1_mf_s_874661278_bjlk8y4m_.bkp tag=TAG20150318T092758
channel ORA_AUX_DISK_1: restored backup piece 1
channel ORA_AUX_DISK_1: restore complete, elapsed time: 00:00:01
output file name=/u01/aux/ORCL12C/controlfile/o1_mf_bjlkso5m_.ctl
Finished restore at 18-MAR-15

sql statement: alter database mount clone database

sql statement: alter system archive log current

contents of Memory Script:
{
# set requested point in time
set until  scn 1966405;
# set destinations for recovery set and auxiliary set datafiles
set newname for clone datafile  1 to new;
set newname for clone datafile  4 to new;
set newname for clone datafile  3 to new;
set newname for clone tempfile  1 to new;
# switch all tempfiles
switch clone tempfile all;
# restore the tablespaces in the recovery set and the auxiliary set
restore clone datafile  1, 4, 3;
switch clone datafile all;
}
executing Memory Script

executing command: SET until clause

executing command: SET NEWNAME

executing command: SET NEWNAME

executing command: SET NEWNAME

executing command: SET NEWNAME

renamed tempfile 1 to /u01/aux/ORCL12C/datafile/o1_mf_temp_%u_.tmp in control file

Starting restore at 18-MAR-15
using channel ORA_AUX_DISK_1

channel ORA_AUX_DISK_1: starting datafile backup set restore
channel ORA_AUX_DISK_1: specifying datafile(s) to restore from backup set
channel ORA_AUX_DISK_1: restoring datafile 00001 to /u01/aux/ORCL12C/datafile/o1_mf_system_%u_.dbf
channel ORA_AUX_DISK_1: restoring datafile 00004 to /u01/aux/ORCL12C/datafile/o1_mf_undotbs1_%u_.dbf
channel ORA_AUX_DISK_1: restoring datafile 00003 to /u01/aux/ORCL12C/datafile/o1_mf_sysaux_%u_.dbf
channel ORA_AUX_DISK_1: reading from backup piece /u01/fast_recovery_area/ORCL12C/backupset/2015_03_18/o1_mf_nnndf_TAG20150318T092731_bjlk83hn_.bkp
channel ORA_AUX_DISK_1: piece handle=/u01/fast_recovery_area/ORCL12C/backupset/2015_03_18/o1_mf_nnndf_TAG20150318T092731_bjlk83hn_.bkp tag=TAG20150318T092731
channel ORA_AUX_DISK_1: restored backup piece 1
channel ORA_AUX_DISK_1: restore complete, elapsed time: 00:00:25
Finished restore at 18-MAR-15

datafile 1 switched to datafile copy
input datafile copy RECID=4 STAMP=874661844 file name=/u01/aux/ORCL12C/datafile/o1_mf_system_bjlksvfk_.dbf
datafile 4 switched to datafile copy
input datafile copy RECID=5 STAMP=874661844 file name=/u01/aux/ORCL12C/datafile/o1_mf_undotbs1_bjlksvfw_.dbf
datafile 3 switched to datafile copy
input datafile copy RECID=6 STAMP=874661844 file name=/u01/aux/ORCL12C/datafile/o1_mf_sysaux_bjlksvfg_.dbf

contents of Memory Script:
{
# set requested point in time
set until  scn 1966405;
# online the datafiles restored or switched
sql clone "alter database datafile  1 online";
sql clone "alter database datafile  4 online";
sql clone "alter database datafile  3 online";
# recover and open database read only
recover clone database tablespace  "SYSTEM", "UNDOTBS1", "SYSAUX";
sql clone 'alter database open read only';
}
executing Memory Script

executing command: SET until clause

sql statement: alter database datafile  1 online

sql statement: alter database datafile  4 online

sql statement: alter database datafile  3 online

Starting recover at 18-MAR-15
using channel ORA_AUX_DISK_1

starting media recovery

archived log for thread 1 with sequence 18 is already on disk as file /u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_18_bjlk8wrj_.arc
archived log for thread 1 with sequence 19 is already on disk as file /u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_19_bjlks12c_.arc
archived log file name=/u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_18_bjlk8wrj_.arc thread=1 sequence=18
archived log file name=/u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_19_bjlks12c_.arc thread=1 sequence=19
media recovery complete, elapsed time: 00:00:00
Finished recover at 18-MAR-15

sql statement: alter database open read only

contents of Memory Script:
{
  sql clone "create spfile from memory";
  shutdown clone immediate;
  startup clone nomount;
  sql clone "alter system set  control_files =
 ''/u01/aux/ORCL12C/controlfile/o1_mf_bjlkso5m_.ctl'' comment=
''RMAN set'' scope=spfile";
  shutdown clone immediate;
  startup clone nomount;
# mount database
sql clone 'alter database mount clone database';
}
executing Memory Script

sql statement: create spfile from memory

database closed
database dismounted
Oracle instance shut down

connected to auxiliary database (not started)
Oracle instance started

Total System Global Area    1068937216 bytes

Fixed Size                     2296576 bytes
Variable Size                285213952 bytes
Database Buffers             775946240 bytes
Redo Buffers                   5480448 bytes

sql statement: alter system set  control_files =   ''/u01/aux/ORCL12C/controlfile/o1_mf_bjlkso5m_.ctl'' comment= ''RMAN set'' scope=spfile

Oracle instance shut down

connected to auxiliary database (not started)
Oracle instance started

Total System Global Area    1068937216 bytes

Fixed Size                     2296576 bytes
Variable Size                285213952 bytes
Database Buffers             775946240 bytes
Redo Buffers                   5480448 bytes

sql statement: alter database mount clone database

contents of Memory Script:
{
# set requested point in time
set until  scn 1966405;
# set destinations for recovery set and auxiliary set datafiles
set newname for datafile  6 to new;
# restore the tablespaces in the recovery set and the auxiliary set
restore clone datafile  6;
switch clone datafile all;
}
executing Memory Script

executing command: SET until clause

executing command: SET NEWNAME

Starting restore at 18-MAR-15
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: SID=7 device type=DISK

channel ORA_AUX_DISK_1: starting datafile backup set restore
channel ORA_AUX_DISK_1: specifying datafile(s) to restore from backup set
channel ORA_AUX_DISK_1: restoring datafile 00006 to /u01/aux/ERSE_PITR_ORCL12C/datafile/o1_mf_users_%u_.dbf
channel ORA_AUX_DISK_1: reading from backup piece /u01/fast_recovery_area/ORCL12C/backupset/2015_03_18/o1_mf_nnndf_TAG20150318T092731_bjlk83hn_.bkp
channel ORA_AUX_DISK_1: piece handle=/u01/fast_recovery_area/ORCL12C/backupset/2015_03_18/o1_mf_nnndf_TAG20150318T092731_bjlk83hn_.bkp tag=TAG20150318T092731
channel ORA_AUX_DISK_1: restored backup piece 1
channel ORA_AUX_DISK_1: restore complete, elapsed time: 00:00:01
Finished restore at 18-MAR-15

datafile 6 switched to datafile copy
input datafile copy RECID=8 STAMP=874661864 file name=/u01/aux/ERSE_PITR_ORCL12C/datafile/o1_mf_users_bjlkv733_.dbf

contents of Memory Script:
{
# set requested point in time
set until  scn 1966405;
# online the datafiles restored or switched
sql clone "alter database datafile  6 online";
# recover and open resetlogs
recover clone database tablespace  "USERS", "SYSTEM", "UNDOTBS1", "SYSAUX" delete archivelog;
alter clone database open resetlogs;
}
executing Memory Script

executing command: SET until clause

sql statement: alter database datafile  6 online

Starting recover at 18-MAR-15
using channel ORA_AUX_DISK_1

starting media recovery

archived log for thread 1 with sequence 18 is already on disk as file /u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_18_bjlk8wrj_.arc
archived log for thread 1 with sequence 19 is already on disk as file /u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_19_bjlks12c_.arc
archived log file name=/u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_18_bjlk8wrj_.arc thread=1 sequence=18
archived log file name=/u01/fast_recovery_area/ORCL12C/archivelog/2015_03_18/o1_mf_1_19_bjlks12c_.arc thread=1 sequence=19
media recovery complete, elapsed time: 00:00:00
Finished recover at 18-MAR-15

database opened

contents of Memory Script:
{
# create directory for datapump import
sql "create or replace directory TSPITR_DIROBJ_DPDIR as ''
/u01/aux''";
# create directory for datapump export
sql clone "create or replace directory TSPITR_DIROBJ_DPDIR as ''
/u01/aux''";
}
executing Memory Script

sql statement: create or replace directory TSPITR_DIROBJ_DPDIR as ''/u01/aux''

sql statement: create or replace directory TSPITR_DIROBJ_DPDIR as ''/u01/aux''

Performing export of tables...
  EXPDP> Starting "SYS"."TSPITR_EXP_ersE_fFjl":
  EXPDP> Estimate in progress using BLOCKS method...
  EXPDP> Processing object type TABLE_EXPORT/TABLE/TABLE_DATA
  EXPDP> Total estimation using BLOCKS method: 64 KB
  EXPDP> Processing object type TABLE_EXPORT/TABLE/TABLE
  EXPDP> Processing object type TABLE_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS
  EXPDP> Processing object type TABLE_EXPORT/TABLE/STATISTICS/MARKER
  EXPDP> ORA-39127: unexpected error from call to export_string :=SYS.DBMS_TRANSFORM_EXIMP.INSTANCE_INFO_EXP('AQ$_ORDERS_QUEUETABLE_S','IX',1,1,'12.01.00.00.00',newblock)
ORA-00376: file 2 cannot be read at this time
ORA-01110: data file 2: '/u01/oradata/orcl12c/example01.dbf'
ORA-06512: at "SYS.DBMS_TRANSFORM_EXIMP", line 197
ORA-06512: at line 1
ORA-06512: at "SYS.DBMS_METADATA", line 9901
ORA-39127: unexpected error from call to export_string :=SYS.DBMS_TRANSFORM_EXIMP.INSTANCE_INFO_EXP('AQ$_STREAMS_QUEUE_TABLE_S','IX',1,1,'12.01.00.00.00',newblock)
ORA-00376: file 2 cannot be read at this time
ORA-01110: data file 2: '/u01/oradata/orcl12c/example01.dbf'
ORA-06512: at "SYS.DBMS_TRANSFORM_EXIMP", line 197
ORA-06512: at line 1
ORA-06512: at "SYS.DBMS_METADATA", line 9901
  EXPDP> . . exported "SCOTT"."T1"                                5.015 KB       1 rows
  EXPDP> Master table "SYS"."TSPITR_EXP_ersE_fFjl" successfully loaded/unloaded
  EXPDP> ******************************************************************************
  EXPDP> Dump file set for SYS.TSPITR_EXP_ersE_fFjl is:
  EXPDP>   /u01/aux/tspitr_ersE_33377.dmp
  EXPDP> Job "SYS"."TSPITR_EXP_ersE_fFjl" completed with 2 error(s) at Wed Mar 18 09:38:30 2015 elapsed 0 00:00:30
Export completed


contents of Memory Script:
{
# shutdown clone before import
shutdown clone abort
}
executing Memory Script

Oracle instance shut down

Performing import of tables...
  IMPDP> Master table "SYS"."TSPITR_IMP_ersE_lgeA" successfully loaded/unloaded
  IMPDP> Starting "SYS"."TSPITR_IMP_ersE_lgeA":
  IMPDP> Processing object type TABLE_EXPORT/TABLE/TABLE
  IMPDP> Processing object type TABLE_EXPORT/TABLE/TABLE_DATA
  IMPDP> . . imported "SCOTT"."T1_PREV"                           5.015 KB       1 rows
  IMPDP> Processing object type TABLE_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS
  IMPDP> Processing object type TABLE_EXPORT/TABLE/STATISTICS/MARKER
  IMPDP> Job "SYS"."TSPITR_IMP_ersE_lgeA" successfully completed at Wed Mar 18 09:39:04 2015 elapsed 0 00:00:05
Import completed


Removing automatic instance
Automatic instance removed
auxiliary instance file /u01/aux/ORCL12C/datafile/o1_mf_temp_bjlktotl_.tmp deleted
auxiliary instance file /u01/aux/ERSE_PITR_ORCL12C/onlinelog/o1_mf_3_bjlkv96w_.log deleted
auxiliary instance file /u01/aux/ERSE_PITR_ORCL12C/onlinelog/o1_mf_2_bjlkv8z4_.log deleted
auxiliary instance file /u01/aux/ERSE_PITR_ORCL12C/onlinelog/o1_mf_1_bjlkv8mb_.log deleted
auxiliary instance file /u01/aux/ERSE_PITR_ORCL12C/datafile/o1_mf_users_bjlkv733_.dbf deleted
auxiliary instance file /u01/aux/ORCL12C/datafile/o1_mf_sysaux_bjlksvfg_.dbf deleted
auxiliary instance file /u01/aux/ORCL12C/datafile/o1_mf_undotbs1_bjlksvfw_.dbf deleted
auxiliary instance file /u01/aux/ORCL12C/datafile/o1_mf_system_bjlksvfk_.dbf deleted
auxiliary instance file /u01/aux/ORCL12C/controlfile/o1_mf_bjlkso5m_.ctl deleted
auxiliary instance file tspitr_ersE_33377.dmp deleted
Finished recover at 18-MAR-15

2 comments:

  1. Did you check about datapump export error got in recover

    ReplyDelete
  2. Did you check about datapump export error got in recover

    ReplyDelete