Friday, November 30, 2018

TDE–How to implement TDE in your database and what to think about (part 2)

This is the second part in a series on implementing TDE and what happens to the sizing.

At first my plan was to encrypt the dataset I created in my first post, but instead I compressed it.

At this point (and throughout this post), I am working with an un-encrypted dataset.

One of the first things to understand about Encryption is that encrypted data DOES NOT compress.
This is critical when understanding what happens when you implement TDE.

One way to save storage when implementing TDE is to implement encryption AND compression together.

In order to break down the affects of encryption on compressed data VS uncompressed data, I took my dataset (the SOE dataset from swing bench) and I compressed it.  I implemented Advanced compression on the tables, and I compressed the indexes and rebuilt them.

I now have 2 copies of the same dataset. 1 is compressed, and 1 is not.

Now let's take a look at the sizing of the Data sets and I will go through the same backup procedures and see what happens.

SEGMENT_NAME              SEGMENT_TYPE Space Used uncompressed   Space Used Compressed SPACE_SAVINGS
------------------------- ------------ ------------------------- -------------------- -------------
ADDRESSES                 TABLE           3,392 MB                  3,264 MB                      3
ADDRESS_CUST_IX           INDEX             703 MB                    728 MB                     -3
ADDRESS_PK                INDEX             662 MB                    888 MB                    -34
CARDDETAILS_CUST_IX       INDEX             703 MB                    562 MB                     20
CARD_DETAILS              TABLE           2,048 MB                  1,600 MB                     21
CARD_DETAILS_PK           INDEX             662 MB                      0 MB                    100
CUSTOMERS                 TABLE           3,328 MB                  2,880 MB                     13
CUSTOMERS_PK              INDEX             443 MB                      0 MB                    100
CUST_ACCOUNT_MANAGER_IX   INDEX             417 MB                    272 MB                     34
CUST_DOB_IX               INDEX             528 MB                    280 MB                     47
CUST_EMAIL_IX             INDEX             975 MB                    280 MB                     71
CUST_FUNC_LOWER_NAME_IX   INDEX             683 MB                    280 MB                     58
INVENTORIES               TABLE             176 MB                    176 MB                      0
INVENTORY_PK              INDEX              18 MB                      0 MB                    100
INV_PRODUCT_IX            INDEX              16 MB                     12 MB                     24
INV_WAREHOUSE_IX          INDEX              16 MB                     12 MB                     24
ITEM_ORDER_IX             INDEX           2,000 MB                  1,770 MB                     11
ITEM_PRODUCT_IX           INDEX           1,768 MB                  1,301 MB                     26
LOGON                     TABLE           1,728 MB                  1,728 MB                      0
ORDERENTRY_METADATA       TABLE               0 MB                      0 MB                      0
ORDERS                    TABLE           3,968 MB                  2,816 MB                     29
ORDER_ITEMS               TABLE           6,976 MB                  4,992 MB                     28
ORDER_ITEMS_PK            INDEX           2,234 MB                      0 MB                    100
ORDER_PK                  INDEX             632 MB                      0 MB                    100
ORD_CUSTOMER_IX           INDEX             671 MB                    480 MB                     28
ORD_ORDER_DATE_IX         INDEX             752 MB                    439 MB                     41
ORD_SALES_REP_IX          INDEX             594 MB                    438 MB                     26
ORD_WAREHOUSE_IX          INDEX             709 MB                    438 MB                     38
PRD_DESC_PK               INDEX               0 MB                      0 MB                    100
PRODUCT_DESCRIPTIONS      TABLE               0 MB                      0 MB                      0
PRODUCT_INFORMATION       TABLE               0 MB                      0 MB                      0
PRODUCT_INFORMATION_PK    INDEX               0 MB                      0 MB                    100
PROD_CATEGORY_IX          INDEX               0 MB                      0 MB                      0
PROD_NAME_IX              INDEX               0 MB                      0 MB                      0
PROD_SUPPLIER_IX          INDEX               0 MB                      0 MB                   -100
WAREHOUSES                TABLE               0 MB                      0 MB                      0
WAREHOUSES_PK             INDEX               0 MB                      0 MB                    100
WHS_LOCATION_IX           INDEX               0 MB                      0 MB                   -100


Here is the total savings by compressing both tables and indexes with advanced compression.

Space Used uncompressed   Space Used Compressed  SPACE_SAVINGS
------------------------- ---------------------- -------------
  36,804 MB                 25,636 MB                       30



Now to compare this with the previous data uncompressed I am going to backup by tablespace.  Below is the sizing of the backups. I used a tag to identify the backups.


-rw-rw----. 1 oracle oracle 26773323776 Nov 29 17:02 COMPRESSED_SOE.bkp
-rw-rw----. 1 oracle oracle 38441140224 Nov 29 17:04 UNCOMPRESSED_SOE.bkp
-rw-rw----. 1 oracle oracle 10987765760 Nov 29 18:35 BASIC_COMPRESSED_SOE.bkp
-rw-rw----. 1 oracle oracle 11135655936 Nov 29 18:36 BASIC_COMPRESSED_SOE_COMPRESSED.bkp
-rw-rw----. 1 oracle oracle 13360308224 Nov 29 20:12 MEDIUM_COMP_SOE_COMPRESSED.bkp
-rw-rw----. 1 oracle oracle 14383603712 Nov 29 20:12 MEDIUM_COMPRESSED_SOE_.bkp
-rw-rw----. 1 oracle oracle  9420791808 Nov 30 00:12 HIGH_COMP_SOE_COMPRESSED.bkp
-rw-rw----. 1 oracle oracle  9112944640 Nov 30 00:23 HIGH_COMPRESSED_SOE.bkp


Now I'm going to put that in a table and a chart to compare..

First the table of sizes



Now the chart


Now by looking at the chart it is apparent what happens with compression and the data.


  • Compression in the database reduced the size of the data by 30%
  • An uncompressed backupset matched the size of the data
  • Once I compressed the backupset, the difference is size was minimal.

** Bottom line - Compressing the data in the database saved on the uncompressed backupsize. Once the backupset is compressed the final size is about the same.

** Final conclusion -- Most modern backup appliances (ZDLRA, ZFS, DD) compress the backups.  When using those appliances with unencrypted data, the final size is the same regardless of whether the data is compressed in the Database.

Now that I've looked at both compressed and uncompressed data at the DB and backupset I am going to compress the data.  Next post.


Thursday, November 15, 2018

TDE–How to implement TDE in your database and what to think about (part 1)

This is the first part in a series of blog posts on TDE.
Many organizations are moving to TDE, and this can have a dramatic affect on your systems.
TDE impacts 2 areas
1) Post encryption compression goes away.  Encrypted data can’t be compressed.  Now why do I mention “Post encryption” ? This is because data can be compressed before encrypting.  Compressed data in your database (HCC, OLTP, basic etc.) is compressed PRIOR to encryption.  Utilizing compression in your database not only saves you disk space on your storage system, but it also saves you disk space for your backups.  The loss of compression post encryption can have many consequences you might not immediately think of
    • if you are using SSD storage that compresses blocks, you need to take into account the extra storage needed
    • If you are using a De-duplication appliance you will lose most of the benefits of de-duplication.
    • If you are compressing your backups, you will lose the benefits gained from compression (small backups and lowered network traffic).
2) Moving to TDE requires more space during the migration. Rebuilding the tablespaces with a newly encrypted copy is done by creating a second copy of each datafile (encrypted), and then removing the pre-encrypted copy.  The database switches to the new datafile when the process is complete.  This utilizes additional storage for the second copy of the datafiles.  The other migration impact is an increase in backup storage.  After encrypting tablespaces, a new level 0 backup is needed to ensure you are restoring to an encrypted copy of the data. Remember the encryption process changes all the blocks in the datafiles. I will discuss the backup implications more later.

Now I’m going to start by describing the dataset I used for testing.
In order to create this dataset I used the oewizard from Swingbench

Here are the objects and the sizes.

SEGMENT_NAME              SEGMENT_TYPE TABLESPACE_NAME SPACE_USED
------------------------- ------------ --------------- ------------
ADDRESSES                 TABLE        SOE                3,392 MB
ADDRESS_CUST_IX           INDEX        SOE                  703 MB
ADDRESS_PK                INDEX        SOE                  662 MB
CARDDETAILS_CUST_IX       INDEX        SOE                  703 MB
CARD_DETAILS              TABLE        SOE                2,048 MB
CARD_DETAILS_PK           INDEX        SOE                  662 MB
CUSTOMERS                 TABLE        SOE                3,328 MB
CUSTOMERS_PK              INDEX        SOE                  443 MB
CUST_ACCOUNT_MANAGER_IX   INDEX        SOE                  417 MB
CUST_DOB_IX               INDEX        SOE                  528 MB
CUST_EMAIL_IX             INDEX        SOE                  975 MB
CUST_FUNC_LOWER_NAME_IX   INDEX        SOE                  683 MB
INVENTORIES               TABLE        SOE                  176 MB
INVENTORY_PK              INDEX        SOE                   18 MB
INV_PRODUCT_IX            INDEX        SOE                   16 MB
INV_WAREHOUSE_IX          INDEX        SOE                   16 MB
ITEM_ORDER_IX             INDEX        SOE                2,000 MB
ITEM_PRODUCT_IX           INDEX        SOE                1,768 MB
LOGON                     TABLE        SOE                1,728 MB
ORDERENTRY_METADATA       TABLE        SOE                    0 MB
ORDERS                    TABLE        SOE                3,968 MB
ORDER_ITEMS               TABLE        SOE                6,976 MB
ORDER_ITEMS_PK            INDEX        SOE                2,234 MB
ORDER_PK                  INDEX        SOE                  632 MB
ORD_CUSTOMER_IX           INDEX        SOE                  671 MB
ORD_ORDER_DATE_IX         INDEX        SOE                  752 MB
ORD_SALES_REP_IX          INDEX        SOE                  594 MB
ORD_WAREHOUSE_IX          INDEX        SOE                  709 MB
PRD_DESC_PK               INDEX        SOE                    0 MB
PRODUCT_DESCRIPTIONS      TABLE        SOE                    0 MB
PRODUCT_INFORMATION       TABLE        SOE                    0 MB
PRODUCT_INFORMATION_PK    INDEX        SOE                    0 MB
PROD_CATEGORY_IX          INDEX        SOE                    0 MB
PROD_NAME_IX              INDEX        SOE                    0 MB
PROD_SUPPLIER_IX          INDEX        SOE                    0 MB
WAREHOUSES                TABLE        SOE                    0 MB
WAREHOUSES_PK             INDEX        SOE                    0 MB
WHS_LOCATION_IX           INDEX        SOE                    0 MB


TOTAL                                                                                 36,804 MB

Here is the total size for the data

TABLESPACE_NAME   FILE_ID FILE_NAME            SPACE_USED   TOTAL_ALLOCATED
--------------- --------- -------------------- ------------ --------------------
SYSTEM                  1 system01.dbf              819 MB       830 MB
SYSAUX                  3 sysaux01.dbf              809 MB       860 MB
UNDOTBS1                4 undotbs01.dbf             369 MB    29,180 MB
SOE                     5 soe_1.dbf               3,600 MB     5,120 MB
USERS                   7 users01.dbf                 5 MB         5 MB
SOE                     8 soe_2.dbf               3,841 MB     5,120 MB
SOE                     9 soe_3.dbf               3,822 MB     5,120 MB
SOE                    10 soe_4.dbf               3,825 MB     5,120 MB
SOE                    11 soe_5.dbf               3,806 MB     5,120 MB
SOE                    12 soe_6.dbf               3,728 MB     5,120 MB
SOE                    13 soe_7.dbf               3,781 MB     5,120 MB
SOE                    14 soe_8.dbf               3,442 MB     5,120 MB
SOE                    15 soe_9.dbf               3,464 MB     5,120 MB
SOE                    16 soe_10.dbf              3,495 MB     5,120 MB


===================================================================================================================

Total                                   38,303 MB      60,820 MB      22,517 MB

From above I can see that I am using 38 GB of space, out of the 61 GB of space allocated.
Now I created a backup set . With no compression the size of the backup set is about the size data used.
[oracle@oracle-server]$ ls -al
total 38910628
drwxrwx---. 2 oracle oracle          58 Nov 15 16:34 .
drwxrwx---. 3 oracle oracle          24 Nov 15 16:23 ..
-rw-rw----. 1 oracle oracle 39844478976 Nov 15 16:37 o1_mf_nnnd0_TAG20181115T163432_fyvsm8rz_.bkp
[oracle@oracle-server]$

Just to save my spot .I’m going to create a restore point to make this the starting point of all my testing.
SQL> create restore point new_database;

Restore point created.



Now let’s look at what happens when I compress the backup of this database

 oracle oracle 39844478976 Nov 15 16:37 o1_mf_nnnd0_TAG20181115T163432_fyvsm8rz_.bkp   ---> Original backup
 oracle oracle 11424759808 Nov 15 17:09 o1_mf_nnndf_TAG20181115T165247_fyvtoj7m_.bkp   ---> Basic Compression
 oracle oracle  9468592128 Nov 15 18:33 o1_mf_nnndf_TAG20181115T174452_fyvxq4s2_.bkp   ---> High Compression
 oracle oracle 14488240128 Nov 15 18:44 o1_mf_nnndf_TAG20181115T183319_fyw0l08k_.bkp   ---> Medium Compression

Finally I took an incremental merge backup to see what happens with that.

ls -al
total 62300276
drwxrwx---. 2 oracle oracle       4096 Nov 16 09:47 .
drwxrwx---. 7 oracle oracle         92 Nov 14 13:24 ..
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:38 o1_mf_soe_fyxolco8_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:39 o1_mf_soe_fyxon2o4_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:40 o1_mf_soe_fyxoohtl_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:41 o1_mf_soe_fyxopwy8_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:41 o1_mf_soe_fyxorb2f_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:42 o1_mf_soe_fyxosq7c_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:43 o1_mf_soe_fyxov49x_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:44 o1_mf_soe_fyxowklr_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:44 o1_mf_soe_fyxoxyl8_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:45 o1_mf_soe_fyxozcq9_.dbf
-rw-rw----. 1 oracle oracle 5368717312 Nov 16 09:46 o1_mf_soe_fyxp0rwd_.dbf
-rw-rw----. 1 oracle oracle  692068352 Nov 16 09:47 o1_mf_sysaux_fyxp3gc4_.dbf
-rw-rw----. 1 oracle oracle  859840512 Nov 16 09:46 o1_mf_system_fyxp2z72_.dbf
-rw-rw----. 1 oracle oracle 3187679232 Nov 16 09:46 o1_mf_undotbs1_fyxp2666_.dbf


Backup Method                    Backup Size         
Image Copy 62 GB
No Compression 40 GB
Basic Compression 11 GB
Medium Compression         14 GB
High Compression 95 GB


My next Blog will cover taking this data set and compressing it.




Wednesday, August 8, 2018

Restoring from multiple nodes in a RAC cluster

My previous post involved backing up from all nodes in a RAC cluster.  You can find it here.

In that post I explained why it is important to use multiples nodes to increase your throughput.

In this post I will explain how to restore using multiple nodes in the clusters.

First let's start with my database and drop it.

I stopped my database and went to ASM and removed all files from the disk group.


Step 1 -- Find the DBID from the rman catalog



select db_id,REG_DB_UNIQUE_NAME from db;

     DB_ID REG_DB_UNIQUE_NAME
---------- ------------------------------
4099465517 db1
3776942889 BRYAN
3281763275 db2
2294802577 db3

There it is !  My database BRYAN has a DBID of 3776942889


Step 2 --  Create a small initfile to use to start the database nomount.



db_name='bryan'
memory_target=1G
processes = 150


Step 3 --  start the database nomount.


startup nomount;
ORACLE instance started.

Total System Global Area 1073741824 bytes
Fixed Size            2932632 bytes
Variable Size          616562792 bytes
Database Buffers      394264576 bytes
Redo Buffers           59981824 bytes


Step 4 -- Connect to RMAN using the target / and catalog {my_rman_catalog}



Recovery Manager: Release 12.1.0.2.0 - Production on Wed Aug 8 11:26:18 2018

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

connected to target database: BRYAN (not mounted)
connected to recovery catalog database


Step 5 -- Set the DBID of the database.


RMAN set dbid=3776942889;

executing command: SET DBID
database name is "BRYAN" and DBID is 3776942889


Step 6 - Restore the SPFILE.



RMAN> run
2> {
3> allocate CHANNEL sbt1 DEVICE TYPE 'SBT_TAPE'  FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";
4> restore spfile;
5> }

allocated channel: sbt1
channel sbt1: SID=133 device type=SBT_TAPE
channel sbt1: RA Library (ZDLRA) SID=72F1DBDB0D05BC0FE05375AF880AE677

Starting restore at 08-AUG-2018 11:41:30

channel sbt1: starting datafile backup set restore
channel sbt1: restoring SPFILE
output file name=/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/spfilebryan1.ora
channel sbt1: reading from backup piece c-3776942889-20180808-0b
channel sbt1: piece handle=c-3776942889-20180808-0b tag=TAG20180808T093007
channel sbt1: restored backup piece 1
channel sbt1: restore complete, elapsed time: 00:00:25
Finished restore at 08-AUG-2018 11:43:22
released channel: sbt1




Step 7 - from asmcmd copy the spfile into ASM, and remove it from the OS.


ASMCMD> mkdir +datac1/bryan
ASMCMD> mkdir +datac1/bryan/parameterfile
ASMCMD> cp /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/spfilebryan1.ora +datac1/bryan/parameterfile/spfilebryan.ora
copying /u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/spfilebryan1.ora -> +datac1/bryan/parameterfile/spfilebryan.ora
ASMCMD> 



Step 8 - point the initfile to use the spfile on both instances. and restart the instance nomount using the spfile


Step 9 - Modify the service to use the spfile location


srvctl modify database -db bryan -spfile '+DATAC1/bryan/parameterfile/spfilebryan.ora'


Step 10 - recreate the password file and change the service to point to it.


orapwd file=+DATAC1/bryan/PASSWORD/pwdbryan.ora dbuniquename=bryan

srvctl modify database -db bryan -pwfile '+DATAC1/bryan/PASSWORD/pwdbryan.ora'


Step 11 - Restore the controlfiles



RMAN> set dbid=3776942889;

executing command: SET DBID
database name is "BRYAN" and DBID is 3776942889

RMAN> run
2> {
3> allocate CHANNEL sbt1 DEVICE TYPE 'SBT_TAPE'  FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";
4> restore controlfile;
5> }

allocated channel: sbt1
channel sbt1: SID=568 instance=bryan1 device type=SBT_TAPE
channel sbt1: RA Library (ZDLRA) SID=72F21BF1040F9F09E05375AF880A4C78

Starting restore at 08-AUG-2018 11:59:25

channel sbt1: starting datafile backup set restore
channel sbt1: restoring control file
channel sbt1: reading from backup piece c-3776942889-20180808-0b
channel sbt1: piece handle=c-3776942889-20180808-0b tag=TAG20180808T093007
channel sbt1: restored backup piece 1
channel sbt1: restore complete, elapsed time: 00:00:02
output file name=+DATAC1/BRYAN/CONTROLFILE/current.708.983620771
output file name=+DATAC1/BRYAN/CONTROLFILE/current.710.983620771
Finished restore at 08-AUG-2018 11:59:31
released channel: sbt1


Step 11 - Mount the database on all the nodes.


srvctl start database -d bryan -o mount

Step 12 - Connect to rman using the service, and restore the database.


rman

Recovery Manager: Release 12.1.0.2.0 - Production on Wed Aug 8 12:51:41 2018

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

RMAN> connect target sys/bryan@bryan

connected to target database: BRYAN (DBID=3776942889, not open)

RMAN> connect catalog /@zdl2ing-scan:1521/zdlra:dedicated

connected to recovery catalog database

RMAN> restore database;




Step 13. - Now let's check the log and make sure it restoring across all nodes.


Starting restore at 08-AUG-2018 12:52:07
allocated channel: ORA_SBT_TAPE_1
channel ORA_SBT_TAPE_1: SID=595 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_1: RA Library (ZDLRA) SID=72F2D881B658956EE05376AF880A153A
allocated channel: ORA_SBT_TAPE_2
channel ORA_SBT_TAPE_2: SID=64 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_2: RA Library (ZDLRA) SID=72F2D88B3E252398E05375AF880A7E91
allocated channel: ORA_SBT_TAPE_3
channel ORA_SBT_TAPE_3: SID=604 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_3: RA Library (ZDLRA) SID=72F2D894B4979578E05376AF880A512C
allocated channel: ORA_SBT_TAPE_4
channel ORA_SBT_TAPE_4: SID=586 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_4: RA Library (ZDLRA) SID=72F2D89E2F8D23B1E05375AF880AADDA
allocated channel: ORA_SBT_TAPE_5
channel ORA_SBT_TAPE_5: SID=613 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_5: RA Library (ZDLRA) SID=72F2D8A7B4E7958BE05376AF880ADDE6
allocated channel: ORA_SBT_TAPE_6
channel ORA_SBT_TAPE_6: SID=622 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_6: RA Library (ZDLRA) SID=72F2D8B13CF99592E05376AF880A55C4
allocated channel: ORA_SBT_TAPE_7
channel ORA_SBT_TAPE_7: SID=595 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_7: RA Library (ZDLRA) SID=72F2D8BADCBC2404E05375AF880A42C0
allocated channel: ORA_SBT_TAPE_8
channel ORA_SBT_TAPE_8: SID=631 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_8: RA Library (ZDLRA) SID=72F2D8C482E695ACE05376AF880A4989


OK.. I can see it is restoring on both instances.

Step 14 - shutdown down all instances


srvctl stop database -d bryan

Step 15 - Start up the first instance mount in RMAN and recover the database.


RMAN> startup mount;

Oracle instance started
database mounted

Total System Global Area   62813896704 bytes

Fixed Size                     7661424 bytes
Variable Size               9261025424 bytes
Database Buffers           53418655744 bytes
Redo Buffers                 126554112 bytes

RMAN> recover database;

Starting recover at 08-AUG-2018 13:00:15
allocated channel: ORA_SBT_TAPE_1
channel ORA_SBT_TAPE_1: SID=586 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_1: RA Library (ZDLRA) SID=72F2F5883A878935E05375AF880A8E9B
...
starting media recovery

channel ORA_SBT_TAPE_1: starting archived log restore to default destination
channel ORA_SBT_TAPE_1: restoring archived log
archived log thread=1 sequence=91
channel ORA_SBT_TAPE_1: reading from backup piece $RSCN_1594143_RTIM_983531820_THRD_1_SEQ_91_CTKEY_5520974_BACKUP
channel ORA_SBT_TAPE_2: starting archived log restore to default destination
channel ORA_SBT_TAPE_2: restoring archived log
archived log thread=2 sequence=34
channel ORA_SBT_TAPE_2: reading from backup piece $RSCN_1594143_RTIM_983531820_THRD_2_SEQ_34_CTKEY_5520979_BACKUP
channel ORA_SBT_TAPE_1: piece handle=$RSCN_1594143_RTIM_983531820_THRD_1_SEQ_91_CTKEY_5520974_BACKUP tag=TAG20180808T105809
channel ORA_SBT_TAPE_1: restored backup piece 1
channel ORA_SBT_TAPE_1: restore complete, elapsed time: 00:00:01
channel ORA_SBT_TAPE_2: piece handle=$RSCN_1594143_RTIM_983531820_THRD_2_SEQ_34_CTKEY_5520979_BACKUP tag=TAG20180808T105736
channel ORA_SBT_TAPE_2: restored backup piece 1
channel ORA_SBT_TAPE_2: restore complete, elapsed time: 00:00:01



Step 16  - Open the instance and startup the other instances.


That's it !

Backing up a RAC database with all nodes

Backing up a RAC environment from multiple DB nodes


I've been working with many customers who have never performed a multi-node backup for a RAC database.

If you didn't already know, in a RAC environment you can backup from more than 1 DB node.

Backing up from multiple DB nodes can be very important for a large multi-terabyte database to give you faster backup times.


** Keep in mind these throughput numbers would be the same for restore capability.

PART 1 - WHY


Why would I want to go through the trouble of backing up on multiple nodes ?

When looking at backup rates, the number to keep in mind is the backup rate for each network speed.

1   Gb/s  == 350 GB/hr
10 Gb/s == 3.5 TB/hr
25 Gb/s == 8.8 TB/hr

**  Note that networks are measured in small "b" which is bits/seconds
**  Database size is measured in large "B" which is Bytes.

The chart below gives you an idea of the impact of adding active network ports, and how the speed of the ports affects the backup throughput.
















Using this chart you can calculate how long it will take to backup your large database.

Here is the example of the number of hours it would take to backup a 50 T database..





PART 2 -  How ?


When performing a backup, the backup process uses channels.  I'm guessing you probably already knew that.  
Each allocated channel connects to a database instance and sends the backup through that channel to the backup location (disk, media manager, etc).
By default the allocated channel connects to the database instance that the RMAN process is executed from.
What this means is... if you are "inst_id 1" and execute a backup, all channels will be connected to "inst_id 1".

This can be changed within the channel allocation by using a channel parameter named "CONNECT".

The connect (as you expect) uses an ID and Password (or a wallet) to connect to a specific service, or by specifying an EZ Connect string.

For my example I am going to use a configure channel setting and a common service that is shared across all nodes and let it balance. the other options are

  • Create a specific service to control which instances are available for backing up.  
  • Manually allocate channels and specify the instance name in the connection.

Step 1 - Create a user for backing up


I'm going assume you are already on 12c, which contains the sysbackup role.
I'm going to create a user ,"backup_only", specifically for backing up, and I am going to use a complicated password.
Next,  I am going to grant that user sysbackup privlege.

SQL  create user backup_only identified by kkk3223490sf9090fjkljkl3590;

User created.

SQL   grant sysbackup to backup_only;

Grant succeeded.




Step 2 - Change the channel configuration to use this user


Now I am going to configure my channel to use this user for the connect clause.

Below is the statement I'm executing.  ** Notice I added the "as sysbackup" to the connection.

CONFIGURE CHANNEL DEVICE TYPE 'SBT_TAPE' connect 'backup_only/kkk3223490sf9090fjkljkl3590@bryan as sysbackup' FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";



This is for a ZDLRA so I have the additional information it needs for the library etc.

Notice that the I am including the id/password and tnsnames entry in the connection string.

This is what happens when I execute the configure command.



RMAN  
RMAN CONFIGURE CHANNEL DEVICE TYPE 'SBT_TAPE' connect * FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";
old RMAN configuration parameters:
CONFIGURE CHANNEL DEVICE TYPE 'SBT_TAPE' FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";
new RMAN configuration parameters:
CONFIGURE CHANNEL DEVICE TYPE 'SBT_TAPE' CONNECT '*' FORMAT   '%d_%U' PARMS  "SBT_LIBRARY=/u01/app/oracle/product/12.1.0.2/dbhome_1/lib/libra.so, ENV=(RA_WALLET='location=file:/u01/app/oracle/product/12.1.0.2/dbhome_1/dbs/zdlra credential_alias=zdl2ing-scan:1521/zdlra:dedicated')";
new RMAN configuration parameters are successfully stored
starting full resync of recovery catalog
full resync complete



One thing that stands out is that the connection information doesn't appear in the channel.  it is obfuscated by the '*' even though it is stored.


Step 3 - Execute backup


I can now execute my backup from either OEM, or from the command line.

This can be monitored (to ensure multiple nodes are used) by looking at the channel allocation in the output log of the backup.



Starting backup at 2018-08-08 09:27:17
allocated channel: ORA_SBT_TAPE_1
channel ORA_SBT_TAPE_1: SID=218 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_1: RA Library (ZDLRA) SID=72EFFBF5EAF19225E05376AF880A0BA7
allocated channel: ORA_SBT_TAPE_2
channel ORA_SBT_TAPE_2: SID=245 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_2: RA Library (ZDLRA) SID=72EFFBFF3A0E9235E05376AF880A1C6D
allocated channel: ORA_SBT_TAPE_3
channel ORA_SBT_TAPE_3: SID=615 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_3: RA Library (ZDLRA) SID=72EFFC0907A51E40E05375AF880AA173
allocated channel: ORA_SBT_TAPE_4
channel ORA_SBT_TAPE_4: SID=299 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_4: RA Library (ZDLRA) SID=72EFFC128EDD9244E05376AF880A6B6B
allocated channel: ORA_SBT_TAPE_5
channel ORA_SBT_TAPE_5: SID=64 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_5: RA Library (ZDLRA) SID=72EFFC1BD2EF924AE05376AF880A68B2
allocated channel: ORA_SBT_TAPE_6
channel ORA_SBT_TAPE_6: SID=64 instance=bryan1 device type=SBT_TAPE
channel ORA_SBT_TAPE_6: RA Library (ZDLRA) SID=72EFFC2595C71E53E05375AF880AA8D1
allocated channel: ORA_SBT_TAPE_7
channel ORA_SBT_TAPE_7: SID=74 instance=bryan2 device type=SBT_TAPE
channel ORA_SBT_TAPE_7: RA Library (ZDLRA) SID=72EFFC2FA4979254E05376AF880AF834
allocated channel: ORA_SBT_TAPE_8


Above is the example from my output.. You can see the that there were 8 channels allocated, and 5 of the channels were on the first instance and 3 were allocated on the second instance.

That's all there is to it !!

Next blog post is going to be restoring across multiple nodes in a RAC cluster.



Thursday, May 17, 2018

Multi-tenant backup and recover part 2

This blog is a followup on both backing up/recovering  a multi-tenant and restore/recovery prioritization.

In my last blog I went through the trace files on the recovery of a database.  I showed where it will ALWAYS go through any incremental backups before going to the archive logs.

WELL ---  I found an exception to this with PDB's on 12.2

Here's the scenario..

When perform a Point in Time recovery of a PDB database, it will not use the incremental backups.

In my test I created a PDB and performed a full backup along with 2 incremental backups.
After the second backup, I created a restore point.

Here is where the restore point is.


QL> select a.name,b.name,scn from v$restore_point a,v$pdbs b where a.con_id=b.con_id;

RESTORE POINT NAME                  PDB NAME                 SCN                                                
----------------------------------- ----------------      ------------
                                                
TEST                                 PDB1                  1543086 


Here is what I have for RMAN backups


starting full resync of recovery catalog
full resync complete

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


BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
237     Incr 0  480.62M    DISK        00:00:23     17-MAY-18      
        BP Key: 245   Status: AVAILABLE  Compressed: NO  Tag: TAG20180517T210354
        Piece Name: D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\EA727D0952C947CE8B2F124498996396\BACKUPSET\2018_05_17\O1_MF_NNND0_TAG20180517T210354_FHW9R000_.BKP
  List of Datafiles in backup set 237
  Container ID: 3, PDB Name: PDB1
  File LV Type Ckp SCN    Ckp Time  Abs Fuz SCN Sparse Name
  ---- -- ---- ---------- --------- ----------- ------ ----
  8    0  Incr 1541202    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSTEM01.DBF
  9    0  Incr 1541202    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSAUX01.DBF
  10   0  Incr 1541202    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\UNDOTBS01.DBF
  11   0  Incr 1541202    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\USERS01.DBF

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
336     Incr 1  1.89M      DISK        00:00:03     17-MAY-18      
        BP Key: 346   Status: AVAILABLE  Compressed: NO  Tag: TAG20180517T211010
        Piece Name: D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\EA727D0952C947CE8B2F124498996396\BACKUPSET\2018_05_17\O1_MF_NNND1_TAG20180517T211010_FHW9ZWXY_.BKP
  List of Datafiles in backup set 336
  Container ID: 3, PDB Name: PDB1
  File LV Type Ckp SCN    Ckp Time  Abs Fuz SCN Sparse Name
  ---- -- ---- ---------- --------- ----------- ------ ----
  8    1  Incr 1542930    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSTEM01.DBF
  9    1  Incr 1542930    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSAUX01.DBF
  10   1  Incr 1542930    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\UNDOTBS01.DBF
  11   1  Incr 1542930    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\USERS01.DBF

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
458     Incr 1  104.00K    DISK        00:00:02     17-MAY-18      
        BP Key: 474   Status: AVAILABLE  Compressed: NO  Tag: TAG20180517T211152
        Piece Name: D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\EA727D0952C947CE8B2F124498996396\BACKUPSET\2018_05_17\O1_MF_NNND1_TAG20180517T211152_FHWB32PX_.BKP
  List of Datafiles in backup set 458
  Container ID: 3, PDB Name: PDB1
  File LV Type Ckp SCN    Ckp Time  Abs Fuz SCN Sparse Name
  ---- -- ---- ---------- --------- ----------- ------ ----
  8    1  Incr 1543195    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSTEM01.DBF
  9    1  Incr 1543195    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSAUX01.DBF
  10   1  Incr 1543195    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\UNDOTBS01.DBF
  11   1  Incr 1543195    17-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\USERS01.DBF



You will note that I have 3 backupsets

  • Level 0  -- Ckp SCN  1541202

  • Level 1 -- Ckp SCN  1542930
  • Level 1 -- Ckp SCN 1542195
The restore point (SCN 1543086)  falls directly between the first level 1 and the second level 1

BUT.  here is the recovery log
it doesn't use the incrementals and goes straight to the archive logs.


Recovery Manager: Release 12.2.0.1.0 - Production on Thu May 17 21:22:58 2018

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

RMAN-06005: connected to target database: ORCL (DBID=1504172276)
RMAN-06008: connected to recovery catalog database

RMAN> 
RMAN-03090: Starting recover at 17-MAY-18
RMAN-08030: allocated channel: ORA_DISK_1
RMAN-08500: channel ORA_DISK_1: SID=273 device type=DISK


RMAN-08054: starting media recovery

RMAN-06050: archived log for thread 1 with sequence 4 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_4_FHW9XZK1_.ARC
RMAN-06050: archived log for thread 1 with sequence 5 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_5_FHW9Y1NM_.ARC
RMAN-06050: archived log for thread 1 with sequence 6 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_6_FHW9Z7YO_.ARC
RMAN-06050: archived log for thread 1 with sequence 7 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_7_FHWB07F4_.ARC
RMAN-06050: archived log for thread 1 with sequence 8 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_8_FHWB0RQG_.ARC
RMAN-06050: archived log for thread 1 with sequence 9 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_9_FHWB0T56_.ARC
RMAN-06050: archived log for thread 1 with sequence 10 is already on disk as file D:\APP\BGRENN\VIRTUAL\FAST_RECOVERY_AREA\ORCL\ORCL\ARCHIVELOG\2018_05_17\O1_MF_1_10_FHWB24PH_.ARC
RMAN-08181: media recovery complete, elapsed time: 00:00:15
RMAN-03091: Finished recover at 17-MAY-18

RMAN> 

Recovery Manager complete.



When going through the trace file here is the clue that it can't use the incremental backup for a PITR.

I see this message for all the datafiles

"Stop scn (1543359) is in the future of until scn (0) with no catalog, do not trust stopSCN"

Then I see this message "sys.dbms_backup_restore.recoverCancel"




DBGMISC:             ENTERED krmkgdf [21:25:08.011]
DBGMISC:              Retrieved file 8, created: 1527866, stopscn: 1543359, blocks: 32000 (rfno: 1, ts: SYSTEM [0]): [21:25:08.510] (krmkgdf)
DBGMISC:                 Name: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSTEM01.DBF (krmkgdf)
DBGMISC:                 Auxname:  (krmkgdf)
DBGMISC:                 Creation Thread: 1; Creation Size : 32000 [21:25:08.591] (krmkgdf)
DBGMISC:              Stop scn (1543359) is in the future of until scn (0) with no catalog, do not trust stopSCN [21:25:08.615] (krmkgdf)
DBGMISC:              File 8 is online [21:25:08.641] (krmkgdf)
DBGMISC:              Retrieved file 9, created: 1527869, stopscn: 1543359, blocks: 44800 (rfno: 4, ts: SYSAUX [1]): [21:25:08.665] (krmkgdf)
DBGMISC:                 Name: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSAUX01.DBF (krmkgdf)
DBGMISC:                 Auxname:  (krmkgdf)
DBGMISC:                 Creation Thread: 1; Creation Size : 42240 [21:25:08.750] (krmkgdf)
DBGMISC:              Stop scn (1543359) is in the future of until scn (0) with no catalog, do not trust stopSCN [21:25:08.782] (krmkgdf)
DBGMISC:              File 9 is online [21:25:08.857] (krmkgdf)
DBGMISC:              Retrieved file 10, created: 1527871, stopscn: 1543359, blocks: 12800 (rfno: 9, ts: UNDOTBS1 [2]): [21:25:08.883] (krmkgdf)
DBGMISC:                 Name: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\UNDOTBS01.DBF (krmkgdf)
DBGMISC:                 Auxname:  (krmkgdf)
DBGMISC:                 Creation Thread: 1; Creation Size : 12800 [21:25:09.082] (krmkgdf)
DBGMISC:              Stop scn (1543359) is in the future of until scn (0) with no catalog, do not trust stopSCN [21:25:09.106] (krmkgdf)
DBGMISC:              File 10 is online [21:25:09.140] (krmkgdf)
DBGMISC:              Retrieved file 11, created: 1528354, stopscn: 1543359, blocks: 640 (rfno: 11, ts: USERS [5]): [21:25:09.165] (krmkgdf)
DBGMISC:                 Name: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\USERS01.DBF (krmkgdf)
DBGMISC:                 Auxname:  (krmkgdf)
DBGMISC:                 Creation Thread: 1; Creation Size : 640 [21:25:09.248] (krmkgdf)
DBGMISC:              Stop scn (1543359) is in the future of until scn (0) with no catalog, do not trust stopSCN [21:25:09.272] (krmkgdf)
DBGMISC:              File 11 is online [21:25:09.306] (krmkgdf)
DBGMISC:              -- No more datafiles -- [21:25:09.331] (krmkgdf)
DBGMISC:              ENTERED krmkgbh [21:25:09.356]
DBGMISC:              EXITED krmkgbh with status No backup history required - no flags set [21:25:09.379] elapsed time [00:00:00:00.023]
DBGMISC:              ENTERED krmkLinkPrePluginDf [21:25:09.405]
DBGMISC:               Not qualified for PrePlugin translation [21:25:09.430] (krmkLinkPrePluginDf)
DBGMISC:              EXITED krmkLinkPrePluginDf with status Done [21:25:09.503] elapsed time [00:00:00:00.098]
DBGMISC:             EXITED krmkgdf [21:25:09.604] elapsed time [00:00:00:01.593]
DBGMISC:            EXITED krmkdbtr with address 57850840 [21:25:09.629] elapsed time [00:00:00:02.094]
DBGMISC:            krmknmtr:  the parse tree after name translation is: [21:25:09.653] (krmknmtr)
DBGMISC:              1 DFILE
DBGMISC:                  1 DF fno=8 pplfno=0 pdbid=3 pdbname=PDB1 crescn=1527866
DBGMISC:                     blksize=8192 blocks=32000 rfno=1 pdbForeignDbid=2445639199
DBGMISC:                    fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSTEM01.DBF
DBGMISC:                    ts=PDB1:SYSTEM, flags=KRMKDF_DATABASE, flags=KRMKDF_INBACKUP
DBGMISC:                    fedata: sta=0x80 crescn=1527866
DBGMISC:                  2 DF fno=9 pplfno=0 pdbid=3 pdbname=PDB1 crescn=1527869
DBGMISC:                     blksize=8192 blocks=44800 rfno=4 pdbForeignDbid=2445639199
DBGMISC:                    fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\SYSAUX01.DBF
DBGMISC:                    ts=PDB1:SYSAUX, flags=KRMKDF_DATABASE, flags=KRMKDF_INBACKUP
DBGMISC:                    fedata: sta=0x80 crescn=1527869
DBGMISC:                  3 DF fno=10 pplfno=0 pdbid=3 pdbname=PDB1 crescn=1527871
DBGMISC:                     blksize=8192 blocks=12800 rfno=9 pdbForeignDbid=2445639199
DBGMISC:                    fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\UNDOTBS01.DBF
DBGMISC:                    ts=PDB1:UNDOTBS1, flags=KRMKDF_DATABASE, flags=KRMKDF_INBACKUP
DBGMISC:                    fedata: sta=0x80 crescn=1527871
DBGMISC:                  4 DF fno=11 pplfno=0 pdbid=3 pdbname=PDB1 crescn=1528354
DBGMISC:                     blksize=8192 blocks=640 rfno=11 pdbForeignDbid=0
DBGMISC:                    fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\PDB1\USERS01.DBF
DBGMISC:                    ts=PDB1:USERS, flags=KRMKDF_DATABASE, flags=KRMKDF_INBACKUP
DBGMISC:                    fedata: sta=0x80 crescn=1528354
DBGMISC:           EXITED krmknmtr with status DFILE [21:25:10.459] elapsed time [00:00:00:14.039]

DBGSQL:            CHANNEL> begin begin sys.dbms_backup_restore.recoverCancel; exception when others then null; end; sys.dbms_backup_restore.recoverStart( opcode         => sys.dbms_backup_restore.PDBPITR_CONVERSATION ,pitrSCN       => :untscn:untscn_i ,pitrTime      => :untiltime:untiltime_i ,scnBased      => :scnbased ,toBefore      => :to_before ,resetSCN      => :resetSCN:resetSCN_i ,resetTime     => :resetTime:resetTime_i ,cleanResPt    => :cleanResPt ,localUndo     => :localUndo ,rspName       => :rspName); end; 
DBGSQL:               sqlcode = 0
DBGSQL:                B :untscn = 1543087
DBGSQL:                B :untiltime = NULL
DBGSQL:                B :scnbased = 1
DBGSQL:                B :to_before = 1
DBGSQL:                B :resetSCN = 1490582
DBGSQL:                B :resetTime = "17-MAY-18"
DBGSQL:                B :cleanResPt = 0
DBGSQL:                B :localUndo = 1
DBGSQL:                B :rspName = TEST


I believe that PDB's are special when it comes to PITR.

The PDB has information that is contained in the CDB,  Performing a incremntal backup of the CDB will affect information for all PDB's.  The only choice recovery has is to use the archive logs for more granularity.


Monday, May 14, 2018

Oracle RMAN restore/recovery prioritization

This blog post is on what happens when you ask RMAN to restore and recover your database or a portion of your database (like a datafile).

This came up with a colleague who asked about the order of recovery.  The question was "If my archive logs are on disk for 48 hours, I performed a full backup 36 hours ago (to SBT_TAPE) and an incremental backup 12 hours ago (to SBT_TAPE), after restoring from SBT_TAPE, will it recover from the archive logs on disk, or will it go to tape for the incremental backup first ?

Well the answer is in the manual here.


Incremental Backups and Archived Redo Log Files
Except for RECOVER BLOCK, RMAN can use both incremental backups and archived redo log files for recovery. RMAN uses the following search order:
  1. Incremental backup sets on disk or tape
  2. Archived redo log files on disk
  3. Archived redo log backups on disk
  4. Archived redo log backup sets on tape

Now let's see this in action.

In my scenario, I am using the "USERS" tablespace.  The datafile I'm going to drop is datafile 7.

Let's walk down what happens at each SCN interval.


3435417  Full backup of datafile 7



BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
1       Incr 0  1.64G      DISK        00:01:30     14-MAY-18      
        BP Key: 1   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T065607
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\01T2ROOB_1_1
  List of Datafiles in backup set 1
  File LV Type Ckp SCN    Ckp Time  Abs Fuz SCN Sparse Name
  ---- -- ---- ---------- --------- ----------- ------ ----
  7    0  Incr 3435417    14-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF



          Backup of Archive logs to defuzzy full backup


BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
5       143.22M    DISK        00:00:05     14-MAY-18      
        BP Key: 5   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T065904
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\05T2ROTO_1_1

  List of Archived Logs in backup set 5
  Thrd Seq     Low SCN    Low Time  Next SCN   Next Time
  ---- ------- ---------- --------- ---------- ---------
  1    38      3394580    13-MAY-18 3435493    14-MAY-18



          Backup of archive logs prior to incremental backup


BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
9       952.50K    DISK        00:00:00     14-MAY-18      
        BP Key: 9   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T070224
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\0BT2RP41_1_1

  List of Archived Logs in backup set 9
  Thrd Seq     Low SCN    Low Time  Next SCN   Next Time
  ---- ------- ---------- --------- ---------- ---------
  1    39      3435493    14-MAY-18 3435597    14-MAY-18
  1    40      3435597    14-MAY-18 3435668    14-MAY-18


h3 style="text-align: left;">

3435627  Incremental backup of datafile 7




BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
7       Incr 1  1.24M      DISK        00:00:37     14-MAY-18      
        BP Key: 7   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T070122
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1
  List of Datafiles in backup set 7
  File LV Type Ckp SCN    Ckp Time  Abs Fuz SCN Sparse Name
  ---- -- ---- ---------- --------- ----------- ------ ----
  7    1  Incr 3435627    14-MAY-18              NO    D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF

          Backup of archive logs


BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
9       952.50K    DISK        00:00:00     14-MAY-18      
        BP Key: 9   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T070224
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\0BT2RP41_1_1

  List of Archived Logs in backup set 9
  Thrd Seq     Low SCN    Low Time  Next SCN   Next Time
  ---- ------- ---------- --------- ---------- ---------
  1    39      3435493    14-MAY-18 3435597    14-MAY-18
  1    40      3435597    14-MAY-18 3435668    14-MAY-18

BS Key  Size       Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ ---------------
11      3.11M      DISK        00:00:00     14-MAY-18      
        BP Key: 11   Status: AVAILABLE  Compressed: NO  Tag: TAG20180514T085551
        Piece Name: D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\0DT2RVOO_1_1

  List of Archived Logs in backup set 11
  Thrd Seq     Low SCN    Low Time  Next SCN   Next Time
  ---- ------- ---------- --------- ---------- ---------
  1    41      3435668    14-MAY-18 3435770    14-MAY-18
  1    42      3435770    14-MAY-18 3437175    14-MAY-18
  1    43      3437175    14-MAY-18 3437200    14-MAY-18
  1    44      3437200    14-MAY-18 3437210    14-MAY-18
  1    45      3437210    14-MAY-18 3437216    14-MAY-18



OK.. Now we have backups on disk (full and level 1) to restore and recover from.


First let's do the restore of datafile 7



RMAN> 
Starting restore at 14-MAY-18
using channel ORA_DISK_1

channel ORA_DISK_1: starting datafile backup set restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
channel ORA_DISK_1: restoring datafile 00007 to D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF
channel ORA_DISK_1: reading from backup piece D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\01T2ROOB_1_1
channel ORA_DISK_1: piece handle=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\01T2ROOB_1_1 tag=TAG20180514T065607
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:01
Finished restore at 14-MAY-18

Now let's do the recovery of datafile 7 and watch what happens.



RMAN> 
Starting recover at 14-MAY-18
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental datafile backup set restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
destination for restore of datafile 00007: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF
channel ORA_DISK_1: reading from backup piece D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1
channel ORA_DISK_1: piece handle=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1 tag=TAG20180514T070122
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:02

starting media recovery

archived log for thread 1 with sequence 40 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001
archived log for thread 1 with sequence 41 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001
archived log for thread 1 with sequence 42 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001
archived log for thread 1 with sequence 43 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001
archived log for thread 1 with sequence 44 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000044_0974378014.0001
archived log for thread 1 with sequence 45 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000045_0974378014.0001
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001 thread=1 sequence=40
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001 thread=1 sequence=41
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001 thread=1 sequence=42
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001 thread=1 sequence=43
media recovery complete, elapsed time: 00:00:03
Finished recover at 14-MAY-18




You can see in the recovery, there are 2 steps performed, but this isn't whole picture.

 Step 1 Restore all incremental backups.

using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental datafile backup set restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
destination for restore of datafile 00007: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF
channel ORA_DISK_1: reading from backup piece D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1
channel ORA_DISK_1: piece handle=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1 tag=TAG20180514T070122
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:02

 Step 2 Recover using archive logs on disk


starting media recovery

archived log for thread 1 with sequence 40 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001
archived log for thread 1 with sequence 41 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001
archived log for thread 1 with sequence 42 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001
archived log for thread 1 with sequence 43 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001
archived log for thread 1 with sequence 44 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000044_0974378014.0001
archived log for thread 1 with sequence 45 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000045_0974378014.0001
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001 thread=1 sequence=40
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001 thread=1 sequence=41
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001 thread=1 sequence=42
archived log file name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001 thread=1 sequence=43
media recovery complete, elapsed time: 00:00:03
Finished recover at 14-MAY-18


Now I reran with trace on and let's look at the pieces


Rman determines the current checkpoint SCN of the datafile I'm recovering (3435417)



DBGSQL:                 TARGET> select fhscn, to_date(fhtim,'MM/DD/RR HH24:MI:SS', 'NLS_CALENDAR=Gregorian'), fhcrs, fhrls, to_date(fhrlc,'MM/DD/RR HH24:MI:SS', 'NLS_CALENDAR=Gregorian'), fhafs, fhrfs, fhrft, hxerr, fhfsz, fhsta, fhdbi, fhfdbi, fhplus, fhtyp into :ckpscn, :ckptime, :crescn, :rlgscn, :rlgtime, :afzscn, :rfzscn, :rfztime, :hxerr, :blocks, :fhsta, :fhdbi, :fhfdbi, :fhplus, :fhtyp from x$kcvfhall where  hxfil = :fno 
DBGSQL:                    sqlcode = 0
DBGSQL:                     D :ckpscn = 3435417
DBGSQL:                     D :ckptime = "14-MAY-18"
DBGSQL:                     D :crescn = 29665
DBGSQL:                     D :rlgscn = 1490582
DBGSQL:                     D :rlgtime = "25-APR-18"
DBGSQL:                     D :afzscn = 0
DBGSQL:                     D :rfzscn = 0
DBGSQL:                     D :rfztime = NULL
DBGSQL:                     D :hxerr = 0
DBGSQL:                     D :blocks = 640
DBGSQL:                     D :fhsta = 0
DBGSQL:                     D :fhdbi = 1502158741
DBGSQL:                     D :fhfdbi = 0
DBGSQL:                     D :fhplus = 0
DBGSQL:                     D :fhtyp = 3
DBGSQL:                     B :fno = 7
DBGMISC:                krmkrfh: [10:07:46.470]
DBGMISC:                DF fno=7 pplfno=0 pdbid=1 pdbname=  crescn=29665
DBGMISC:                     blksize=8192 blocks=640 rfno=7 pdbForeignDbid=0
DBGMISC:                    fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF
DBGMISC:                    ts=USERS, flags=KRMKDF_INBACKUP
DBGMISC:                    fedata: sta=0x0e crescn=29665
DBGMISC:                    fhdata: ckpscn=3435417 rlgscn=1490582
DBGMISC:               EXITED krmkrfh [10:07:46.779] elapsed time [00:00:00:01.074]

RMAN finds any incremental backups that can applied. Then restores and applies as much incremental backups as it can.


  TARGET> declare allCopies boolean; begin dbms_rcvman.resetthisBackupAge; if (:allCopies > 0) then allCopies := TRUE; else allCopies := FALSE; end if; :rc := dbms_rcvman.computeRecoveryActions( fno     => :fno, crescn   => :crescn, df_rlgscn  => :rlgscn, df_rlgtime => :rlgtime, df_ckpscn  => :ckpscn, offlscn   => :offlscn, onlscn   => :onlscn, onltime   => :onltime, cleanscn  => :cleanscn, clean2scn  => :clean2scn, clean2time => :clean2time, allowfuzzy => FALSE, partial_rcv => FALSE, cf_scn   => :cfscn, cf_cretime => :cfcretime, cf_offrrid => :cfoffrrid, allCopies  => allCopies, df_cretime => :cretime, rmanCmd   => :rmanCmd, foreignDbid  => :foreignDbid, pluggedRonly => :pluggedRonly, pluginSCN   => :pluginSCN, pluginRlgSCN => :pluginRlgSCN, pluginRlgTime => :pluginRlgTime, creation_thread => :creation_thread, creation_size  => :creation_size, pdbId      => :pdbId, pdbForeignDbid => :pdbForeignDbid ); if (:maxact > 0) then dbms_rcvman.trimRecoveryActions( maxActions  => :maxact, containerMask => dbms_rcvman.proxyCopy_con_t + dbms_rcvman.imageCopy_con_t + dbms_rcvman.backupSet_con_t, actionMask  => dbms_rcvman.full_act_t); end if; end;  
 DBGSQL:          sqlcode = 0  
 DBGSQL:          B :rc = 0  
 DBGSQL:          B :allCopies = 2  
 DBGSQL:          B :fno = 7  
 DBGSQL:          B :crescn = 29665  
 DBGSQL:          B :rlgscn = 1490582  
 DBGSQL:          B :rlgtime = "25-APR-18"  
 DBGSQL:          B :ckpscn = 3435417  
 DBGSQL:          B :offlscn = 1490581  
 DBGSQL:          B :onlscn = 1490582  
 DBGSQL:          B :onltime = "25-APR-18"  
 DBGSQL:          B :cleanscn = 0  
 DBGSQL:          B :clean2scn = 0  
 DBGSQL:          B :clean2time = "01-JAN-88"  
 DBGSQL:          B :cfscn = 3440786  
 DBGSQL:          B :cfcretime = "25-APR-18"  
 DBGSQL:          B :cfoffrrid = 1  
 DBGSQL:          B :cretime = "08-MAR-17"  
 DBGSQL:          B :rmanCmd = 1  
 DBGSQL:          B :maxact = 0  
 DBGSQL:          B :foreignDbid = 0  
 DBGSQL:          B :pluggedRonly = 0  
 DBGSQL:          B :pluginSCN = 0  
 DBGSQL:          B :pluginRlgSCN = 0  
 DBGSQL:          B :pluginRlgTime = NULL  
 DBGSQL:          B :creation_thread = 0  
 DBGSQL:          B :creation_size = 0  
 DBGSQL:          B :pdbId = 1  
 DBGSQL:          B :pdbForeignDbid = 0  
       DBGRCVMAN: thisBackupAge= 0  
       DBGRCVMAN: ENTERING computeRecoveryActions  
       DBGRCVMAN:  computeRecoveryActions  fno:     7  
       DBGRCVMAN:  computeRecoveryActions  crescn:    29665  
       DBGRCVMAN:  computeRecoveryActions  df_rlgscn:  1490582  
       DBGRCVMAN:  computeRecoveryActions  df_ckpscn:  3435417  
       DBGRCVMAN:  computeRecoveryActions  offlscn:   1490581  
       DBGRCVMAN:  computeRecoveryActions  onlscn:    1490582  
       DBGRCVMAN:  computeRecoveryActions  cleanscn:   0  
       DBGRCVMAN:  computeRecoveryActions  clean2scn:  0  
       DBGRCVMAN:  computeRecoveryActions  cf_scn:    3440786  
       DBGRCVMAN:  computeRecoveryActions  cf_offrrid:  1  
       DBGRCVMAN:  computeRecoveryActions  foreignDbid: 0  
       DBGRCVMAN:  computeRecoveryActions  pluggedRonly: 0  
       DBGRCVMAN:  computeRecoveryActions  pluginSCN:  0  
       DBGRCVMAN:  computeRecoveryActions  pluinRlgSCN: 0  
       DBGRCVMAN:  computeRecoveryActions  creation_thread: 0  
       DBGRCVMAN:  computeRecoveryActions  creation_size:  0  
       DBGRCVMAN:  computeRecoveryActions  pdbid:      1  
       DBGRCVMAN:  computeRecoveryActions  pdbForeignDbid: 0  
       DBGRCVMAN: allCopies is TRUE  
       DBGRCVMAN: doing recover  
       DBGRCVMAN: ENTERING computeRecoveryActions2  
       DBGRCVMAN:   computeRecoveryActions2 doing recovery.  
       DBGRCVMAN:   computeRecoveryActions2 This is ancestor.  
       DBGRCVMAN:  ENTERING openRecoveryActionCursor  
       DBGRCVMAN:   openRecoveryActionCursor target scn is NULL,creSCN=29665,dfCkpSCN=3435417,dbincRlgSCN=1490582,offlSCN=1490581,onlSCN=1490582,cleanSCN=0,clean2SCN=0,fno=7,pluginSCN=0,rmanCmd=1  
       DBGRCVMAN:   openRecoveryActionCursor currc1.type_con=NULL currc1.fno=7 currc1.crescn=29665  
       DBGRCVMAN:   openRecoveryActionCursor restoreSource=, restoreSparse=0  
       DBGRCVMAN:   openRecoveryActionCursor cursor1 not open yet  
       DBGRCVMAN:  OPENING cursor rcvRecCursor1_c in openRecoveryActionCursor  
       DBGRCVMAN:  ENTERING fetchCursor1RecoveryAction  
       DBGRCVMAN:    fetchCursor1RecoveryAction opcode=1  
       DBGRCVMAN:    fetchCursor1RecoveryAction seekNext  
       DBGRCVMAN:    fetchCursor1RecoveryAction rcvRecCursor1_c record  
       DBGRCVMAN: DUMPING RECOVERY CONTAINER  
       DBGRCVMAN: Incremental Backup Set  
       DBGRCVMAN:  bsKey=7 bsRecid=7 bsStamp=976086120 setStamp=976086083 setCount=7 site_key=0  
       DBGRCVMAN:  bsLevel=1 bsType=I pieceCount=1  
       DBGRCVMAN:  multi_section=N  
       DBGRCVMAN:  key=17 recid=17 stamp=976086085 sparse_backup_con =NO  
       DBGRCVMAN:  compTime=14-MAY-18  
       DBGRCVMAN:  blocks=1 blockSize=8192  
       DBGRCVMAN:  fromSCN=3435417 toSCN=3435627 toTime=14-MAY-18 level=1 section_size=0  
       DBGRCVMAN:  rlgSCN=1490582 rlgTime=25-APR-18 dbincKey=  
       DBGRCVMAN:  afzSCN=0  
       DBGRCVMAN:  pdbKey=1  
       DBGRCVMAN:  dfNumber=7 creationSCN=29665 pluginSCN=0 foreignDbid=0 pluggedRonly=0  
       DBGRCVMAN:  cfType=B  
       DBGRCVMAN:  keep_options=0 keep_until=NULL  
       DBGRCVMAN:  EXITING fetchCursor1RecoveryAction filter accepted  
       DBGRCVMAN:  EXITING openRecoveryActionCursor  
       DBGRCVMAN:  ENTERING fetchRecoveryAction  
       DBGRCVMAN:  ENTERING fetchCursor1RecoveryAction  
       DBGRCVMAN:    fetchCursor1RecoveryAction opcode=1  
       DBGRCVMAN:    fetchCursor1RecoveryAction seekNext  
       DBGRCVMAN:    fetchCursor1RecoveryAction no more records  
       DBGRCVMAN:  EXITING fetchCursor1RecoveryAction seekCurrent - beyond current fno, creSCN  
       DBGRCVMAN:  EXITING fetchRecoveryAction with TRUE  
       DBGRCVMAN: fetched recovery action  
       DBGRCVMAN: DUMPING RECOVERY CONTAINER  
       DBGRCVMAN: Incremental Backup Set  
       DBGRCVMAN:  bsKey=7 bsRecid=7 bsStamp=976086120 setStamp=976086083 setCount=7 site_key=0  
       DBGRCVMAN:  bsLevel=1 bsType=I pieceCount=1  
       DBGRCVMAN:  multi_section=N  
       DBGRCVMAN:  key=17 recid=17 stamp=976086085 sparse_backup_con =NO  
       DBGRCVMAN:  compTime=14-MAY-18  
       DBGRCVMAN:  blocks=1 blockSize=8192  
       DBGRCVMAN:  fromSCN=3435417 toSCN=3435627 toTime=14-MAY-18 level=1 section_size=0  
       DBGRCVMAN:  rlgSCN=1490582 rlgTime=25-APR-18 dbincKey=  
       DBGRCVMAN:  afzSCN=0  
       DBGRCVMAN:  pdbKey=1  
       DBGRCVMAN:  dfNumber=7 creationSCN=29665 pluginSCN=0 foreignDbid=0 pluggedRonly=0  
       DBGRCVMAN:  cfType=B  
       DBGRCVMAN:  keep_options=0 keep_until=NULL  
       DBGRCVMAN: found an incremental backup set  
       DBGRCVMAN:  ENTERING addAction  
       DBGRCVMAN:   addAction action.type_con=  
       DBGRCVMAN:  ENTERING redoNeeded  
       DBGRCVMAN:  EXITING redoNeeded with: FALSE  
       DBGRCVMAN: CheckRecAction called 04/25/18 12:33:34; rlgscn=1490582; pdbId=1; cleanscn=0  
       DBGRCVMAN: CheckRecAction:matches inc=0,fromscn=3435417,toscn=3435627,afzSCN=0  
       DBGRCVMAN: cacheFindValidBackupSet: setStamp=976086083 setCount=7 tag=NULL deviceType=NULL mask=1  
       DBGRCVMAN:  ENTERING loadBsRecCache  
       DBGRCVMAN:    loadBsRecCache mixcopy=0  
       DBGRCVMAN: *****BsRecCache Statistics*****  
       DBGRCVMAN: Cache size=0 hit=0  
       DBGRCVMAN:    loadBsRecCache loadRedundDf_c  
       DBGRCVMAN:    loadBsRecCache tag=NULL deviceType=NULL mask=1  
       DBGRCVMAN:    loadBsRecCache Cache contains 12 records  
       DBGRCVMAN:    loadBsRecCache Minimum SetCount=1  
       DBGRCVMAN:  EXITING loadBsRecCache  
       DBGRCVMAN:  ENTERING validateBackupSet0  
       DBGRCVMAN: cacheGetValidBackupSet: returning valid rec deviceType=DISK tag=TAG20180514T070122 copyNumber=1  
       DBGRCVMAN:    validateBackupSet0 exiting loop with rc: SUCCESS  
       DBGRCVMAN:  EXITING validateBackupSet0 with rc:0  
       DBGRCVMAN: DUMPING RECOVERY CONTAINER  
       DBGRCVMAN: Incremental Backup Set  
       DBGRCVMAN:  bsKey=7 bsRecid=7 bsStamp=976086120 setStamp=976086083 setCount=7 site_key=0  
       DBGRCVMAN:  bsLevel=1 bsType=I pieceCount=1  
       DBGRCVMAN:  multi_section=N  
       DBGRCVMAN:  key=17 recid=17 stamp=976086085 sparse_backup_con =NO  
       DBGRCVMAN:  tag=TAG20180514T070122 compTime=14-MAY-18  
       DBGRCVMAN:  deviceType=DISK blocks=1 blockSize=8192  
       DBGRCVMAN:  fromSCN=3435417 toSCN=3435627 toTime=14-MAY-18 level=1 section_size=0  
       DBGRCVMAN:  rlgSCN=1490582 rlgTime=25-APR-18 dbincKey=  
       DBGRCVMAN:  afzSCN=0  
       DBGRCVMAN:  pdbKey=1  
       DBGRCVMAN:  dfNumber=7 creationSCN=29665 pluginSCN=0 foreignDbid=0 pluggedRonly=0  
       DBGRCVMAN:  cfType=B  
       DBGRCVMAN:  keep_options=0 keep_until=NULL  
       DBGRCVMAN: rcvRecPush:from_scn=3435417,to_scn=3435627,rcvRecStackCount=1  
       DBGRCVMAN:   addAction Added action:  
       DBGRCVMAN:   addAction allCopies is TRUE, trying to add other copies  
       DBGRCVMAN:  ENTERING validateBackupSet0  
       DBGRCVMAN:    validateBackupSet0 rc is null, setting to unavailable  
       DBGRCVMAN:  EXITING validateBackupSet0 with rc:1  
       DBGRCVMAN:  EXITING addAction with: action_OK  
       DBGRCVMAN: addAction returned code 0  
       DBGRCVMAN: done set to true - 3  
       DBGRCVMAN: EXITING computeRecoveryActions2 - 3  
       DBGRCVMAN: computeRecoveryActions: Top of stack=1  
       DBGRCVMAN: EXITING computeRecoveryActions with: SUCCESS  
 DBGMISC:       EXITED krmkcra with status 0 [10:07:52.484] elapsed time [00:00:00:06.814]  
 DBGRCV:        ENTERED krmkgrr  
 DBGRCV:        krmkgrr(funcode=10) (krmkgrr)  
       DBGRCVMAN: ENTERING getRcvRec  
       DBGRCVMAN:  getRcvRec funCode=10  
       DBGRCVMAN: ENTERING getRecoveryAction  
       DBGRCVMAN: rcvRecPop:from_scn=3435417,to_scn=3435627,rcvRecStackCount=1  
       DBGRCVMAN: EXITING getRecoveryAction with: FALSE#  
       DBGRCVMAN: DUMPING RECOVERY CONTAINER  
       DBGRCVMAN: Incremental Backup Set  
       DBGRCVMAN:  bsKey=7 bsRecid=7 bsStamp=976086120 setStamp=976086083 setCount=7 site_key=0  
       DBGRCVMAN:  bsLevel=1 bsType=I pieceCount=1  
       DBGRCVMAN:  multi_section=N  
       DBGRCVMAN:  key=17 recid=17 stamp=976086085 sparse_backup_con =NO  
       DBGRCVMAN:  tag=TAG20180514T070122 compTime=14-MAY-18  
       DBGRCVMAN:  deviceType=DISK blocks=1 blockSize=8192  
       DBGRCVMAN:  fromSCN=3435417 toSCN=3435627 toTime=14-MAY-18 level=1 section_size=0  
       DBGRCVMAN:  rlgSCN=1490582 rlgTime=25-APR-18 dbincKey=  
       DBGRCVMAN:  afzSCN=0  
       DBGRCVMAN:  pdbKey=1  
       DBGRCVMAN:  dfNumber=7 creationSCN=29665 pluginSCN=0 foreignDbid=0 pluggedRonly=0  
       DBGRCVMAN:  cfType=B  
       DBGRCVMAN:  keep_options=0 keep_until=NULL  
       DBGRCVMAN: EXITING getRcvRec with rc:0  
 DBGRCV:        ENTERED krmrrcvc  
 DBGRCV:        EXITED krmrrcvc  
 DBGRCV:        EXITED krmkgrr with status 0  
 DBGMISC:       EXITED krmkfbs [10:07:54.256] elapsed time [00:00:00:08.618]  
 DBGRESTORE:     EXITED krmrrcv_dfile  
 DBGRCV:       ENTERED krmkbbsbp  
 DBGSQL:       TARGET> begin dbms_rcvman.translateBackupPieceBsKey( startBskey => :bsKey, tag     => :tag, statusMask => :statusMask); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :bsKey = 7  
 DBGSQL:         B :tag = NULL  
 DBGSQL:         B :statusMask = 1  
      DBGRCVMAN: ENTERING computeAvailableMask  
      DBGRCVMAN: EXITING computeAvailableMask with rc:1  
 DBGSQL:       TARGET> begin dbms_rcvman.translateSeekBpBsKey( bsKey    => :bsKey, pieceCount => :pieceCount, duplicates => :duplicates, deviceType => :deviceType, copyNumber => :copyNumber); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :bsKey = 7  
 DBGSQL:         B :pieceCount = 1  
 DBGSQL:         B :duplicates = 0  
 DBGSQL:         B :deviceType = DISK  
 DBGSQL:         B :copyNumber = 1  
      DBGRCVMAN: ENTERING translateSeekBpBsKey  
      DBGRCVMAN:  translateSeekBpBsKey bskey=7  
      DBGRCVMAN: EXITING translateSeekBpBsKey got key=7  
 DBGRCV:       ENTERED krmkgtbp  
      DBGRCVMAN: ENTERING getBackupPiece  
      DBGRCVMAN: bskey = 7  
      DBGRCVMAN: next bskey=8  
      DBGRCVMAN: EXITING getBackupPiece  
 DBGSQL:        ocirc = 0 (krmkgtbp)  
      DBGRCVMAN: ENTERING getBackupPiece  
      DBGRCVMAN: bskey = 8  
      DBGRCVMAN: end of backupset  
      DBGRCVMAN: EXITING getBackupPiece no more records  
 DBGRCV:       EXITED krmkgtbp  
 DBGSQL:       TARGET> begin dbms_rcvman.translateBpBsKeyCancel; end;   
 DBGSQL:         sqlcode = 0  
 DBGRCV:       EXITED krmkbbsbp  
 DBGRCV:      EXITED krmrrcv with address 53622976  
 DBGMISC:      krmkibap: the incremental backup source tree is: [10:07:55.852]  
 DBGMISC:       1 BS (incremental datafile) key=7 recid=7 stamp=976086120 setstamp=976086083 setcount=7  
 DBGMISC:        level=1 level_i=0 piececount=1 keepopts=0, site_key=0 [10:07:55.918]  
 DBGMISC:        site_key=0 [10:07:55.941]  
 DBGMISC:        chid=NIL parm=NIL [10:07:55.976]  
 DBGMISC:        flags=<has site key> [10:07:56.001]  
 DBGMISC:        valid backup set list is [10:07:56.034]  
 DBGMISC:         1 VBS copy#=1 tag=TAG20180514T070122 deviceType=DISK status=A  
 DBGMISC:           1 BPIECEX key=7 recid=7 stamp=976086084  
 DBGMISC:                   bskey=7 vbkey=0 set_stamp=976086083 set_count=7           site_key=0  
 DBGMISC:              pieceno=1 handle=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1 ba_access=U  
 DBGMISC:                device=DISK krmkch { count=0 found=FALSE }  
 DBGMISC:        restore target list is [10:07:56.217]  
 DBGMISC:         1 ACT type=incremental fromSCN=3435417 toSCN=3435627 fno=7  
 DBGMISC:          DF fno=7 pplfno=0 pdbid=1 pdbname= crescn=29665  
 DBGMISC:            blksize=8192 blocks=640 rfno=7 pdbForeignDbid=0  
 DBGMISC:            fn=D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF  
 DBGMISC:            ts=USERS, flags=KRMKDF_INBACKUP  
 DBGMISC:            fedata: sta=0x0e crescn=29665  
 DBGMISC:            fhdata: ckpscn=3435627 rlgscn=1490582  
 DBGRESTORE:    ENTERED krmkrstp  
 DBGRESTORE:     ENTERED krmkgdn  
 DBGRESTORE:     Looking up newname for 7 (krmkgdn)  
 DBGRCV:       ENTERED krmklknn  
 DBGRCV:        Looking for newname for datafile: 7, Translate: 1, dosearch=1 (krmklknn)  
 DBGRCV:        Looking up in unprocessed newname list, need_dfinfo=0 (krmklknn)  
 DBGRCV:        ENTERED krmksearchnewname  
 DBGRCV:        EXITED krmksearchnewname with address 0  
 DBGRCV:        No newname found for datafile 7 (krmklknn)  
 DBGRCV:       EXITED krmklknn with address 0  
 DBGRESTORE:     Restoring datafile 7 to filename in controlfile: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF (krmkgdn)  
 DBGRESTORE:     EXITED krmkgdn with status D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF  
 DBGRESTORE:     ENTERED krmkgbp  
 DBGRESTORE:     EXITED krmkgbp  
 DBGRESTORE:    EXITED krmkrstp  
 DBGRCV:      EXITED krmkibap with address 53624008  
 DBGMISC:     EXITED krmkomp [10:07:57.652] elapsed time [00:00:00:14.968]  
 DBGPLSQL:    the compiled command tree is: [10:07:57.689] (krmicomp)  
 DBGPLSQL:     1 CMD type=incremental backup restore cmdid=1 status=NOT STARTED  
 DBGPLSQL:       1 STEPstepid=1 cmdid=1 status=NOT STARTED devtype=DISK bs.stamp=976086120 step_size=0 Bytes  
 DBGPLSQL:         1 TEXTNOD = --  
 DBGPLSQL:         2 TEXTNOD = declare  
 DBGPLSQL:         3 TEXTNOD =  /* restoreStatus */  
 DBGPLSQL:         4 TEXTNOD =  state    binary_integer;  
 DBGPLSQL:         5 TEXTNOD =  pieces_done binary_integer;  
 DBGPLSQL:         6 TEXTNOD =  files    binary_integer;  
 DBGPLSQL:         7 TEXTNOD =  datafiles  boolean;  
 DBGPLSQL:         8 TEXTNOD =  incremental boolean;  
 DBGPLSQL:         9 TEXTNOD =  device   boolean;  
 DBGPLSQL:         10 TEXTNOD =  /* restorebackuppiece */  
 DBGPLSQL:         11 TEXTNOD =  done    boolean;  
 DBGPLSQL:         12 TEXTNOD =  currcf   boolean;  
 DBGPLSQL:         13 TEXTNOD =  fhandle   varchar2(512);  
 DBGPLSQL:         14 TEXTNOD =  handle   varchar2(512);  
 DBGPLSQL:         15 TEXTNOD =  outhandle  varchar2(512);  
 DBGPLSQL:         16 TEXTNOD =  params   varchar2(512);  
 DBGPLSQL:         17 TEXTNOD =  fromdisk  boolean;       -- TRUE => backupset on disk  
 DBGPLSQL:         18 TEXTNOD =  /* Miscellaneous */  
 DBGPLSQL:         19 TEXTNOD =  memnum   number;  
 DBGPLSQL:         20 TEXTNOD =  piecenum  number;  
 DBGPLSQL:         21 TEXTNOD =  dfnumber  number;  
 DBGPLSQL:         22 TEXTNOD =  thread   number := null;  
 DBGPLSQL:         23 TEXTNOD =  sequence  number := null;  
 DBGPLSQL:         24 TEXTNOD =  toname   varchar2(512);  
 DBGPLSQL:         25 TEXTNOD =  cfname   varchar2(512);  
 DBGPLSQL:         26 TEXTNOD =  fuzzy_hint number;  
 DBGPLSQL:         27 TEXTNOD =  set_count  number;  
 DBGPLSQL:         28 TEXTNOD =  set_stamp  number;  
 DBGPLSQL:         29 TEXTNOD =  first_time    boolean := TRUE;  
 DBGPLSQL:         30 TEXTNOD =  validate     boolean := FALSE;  
 DBGPLSQL:         31 TEXTNOD =  val_bs_only   boolean := FALSE;  -- TRUE => only bs validation  
 DBGPLSQL:         32 TEXTNOD = --  
 DBGPLSQL:         33 TEXTNOD =  max_corrupt   binary_integer := 0;  
 DBGPLSQL:         34 TEXTNOD =  check_logical  boolean := FALSE;  
 DBGPLSQL:         35 TEXTNOD =  tag       varchar2(31);  
 DBGPLSQL:         36 TEXTNOD =  outtag      varchar2(31);  
 DBGPLSQL:         37 TEXTNOD =  bmr       boolean := FALSE;  
 DBGPLSQL:         38 TEXTNOD =  blocks      number;  
 DBGPLSQL:         39 TEXTNOD =  blksize     number;  
 DBGPLSQL:         40 TEXTNOD =  failover     boolean := FALSE;  
 DBGPLSQL:         41 TEXTNOD =  devtype     varchar2(512);  
 DBGPLSQL:         42 TEXTNOD =  rcvcopy     boolean := FALSE;  
 DBGPLSQL:         43 TEXTNOD =  islevel0     binary_integer := 0;  
 DBGPLSQL:         44 TEXTNOD =  rsid       number;  
 DBGPLSQL:         45 TEXTNOD =  rsts       number;  
 DBGPLSQL:         46 TEXTNOD =  err_msg     varchar2(2048);  
 DBGPLSQL:         47 TEXTNOD =  start_time    date;  
 DBGPLSQL:         48 TEXTNOD =  recid      number;  
 DBGPLSQL:         49 TEXTNOD =  stamp      number;  
 DBGPLSQL:         50 TEXTNOD =  preview     boolean := FALSE;  
 DBGPLSQL:         51 TEXTNOD =  recall      boolean := FALSE;  
 DBGPLSQL:         52 TEXTNOD =  isstby      boolean := FALSE;  
 DBGPLSQL:         53 TEXTNOD =  nocfconv     boolean := FALSE;  
 DBGPLSQL:         54 TEXTNOD =  msrpno      number := 0;  
 DBGPLSQL:         55 TEXTNOD =  msrpct      number := 0;  
 DBGPLSQL:         56 TEXTNOD =  isfarsync    boolean := FALSE;  
 DBGPLSQL:         57 TEXTNOD =  preplugin    boolean := FALSE;  
 DBGPLSQL:         58 TEXTNOD =  pdbid      number := 0;  
 DBGPLSQL:         59 TEXTNOD =  pplcdbdbid    number := 0;  
 DBGPLSQL:         60 TEXTNOD =  ppltrans     number;  
 DBGPLSQL:         61 TEXTNOD =  old_dfnumber   number;  
 DBGPLSQL:         62 TEXTNOD =  restore_not_complete exception;  
 DBGPLSQL:         63 TEXTNOD =   
 DBGPLSQL:         64 TEXTNOD = begin  
 DBGPLSQL:         65 TEXTNOD =    
 DBGPLSQL:         66 PRMVAL = set_count := 7; set_stamp := 976086083; rsid := 53; rsts := 976097261; params := null; isstby := false; isfarsync := false; nocfconv := true;  
 DBGPLSQL:         67 TEXTNOD =   
 DBGPLSQL:         68 TEXTNOD = --  
 DBGPLSQL:         69 TEXTNOD =  if preview then  
 DBGPLSQL:         70 TEXTNOD =   deb('ridf_start', 'preview');  
 DBGPLSQL:         71 TEXTNOD =   return;  
 DBGPLSQL:         72 TEXTNOD =  end if;  
 DBGPLSQL:         73 TEXTNOD =   
 DBGPLSQL:         74 TEXTNOD =  sys.dbms_backup_restore.restoreStatus(state, pieces_done, files, datafiles,  
 DBGPLSQL:         75 TEXTNOD =            incremental, device);  
 DBGPLSQL:         76 TEXTNOD =  if (msrpno > 1) then  
 DBGPLSQL:         77 TEXTNOD = --  
 DBGPLSQL:         78 TEXTNOD = --  
 DBGPLSQL:         79 TEXTNOD = --  
 DBGPLSQL:         80 TEXTNOD = --  
 DBGPLSQL:         81 TEXTNOD =   pieces_done := msrpno - 1;  
 DBGPLSQL:         82 TEXTNOD =  end if;  
 DBGPLSQL:         83 TEXTNOD =   
 DBGPLSQL:         84 TEXTNOD =  select sysdate into start_time from x$dual;  
 DBGPLSQL:         85 TEXTNOD =  if state = sys.dbms_backup_restore.restore_no_conversation then  
 DBGPLSQL:         86 TEXTNOD =   goto start_convo;  
 DBGPLSQL:         87 TEXTNOD =  elsif state = sys.dbms_backup_restore.restore_naming_files then  
 DBGPLSQL:         88 TEXTNOD =   goto name_files;  
 DBGPLSQL:         89 TEXTNOD =  else  
 DBGPLSQL:         90 TEXTNOD =   goto restore_piece;  
 DBGPLSQL:         91 TEXTNOD =  end if;  
 DBGPLSQL:         92 TEXTNOD =   
 DBGPLSQL:         93 TEXTNOD = <<start_convo>>  
 DBGPLSQL:         94 TEXTNOD =  sys.dbms_backup_restore.setRmanStatusRowId(rsid=>rsid, rsts=>rsts);  
 DBGPLSQL:         95 TEXTNOD =  sys.dbms_backup_restore.applySetDatafile(  
 DBGPLSQL:         96 TEXTNOD =    check_logical  => check_logical  
 DBGPLSQL:         97 TEXTNOD =   ,cleanup     => FALSE  
 DBGPLSQL:         98 TEXTNOD =   ,service     => NULL  
 DBGPLSQL:         99 TEXTNOD =   ,chunksize    => 0  
 DBGPLSQL:        100 TEXTNOD =   ,rs_flags     => 0  
 DBGPLSQL:        101 TEXTNOD =   ,preplugin    => preplugin);  
 DBGPLSQL:        102 TEXTNOD =  incremental := TRUE;  
 DBGPLSQL:        103 TEXTNOD =  krmicd.writeMsg(8039, krmicd.getChid);  
 DBGPLSQL:        104 TEXTNOD =   
 DBGPLSQL:        105 TEXTNOD =  setRestoreParams;  
 DBGPLSQL:        106 TEXTNOD = <<name_files>>  
 DBGPLSQL:        107 TEXTNOD =  deb('ridf_start', 'set_stamp=' || set_stamp || ' set_count=' || set_count,  
 DBGPLSQL:        108 TEXTNOD =    rman_constant.DEBUG_IO, rman_constant.LEVEL_MIN);  
 DBGPLSQL:        109 TEXTNOD = --  
 DBGPLSQL:        110 TEXTNOD =  toname := null;  
 DBGPLSQL:        111 TEXTNOD =  max_corrupt := 0;  
 DBGPLSQL:        112 TEXTNOD =    
 DBGPLSQL:        113 PRMVAL = memnum := 1;  
 DBGPLSQL:        114 TEXTNOD =    
 DBGPLSQL:        115 PRMVAL = fuzzy_hint := 0; islevel0 := 0; recid := 0; stamp := 0; dfnumber := 7; old_dfnumber := 7; toname := 'D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF'; blocks := 640; blksize := 8192;  
 DBGPLSQL:        116 TEXTNOD =  if msrpno > 1 and not bmr then  
 DBGPLSQL:        117 TEXTNOD =   declare  
 DBGPLSQL:        118 TEXTNOD =    tempfno number;  
 DBGPLSQL:        119 TEXTNOD =   begin  
 DBGPLSQL:        120 TEXTNOD =    krmicd.getMSR(tempfno, toname);  
 DBGPLSQL:        121 TEXTNOD =   end;  
 DBGPLSQL:        122 TEXTNOD =  end if;  
 DBGPLSQL:        123 TEXTNOD =  if files < memnum then  
 DBGPLSQL:        124 TEXTNOD =   sys.dbms_backup_restore.applyDataFileTo(  
 DBGPLSQL:        125 TEXTNOD =     dfnumber    => dfnumber,  
 DBGPLSQL:        126 TEXTNOD =     toname     => toname,  
 DBGPLSQL:        127 TEXTNOD =     fuzziness_hint => fuzzy_hint,  
 DBGPLSQL:        128 TEXTNOD =     max_corrupt  => max_corrupt,  
 DBGPLSQL:        129 TEXTNOD =     islevel0    => islevel0,  
 DBGPLSQL:        130 TEXTNOD =     recid     => recid,  
 DBGPLSQL:        131 TEXTNOD =     stamp     => stamp,  
 DBGPLSQL:        132 TEXTNOD =     old_dfnumber  => old_dfnumber);  
 DBGPLSQL:        133 TEXTNOD =   
 DBGPLSQL:        134 TEXTNOD =   if msrpno = 1 and not bmr then  
 DBGPLSQL:        135 TEXTNOD =    sys.dbms_backup_restore.initMSR(dfnumber, toname);  
 DBGPLSQL:        136 TEXTNOD =   end if;  
 DBGPLSQL:        137 TEXTNOD =   
 DBGPLSQL:        138 TEXTNOD =   if msrpno > 0 then  
 DBGPLSQL:        139 TEXTNOD =    krmicd.setMSR(dfnumber, toname);  
 DBGPLSQL:        140 TEXTNOD =   end if;  
 DBGPLSQL:        141 TEXTNOD =   
 DBGPLSQL:        142 TEXTNOD =   if first_time then  
 DBGPLSQL:        143 TEXTNOD =    if bmr then  
 DBGPLSQL:        144 TEXTNOD =      krmicd.writeMsg(8108, krmicd.getChid);  
 DBGPLSQL:        145 TEXTNOD =    elsif rcvcopy then  
 DBGPLSQL:        146 TEXTNOD =      krmicd.writeMsg(8131, krmicd.getChid);  
 DBGPLSQL:        147 TEXTNOD =    else  
 DBGPLSQL:        148 TEXTNOD =      krmicd.writeMsg(8089, krmicd.getChid);  
 DBGPLSQL:        149 TEXTNOD =    end if;  
 DBGPLSQL:        150 TEXTNOD =    first_time := FALSE;  
 DBGPLSQL:        151 TEXTNOD =   end if;  
 DBGPLSQL:        152 TEXTNOD =   
 DBGPLSQL:        153 TEXTNOD =   if bmr then  
 DBGPLSQL:        154 TEXTNOD =    krmicd.writeMsg(8533, to_char(dfnumber, 'FM09999'));  
 DBGPLSQL:        155 TEXTNOD =   elsif toname is not null then  
 DBGPLSQL:        156 TEXTNOD =    if rcvcopy then  
 DBGPLSQL:        157 TEXTNOD =     krmicd.writeMsg(8551, to_char(dfnumber, 'FM09999'), toname);  
 DBGPLSQL:        158 TEXTNOD =    else  
 DBGPLSQL:        159 TEXTNOD =     krmicd.writeMsg(8509, to_char(dfnumber, 'FM09999'), toname);  
 DBGPLSQL:        160 TEXTNOD =    end if;  
 DBGPLSQL:        161 TEXTNOD =    deb('ridf_name', 'blocks=' || blocks || ' block_size=' || blksize,  
 DBGPLSQL:        162 TEXTNOD =      rman_constant.DEBUG_IO, rman_constant.LEVEL_MIN);  
 DBGPLSQL:        163 TEXTNOD =   end if;  
 DBGPLSQL:        164 TEXTNOD =   if (msrpno > 0) then  
 DBGPLSQL:        165 TEXTNOD =    krmicd.writeMsg(8555, krmicd.getChid, to_char(msrpno), to_char(msrpct));  
 DBGPLSQL:        166 TEXTNOD =   end if;  
 DBGPLSQL:        167 TEXTNOD =  end if;  
 DBGPLSQL:        168 TEXTNOD = --  
 DBGPLSQL:        169 TEXTNOD = <<restore_piece>>  
 DBGPLSQL:        170 TEXTNOD = --  
 DBGPLSQL:        171 TEXTNOD =  fhandle := NULL;  
 DBGPLSQL:        172 TEXTNOD =    
 DBGPLSQL:        173 PRMVAL = piecenum := 1;  
 DBGPLSQL:        174 TEXTNOD = --  
 DBGPLSQL:        175 TEXTNOD =    
 DBGPLSQL:        176 PRMVAL = handle := 'D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1'; fromdisk := true; recid := 7; stamp := 976086084; tag := 'TAG20180514T070122';  
 DBGPLSQL:        177 TEXTNOD =  -- handle, tag, fromdisk, recid, stamp  
 DBGPLSQL:        178 TEXTNOD =  if (pieces_done+1) = piecenum then  
 DBGPLSQL:        179 TEXTNOD =   sys.dbms_backup_restore.restoreSetPiece(handle  => handle,  
 DBGPLSQL:        180 TEXTNOD =                       tag   => tag,  
 DBGPLSQL:        181 TEXTNOD =                       fromdisk => fromdisk,  
 DBGPLSQL:        182 TEXTNOD =                       recid  => recid,  
 DBGPLSQL:        183 TEXTNOD =                       stamp  => stamp);  
 DBGPLSQL:        184 TEXTNOD =   if fhandle is NULL then  
 DBGPLSQL:        185 TEXTNOD =    fhandle := handle;  
 DBGPLSQL:        186 TEXTNOD =   end if;  
 DBGPLSQL:        187 TEXTNOD =  end if;  
 DBGPLSQL:        188 TEXTNOD =  if (restore_piece_int(pieces_done, piecenum, fhandle, done, params,  
 DBGPLSQL:        189 TEXTNOD =     outhandle, outtag, failover, err_msg, val_bs_only, validate,  
 DBGPLSQL:        190 TEXTNOD =     devtype, bmr, set_stamp, set_count, start_time, incremental,   
 DBGPLSQL:        191 TEXTNOD =     currcf, ppltrans)) then  
 DBGPLSQL:        192 TEXTNOD =   goto restore_failover;  
 DBGPLSQL:        193 TEXTNOD =  end if;  
 DBGPLSQL:        194 TEXTNOD =   
 DBGPLSQL:        195 TEXTNOD =  if done then  
 DBGPLSQL:        196 TEXTNOD =   return;  
 DBGPLSQL:        197 TEXTNOD =  end if;   
 DBGPLSQL:        198 TEXTNOD = --  
 DBGPLSQL:        199 TEXTNOD =  krmicd.writeMsg(8001);  
 DBGPLSQL:        200 TEXTNOD =   
 DBGPLSQL:        201 TEXTNOD =  if not krmicd.doRestoreFailover(rman_constant.BACKUPPIECE) then  
 DBGPLSQL:        202 TEXTNOD =   begin  
 DBGPLSQL:        203 TEXTNOD =     sys.dbms_backup_restore.restoreCancel(FALSE);  
 DBGPLSQL:        204 TEXTNOD =   exception  
 DBGPLSQL:        205 TEXTNOD =     when others then  
 DBGPLSQL:        206 TEXTNOD =      krmicd.writeMsg(1005,   
 DBGPLSQL:        207 TEXTNOD =              'a. dbms_backup_restore.restoreCancel() failed');  
 DBGPLSQL:        208 TEXTNOD =   end;   
 DBGPLSQL:        209 TEXTNOD =   
 DBGPLSQL:        210 TEXTNOD =   if (ppltrans > 0) then  
 DBGPLSQL:        211 TEXTNOD =     sys.dbms_backup_restore.endPrePluginTranslation;  
 DBGPLSQL:        212 TEXTNOD =   end if;  
 DBGPLSQL:        213 TEXTNOD =   raise restore_not_complete;  
 DBGPLSQL:        214 TEXTNOD =  end if;  
 DBGPLSQL:        215 TEXTNOD =   
 DBGPLSQL:        216 TEXTNOD = --  
 DBGPLSQL:        217 TEXTNOD = --  
 DBGPLSQL:        218 TEXTNOD = --  
 DBGPLSQL:        219 TEXTNOD = --  
 DBGPLSQL:        220 TEXTNOD =  if (not validate) then  
 DBGPLSQL:        221 TEXTNOD =   getFileRestored(FALSE);  
 DBGPLSQL:        222 TEXTNOD =  end if;  
 DBGPLSQL:        223 TEXTNOD =    
 DBGPLSQL:        224 TEXTNOD =  devtype := krmicd.checkBsFailover;  
 DBGPLSQL:        225 TEXTNOD =   
 DBGPLSQL:        226 TEXTNOD =  if (incremental and devtype is null) then  
 DBGPLSQL:        227 TEXTNOD =   begin  
 DBGPLSQL:        228 TEXTNOD =     sys.dbms_backup_restore.restoreCancel(TRUE);  
 DBGPLSQL:        229 TEXTNOD =   exception   
 DBGPLSQL:        230 TEXTNOD =     when others then  
 DBGPLSQL:        231 TEXTNOD =      krmicd.writeMsg(1005,   
 DBGPLSQL:        232 TEXTNOD =              'b. dbms_backup_restore.restoreCancel() failed');  
 DBGPLSQL:        233 TEXTNOD =   end;  
 DBGPLSQL:        234 TEXTNOD =   
 DBGPLSQL:        235 TEXTNOD =   if (ppltrans > 0) then  
 DBGPLSQL:        236 TEXTNOD =     sys.dbms_backup_restore.endPrePluginTranslation;  
 DBGPLSQL:        237 TEXTNOD =   end if;  
 DBGPLSQL:        238 TEXTNOD =  end if;  
 DBGPLSQL:        239 TEXTNOD =   
 DBGPLSQL:        240 TEXTNOD =  if (dfnumber is not null) then  
 DBGPLSQL:        241 TEXTNOD =   krmicd.writeMsg(1005, 'Restore did not complete for some' ||  
 DBGPLSQL:        242 TEXTNOD =           ' files from backup piece ' ||  
 DBGPLSQL:        243 TEXTNOD =           outhandle || ' (piecenum=' || to_char(piecenum) ||  
 DBGPLSQL:        244 TEXTNOD =           ', pieces_done=' || to_char(pieces_done) ||  
 DBGPLSQL:        245 TEXTNOD =           ', done=' || bool2char(done) ||  
 DBGPLSQL:        246 TEXTNOD =           ', failover=' || bool2char(failover) || ')');  
 DBGPLSQL:        247 TEXTNOD =  else  
 DBGPLSQL:        248 TEXTNOD =   krmicd.writeMsg(1005, 'Restore did not complete for some' ||  
 DBGPLSQL:        249 TEXTNOD =           ' archived logs from backup piece ' || outhandle ||  
 DBGPLSQL:        250 TEXTNOD =           ' (piecenum=' || to_char(piecenum) ||  
 DBGPLSQL:        251 TEXTNOD =           ', pieces_done=' || to_char(pieces_done) ||  
 DBGPLSQL:        252 TEXTNOD =           ', done=' || bool2char(done) ||  
 DBGPLSQL:        253 TEXTNOD =           ', failover=' || bool2char(failover) || ')');  
 DBGPLSQL:        254 TEXTNOD =  end if;  
 DBGPLSQL:        255 TEXTNOD =   
 DBGPLSQL:        256 TEXTNOD =  krmicd.writeMsg(1005, 'Please check alert log for ' ||  
 DBGPLSQL:        257 TEXTNOD =             'additional information.');  
 DBGPLSQL:        258 TEXTNOD =   
 DBGPLSQL:        259 TEXTNOD =  if (devtype is not null) then  
 DBGPLSQL:        260 TEXTNOD =   krmicd.writeMsg(8612, krmicd.getChid, devtype);  
 DBGPLSQL:        261 TEXTNOD =  end if;  
 DBGPLSQL:        262 TEXTNOD =   
 DBGPLSQL:        263 TEXTNOD = --  
 DBGPLSQL:        264 TEXTNOD = <<restore_failover>>  
 DBGPLSQL:        265 TEXTNOD =  begin  
 DBGPLSQL:        266 TEXTNOD =   sys.dbms_backup_restore.restoreCancel(FALSE);  
 DBGPLSQL:        267 TEXTNOD =  exception  
 DBGPLSQL:        268 TEXTNOD =   when others then  
 DBGPLSQL:        269 TEXTNOD =     krmicd.writeMsg(1005,   
 DBGPLSQL:        270 TEXTNOD =             'c. dbms_backup_restore.restoreCancel() failed');  
 DBGPLSQL:        271 TEXTNOD =  end;   
 DBGPLSQL:        272 TEXTNOD =   
 DBGPLSQL:        273 TEXTNOD =  if (ppltrans > 0) then  
 DBGPLSQL:        274 TEXTNOD =   sys.dbms_backup_restore.endPrePluginTranslation;  
 DBGPLSQL:        275 TEXTNOD =  end if;  
 DBGPLSQL:        276 TEXTNOD =   
 DBGPLSQL:        277 TEXTNOD =  sys.dbms_backup_restore.setRmanStatusRowId(rsid=>0, rsts=>0);  
 DBGPLSQL:        278 TEXTNOD = end;  
 DBGMISC:    EXITED krmicomp with address 53624008 [10:08:11.848] elapsed time [00:00:00:29.192]  
 DBGMISC:    ENTERED krmiexe [10:08:11.876]  
 DBGMISC:     Executing command incremental backup restore [10:08:11.995] (krmiexe)  
 DBGRPC:     krmxr - entering  
 DBGRPC:     krmxpoq - returning rpc_number: 14 with status: FINISHED129 for channel default  
 DBGRPC:     krmxr - channel default has rpc_count: 14  
 DBGRPC:     krmxpoq - returning rpc_number: 27 with status: FINISHED129 for channel ORA_DISK_1  
 DBGRPC:     krmxr - channel ORA_DISK_1 has rpc_count: 27  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: looking for work for channel default (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      CMD type=incremental backup restore cmdid=1 status=NOT STARTED  
 DBGRPC:         1 STEPstepid=1 cmdid=1 status=NOT STARTED devtype=DISK bs.stamp=976086120 step_size=0 Bytes  
 DBGRPC:      krmqgns: no work found for channel default (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: looking for work for channel ORA_DISK_1 (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      CMD type=incremental backup restore cmdid=1 status=NOT STARTED  
 DBGRPC:         1 STEPstepid=1 cmdid=1 status=NOT STARTED devtype=DISK bs.stamp=976086120 step_size=0 Bytes  
 DBGRPC:      krmqgns: channel ORA_DISK_1 assigned step 1 (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 0  
 DBGRPC:     krmxcis - channel ORA_DISK_1, calling pcicmp  
 DBGRPC:     krmxr - channel ORA_DISK_1 calling peicnt  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.RESTORESTATUS excl: 0  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.SETRMANSTATUSROWID excl: 0  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.APPLYSETDATAFILE excl: 0  
 DBGMISC:     ENTERED krmzlog [10:08:12.863]  
 RMAN-08039: channel ORA_DISK_1: starting incremental datafile backup set restore  
 DBGMISC:     EXITED krmzlog [10:08:12.957] elapsed time [00:00:00:00.094]  
 DBGMISC:     ENTERED krmzgparms [10:08:12.979]  
 DBGMISC:     Step id = 1; Code = 2 [10:08:13.102] (krmzgparms)  
 DBGMISC:     EXITED krmzgparms with status 0 (FALSE) [10:08:13.145] elapsed time [00:00:00:00.166]  
 DBGIO:      channel ORA_DISK_1: set_stamp=976086083 set_count=7 [10:08:13.181] (ridf_start)  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.APPLYDATAFILETO excl: 0  
 DBGMISC:     ENTERED krmzlog [10:08:13.270]  
 RMAN-08089: channel ORA_DISK_1: specifying datafile(s) to restore from backup set  
 DBGMISC:     EXITED krmzlog [10:08:13.356] elapsed time [00:00:00:00.086]  
 DBGMISC:     ENTERED krmzlog [10:08:13.378]  
 RMAN-08509: destination for restore of datafile 00007: D:\APP\BGRENN\VIRTUAL\ORADATA\ORCL\USERS01.DBF  
 DBGMISC:     EXITED krmzlog [10:08:13.456] elapsed time [00:00:00:00.078]  
 DBGIO:      channel ORA_DISK_1: blocks=640 block_size=8192 [10:08:13.477] (ridf_name)  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.RESTORESETPIECE excl: 0  
 DBGMISC:     ENTERED krmzlog [10:08:13.571]  
 RMAN-08003: channel ORA_DISK_1: reading from backup piece D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1  
 DBGMISC:     EXITED krmzlog [10:08:13.680] elapsed time [00:00:00:00.109]  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=3123 db=target proc=SYS.DBMS_BACKUP_RESTORE.RESTOREBACKUPPIECE excl: 0  
 DBGRPC:     krmxr - channel ORA_DISK_1 returned from peicnt  
 DBGRPC:     krmxpoq - returning rpc_number: 33 with status: STARTED40 for channel ORA_DISK_1  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: looking for work for channel default (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      CMD type=incremental backup restore cmdid=1 status=STARTED  
 DBGRPC:         1 STEPstepid=1 cmdid=1 status=STARTED devtype=DISK bs.stamp=976086120 step_size=0 Bytes  
 DBGRPC:      krmqgns: no work found for channel default (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     krmxpoq - returning rpc_number: 33 with status: FINISHED40 for channel ORA_DISK_1  
 DBGRPC:     krmxr - channel ORA_DISK_1 calling peicnt  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.RESTOREBACKUPPIECE excl: 0  
 DBGMISC:     ENTERED krmzlog [10:08:14.452]  
 RMAN-08611: channel ORA_DISK_1: piece handle=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1 tag=TAG20180514T070122  
 DBGMISC:     EXITED krmzlog [10:08:14.527] elapsed time [00:00:00:00.075]  
 DBGMISC:     ENTERED krmzlog [10:08:14.560]  
 RMAN-08023: channel ORA_DISK_1: restored backup piece 1  
 DBGMISC:     EXITED krmzlog [10:08:14.677] elapsed time [00:00:00:00.117]  
 DBGIO:      Type %Comp Blocks   Tot Blocks Blksize  ElpTime(s) IO Rt(b/s) Name [10:08:14.710] (krmkqio)  
 DBGIO:      ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [10:08:14.732] (krmkqio)  
 DBGIO:      IN     127          8192    0     0     D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\DATABASE\07T2RP23_1_1 [10:08:14.759] (krmkqio)  
 DBGIO:      AGG    0           8192    0     0      [10:08:14.790] (krmkqio)  
 DBGMISC:     ENTERED krmzlog [10:08:14.818]  
 RMAN-08180: channel ORA_DISK_1: restore complete, elapsed time: 00:00:02  
 DBGMISC:     EXITED krmzlog [10:08:14.893] elapsed time [00:00:00:00.075]  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.FETCHFILERESTORED excl: 0  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.FETCHFILERESTORED excl: 0  
 DBGRPC:     krmxrpc - channel ORA_DISK_1 kpurpc2 err=0 db=target proc=SYS.DBMS_BACKUP_RESTORE.RESTORECANCEL excl: 0  
 DBGRPC:     krmxr - channel ORA_DISK_1 returned from peicnt  
 DBGRPC:     krmxr - channel ORA_DISK_1 finished step  
 DBGRPC:        ENTERED krmqgns  
 krmqgns: looking for work for channel default (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      CMD type=incremental backup restore cmdid=1 status=STARTED  
 DBGRPC:         1 STEPstepid=1 cmdid=1 status=FINISHED devtype=DISK bs.stamp=976086120 step_size=0 Bytes  
 DBGRPC:      krmqgns: no work found for channel default (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: channel ORA_DISK_1 finished step 1 (krmqgns)  
 DBGRPC:      krmqgns: looking for work for channel ORA_DISK_1 (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      krmqgns: no work found for channel ORA_DISK_1 (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: looking for work for channel default (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      krmqgns: no work found for channel default (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     ENTERED krmqgns  
 DBGRPC:      krmqgns: looking for work for channel ORA_DISK_1 (krmqgns)  
 DBGRPC:      krmqgns: commands remaining to be executed: (krmqgns)  
 DBGRPC:      krmqgns: no work found for channel ORA_DISK_1 (krmqgns)  
 DBGRPC:      (krmqgns)  
 DBGRPC:     EXITED krmqgns with status 1  
 DBGRPC:     krmxr - all done  
 DBGRPC:     krmxr - exiting with 0  
 DBGMISC:    EXITED krmiexe with status 0 [10:08:16.147] elapsed time [00:00:00:04.271]  
 DBGMISC:    Finished incremental backup restore at 14-MAY-18 [10:08:16.169]  
 DBGMISC:    ENTERED krmkmrsr [10:08:16.196]  
 DBGSQL:     ENTERED krmkosqlerr  
 DBGSQL:      TARGET> select /*+ rule */ round(sum(MBYTES_PROCESSED)), round(sum(INPUT_BYTES)), round(sum(OUTPUT_BYTES)) from V$RMAN_STATUS START WITH RECID = :row_id and STAMP = :row_stamp CONNECT BY PRIOR RECID = parent_recid  
 DBGSQL:       sqlcode = 24347  
 DBGSQL:        B :row_id = 53  
 DBGSQL:        B :row_stamp = 976097261  
 DBGSQL:      success: ORA-24347: Warning of a NULL column in an aggregate function (krmkosqlerr)  
 DBGSQL:      (krmkosqlerr)  
 DBGSQL:     EXITED krmkosqlerr  
 DBGSQL:     ENTERED krmkgodevtype  
 DBGMISC:     krmkgodevtype: return device type [10:08:16.641]  
 DBGSQL:     EXITED krmkgodevtype  
 DBGSQL:     TARGET> begin sys.dbms_backup_restore.commitRmanStatusRow( row_id  => :row_id, row_stamp => :row_stamp, mbytes  => :mb, status  => :status, ibytes  => :ib, obytes  => :ob, odevtype => :odevtype); end;  
 DBGSQL:       sqlcode = 0  
 DBGSQL:       B :row_id = 53  
 DBGSQL:       B :row_stamp = 976097261  
 DBGSQL:       B :mb = 0  
 DBGSQL:       B :status = 2  
 DBGSQL:       B :ib = 1040384  
 DBGSQL:       B :ob = 0  
 DBGSQL:       B :odevtype =   
 DBGMISC:    EXITED krmkmrsr [10:08:17.225] elapsed time [00:00:00:01.029]  
 DBGMISC:    EXITED krmice [10:08:17.251] elapsed time [00:00:00:36.481]  
 DBGMISC:    ENTERED krmice [10:08:17.343]  
 DBGMISC:    command to be compiled and executed is: starting media recovery [10:08:17.368] (krmice)  
 DBGMISC:    command after this command is: restoring and applying logs [10:08:17.390] (krmice)  
 DBGMISC:    current incarnation must match for starting media recovery [10:08:17.417] (krmice)  
 DBGMISC:    ENTERED krmkcrsr [10:08:17.456]  
 DBGSQL:     TARGET> begin sys.dbms_backup_restore.createRmanStatusRow( level    => :level, parent_id  => :pid, parent_stamp => :pts, status    => :status, command_id  => :command_id, operation  => :operation, row_id    => :row_id, row_stamp  => :row_stamp, flags    => :flags); end;  
 DBGSQL:       sqlcode = 0  
 DBGSQL:       B :row_id = 54  
 DBGSQL:       B :row_stamp = 976097297  
 DBGSQL:       B :level = 2  
 DBGSQL:       B :pid = 51  
 DBGSQL:       B :pts = 976097246  
 DBGSQL:       B :status = 1  
 DBGSQL:       B :command_id = 2018-05-14T10:05:22  
 DBGSQL:       B :operation = starting media recovery  
 DBGSQL:       B :flags = 2  
 DBGMISC:    EXITED krmkcrsr [10:08:18.371] elapsed time [00:00:00:00.915]  
 DBGMISC:    ENTERED krmicomp [10:08:18.398]  
 DBGMISC:     ENTERED krmkomp [10:08:18.420]  
 DBGRCV:      ENTERED krmkucls  
 DBGRCV:      EXITED krmkucls with address 0  
 DBGMISC:     krmkcomp - Name translation defaults  

RMAN gets the list of archive logs that are needed.



 DBGSQL:       TARGET> declare thread  number; sequence number; recid  number; alRec  dbms_rcvman.alRec_t; begin dbms_rcvman.getArchivedLog(alRec => alRec); if (:rlscn = alRec.rlgSCN and :stopthr = alRec.thread and ((alRec.sequence >= :stopseq and :toclause = 0) or (alRec.sequence > :stopseq and :toclause = 1))) then :flag := 1; else :flag := 0; :al_key:al_key_i     := alRec.key; :recid:recid_i      := alRec.recid; :stamp:stamp_i      := alRec.stamp; :thread         := alRec.thread; :sequence        := alRec.sequence; :fileName:fileName_i   := alRec.fileName; :lowSCN         := alRec.lowSCN; :lowTime         := alRec.lowTime; :nextSCN         := alRec.nextSCN; :nextTime        := nvl(alRec.nextTime, to_date('12/31/9999', 'MM/DD/YYYY')); :rlgSCN         := alRec.rlgSCN; :rlgTime         := alRec.rlgTime; :blocks         := alRec.blocks; :blockSize        := alRec.blockSize; :status         := alRec.status; :compTime:compTime_i   := alRec.compTime; :duplicate        := alRec.duplicate; :compressed:compressed_i := alRec.compressed; :isrdf:isrdf_i      := alRec.isrdf; :stby          := alRec.stby; :terminal        := alRec.terminal; :site_key:site_key_i   := alRec.site_key; :source_dbid       := alRec.source_dbid; end if; end;   
 DBGSQL:        sqlcode = 0  
 DBGSQL:         B :flag = 0  
 DBGSQL:         B :al_key = NULL  
 DBGSQL:         B :recid = NULL  
 DBGSQL:         B :stamp = NULL  
 DBGSQL:         B :thread = 1  
 DBGSQL:         B :sequence = 44  
 DBGSQL:         B :fileName = NULL  
 DBGSQL:         B :lowSCN = 3437200  
 DBGSQL:         B :lowTime = "14-MAY-18"  
 DBGSQL:         B :nextSCN = 3437210  
 DBGSQL:         B :nextTime = "14-MAY-18"  
 DBGSQL:         B :rlgSCN = 1490582  
 DBGSQL:         B :rlgTime = "25-APR-18"  
 DBGSQL:         B :blocks = 25  
 DBGSQL:         B :blockSize = 512  
 DBGSQL:         B :status = D  
 DBGSQL:         B :compTime = NULL  
 DBGSQL:         B :duplicate = 1  
 DBGSQL:         B :compressed = NO  
 DBGSQL:         B :isrdf = NO  
 DBGSQL:         B :stby = N  
 DBGSQL:         B :terminal = NO  
 DBGSQL:         B :site_key = 0  
 DBGSQL:         B :source_dbid = 0  
 DBGSQL:         B :rlscn = 1490582  
 DBGSQL:         B :stopthr = 0  
 DBGSQL:         B :stopseq = 0  
 DBGSQL:         B :toclause = 0  
     DBGRCVMAN: ENTERING getArchivedLog  
     DBGRCVMAN: getArchivedLog - resetscn=1490582 thread=1 seq=44 lowscn=3437200 nextscn=3437210 terminal=NO site_key_order_col=0 isrdf=NO stamp=-1  
     DBGRCVMAN: getArchivedLog - currInc =0  
     DBGRCVMAN: getArchivedLogLast(translateArcLogSCNRange2) := local  
     DBGRCVMAN: getArchivedLogLast := local  
     DBGRCVMAN: EXITING getArchivedLog  
 DBGMISC:      EXITED krmkgal with status Done [10:08:57.766] elapsed time [00:00:00:01.696]  
 DBGMISC:      ENTERED krmkgal [10:08:57.792]  
 BGMISC:      krmrfalb: archive log list: [10:09:02.627]  
 DBGRESTORE:      1 ALSPEC  
 DBGRESTORE:        1 RAL key=3 recid=3 stamp=976086144 thread=1 seq=40 site_key=0  
 DBGRESTORE:          lowscn=3435597 nxtscn=3435668 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:00:45 nexttime=2018-05-14 07:02:24 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=9 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001  
 DBGRESTORE:        2 RAL key=0 recid=0 stamp=0 thread=1 seq=40 site_key=0  
 DBGRESTORE:          lowscn=3435597 nxtscn=3435668 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:00:45 nexttime=2018-05-14 07:02:24 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=9 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  
 DBGRESTORE:        3 RAL key=4 recid=4 stamp=976086175 thread=1 seq=41 site_key=0  
 DBGRESTORE:          lowscn=3435668 nxtscn=3435770 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:02:24 nexttime=2018-05-14 07:02:55 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=1970 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001  
 DBGRESTORE:        4 RAL key=0 recid=0 stamp=0 thread=1 seq=41 site_key=0  
 DBGRESTORE:          lowscn=3435668 nxtscn=3435770 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:02:24 nexttime=2018-05-14 07:02:55 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=1970 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  
 DBGRESTORE:        5 RAL key=5 recid=5 stamp=976092346 thread=1 seq=42 site_key=0  
 DBGRESTORE:          lowscn=3435770 nxtscn=3437175 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:02:55 nexttime=2018-05-14 08:45:45 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=4349 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001  
 DBGRESTORE:        6 RAL key=0 recid=0 stamp=0 thread=1 seq=42 site_key=0  
 DBGRESTORE:          lowscn=3435770 nxtscn=3437175 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 07:02:55 nexttime=2018-05-14 08:45:45 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=4349 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  
 DBGRESTORE:        7 RAL key=6 recid=6 stamp=976092358 thread=1 seq=43 site_key=0  
 DBGRESTORE:          lowscn=3437175 nxtscn=3437200 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:45:45 nexttime=2018-05-14 08:45:58 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=16 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001  
 DBGRESTORE:        8 RAL key=0 recid=0 stamp=0 thread=1 seq=43 site_key=0  
 DBGRESTORE:          lowscn=3437175 nxtscn=3437200 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:45:45 nexttime=2018-05-14 08:45:58 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=16 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  
 DBGRESTORE:        9 RAL key=7 recid=7 stamp=976092375 thread=1 seq=44 site_key=0  
 DBGRESTORE:          lowscn=3437200 nxtscn=3437210 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:45:58 nexttime=2018-05-14 08:46:14 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=25 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000044_0974378014.0001  
 DBGRESTORE:       10 RAL key=0 recid=0 stamp=0 thread=1 seq=44 site_key=0  
 DBGRESTORE:          lowscn=3437200 nxtscn=3437210 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:45:58 nexttime=2018-05-14 08:46:14 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=25 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  
 DBGRESTORE:       11 RAL key=8 recid=8 stamp=976092381 thread=1 seq=45 site_key=0  
 DBGRESTORE:          lowscn=3437210 nxtscn=3437216 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:46:14 nexttime=2018-05-14 08:46:21 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=A blocks=1 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000045_0974378014.0001  
 DBGRESTORE:       12 RAL key=0 recid=0 stamp=0 thread=1 seq=45 site_key=0  
 DBGRESTORE:          lowscn=3437210 nxtscn=3437216 rstscn=1490582  
 DBGRESTORE:          lowtime=2018-05-14 08:46:14 nexttime=2018-05-14 08:46:21 rlgtime=2018-04-25 12:33:34  
 DBGRESTORE:          status=D blocks=1 krmkch { count=0 found=FALSE }  
 DBGRESTORE:          name=  

RMAN validates to see if they are already on disk or need to be restored.


 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 3  
 DBGSQL:         B :stamp = 976086144  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 40  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3435597  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:05.892] elapsed time [00:00:00:00.516]  
 RMAN-06050: archived log for thread 1 with sequence 40 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000040_0974378014.0001  
 DBGMISC:      ENTERED krmkflog [10:09:06.000]  
 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 4  
 DBGSQL:         B :stamp = 976086175  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 41  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3435668  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:06.407] elapsed time [00:00:00:00.407]  
 RMAN-06050: archived log for thread 1 with sequence 41 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000041_0974378014.0001  
 DBGMISC:      ENTERED krmkflog [10:09:06.482]  
 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 5  
 DBGSQL:         B :stamp = 976092346  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 42  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3435770  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:06.915] elapsed time [00:00:00:00.433]  
 RMAN-06050: archived log for thread 1 with sequence 42 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000042_0974378014.0001  
 DBGMISC:      ENTERED krmkflog [10:09:07.146]  
 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 6  
 DBGSQL:         B :stamp = 976092358  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 43  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3437175  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:07.705] elapsed time [00:00:00:00.559]  
 RMAN-06050: archived log for thread 1 with sequence 43 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000043_0974378014.0001  
 DBGMISC:      ENTERED krmkflog [10:09:07.787]  
 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 7  
 DBGSQL:         B :stamp = 976092375  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000044_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 44  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3437200  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:08.209] elapsed time [00:00:00:00.422]  
 RMAN-06050: archived log for thread 1 with sequence 44 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000044_0974378014.0001  
 DBGMISC:      ENTERED krmkflog [10:09:08.294]  
 DBGSQL:       TARGET> begin :valrc := sys.dbms_backup_restore.validateArchivedLog( recid       => :recid, stamp       => :stamp, fname       => :fname, thread      => :thd, sequence     => :seq, resetlogs_change => :resetscn, first_change   => :lowscn, blksize      => :blksize, signal      => 0, terminal     => :terminal); end;   
 DBGSQL:         sqlcode = 0  
 DBGSQL:         B :valrc = 0  
 DBGSQL:         B :recid = 8  
 DBGSQL:         B :stamp = 976092381  
 DBGSQL:         B :fname = D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000045_0974378014.0001  
 DBGSQL:         B :thd = 1  
 DBGSQL:         B :seq = 45  
 DBGSQL:         B :resetscn = 1490582  
 DBGSQL:         B :lowscn = 3437210  
 DBGSQL:         B :blksize = 512  
 DBGSQL:         B :terminal = 0  
 DBGMISC:      EXITED krmkflog with status 0 [10:09:08.799] elapsed time [00:00:00:00.505]  
 RMAN-06050: archived log for thread 1 with sequence 45 is already on disk as file D:\APP\BGRENN\VIRTUAL\PRODUCT\12.2.0\DBHOME_1\RDBMS\ARC0000000045_0974378014.0001  
 DBGRCV:       ENTERED krmksmr  


Finally the logs are applied




 BGSQL:       TARGET> select decode(LOG_MODE, 'ARCHIVELOG', 1, 0) into :dbstate from V$DATABASE  
 DBGSQL:         sqlcode = 0  
 DBGSQL:         D :dbstate = 1  
 DBGRCV:       EXITED krmksmr with address 0  
 DBGMISC:      EXITED krmkrcas [10:09:09.165] elapsed time [00:00:00:07.119]  
 DBGMISC:     EXITED krmkdmr [10:09:09.189] elapsed time [00:00:00:29.103]  
 DBGMISC:     EXITED krmkomp [10:09:09.232] elapsed time [00:00:00:31.701]  
 DBGPLSQL:    the compiled command tree is: [10:09:09.255] (krmicomp)  
 DBGPLSQL:     1 CMD type=restoring and applying logs cmdid=1 status=NOT STARTED  
 DBGPLSQL:       1 STEPstepid=1 cmdid=1 status=NOT STARTED chid=default  
 DBGPLSQL:         1 TEXTNOD = --  
 DBGPLSQL:         2 TEXTNOD = declare  
 DBGPLSQL:         3 TEXTNOD =   
 DBGPLSQL:         4 TEXTNOD =  mr_cancelled exception;  
 DBGPLSQL:         5 TEXTNOD =  pragma exception_init(mr_cancelled, -283);  
 DBGPLSQL:         6 TEXTNOD =   
 DBGPLSQL:         7 TEXTNOD = --  
 DBGPLSQL:         8 TEXTNOD =  mr_cont_rcv exception;  
 DBGPLSQL:         9 TEXTNOD =  pragma exception_init(mr_cont_rcv, -288);  
 DBGPLSQL:         10 TEXTNOD =   
 DBGPLSQL:         11 TEXTNOD =  mr_need_log exception;  
 DBGPLSQL:         12 TEXTNOD =  pragma exception_init(mr_need_log, -279);  
 DBGPLSQL:         13 TEXTNOD =   
 DBGPLSQL:         14 TEXTNOD =  mr_aborted  exception;  
 DBGPLSQL:         15 TEXTNOD =  pragma exception_init(mr_aborted, -20500);  
 DBGPLSQL:         16 TEXTNOD =   
 DBGPLSQL:         17 TEXTNOD =  bmr_block_errors exception;  
 DBGPLSQL:         18 TEXTNOD =  pragma exception_init(bmr_block_errors, -19680);  
 DBGPLSQL:         19 TEXTNOD =   
 DBGPLSQL:         20 TEXTNOD =  mr_createdf exception;  
 DBGPLSQL:         21 TEXTNOD =  pragma exception_init(mr_createdf, -20505);  
 DBGPLSQL:         22 TEXTNOD =   
 DBGPLSQL:         23 TEXTNOD =  archivelog_missing_exception   exception;  
 DBGPLSQL:         24 TEXTNOD =  pragma exception_init(archivelog_missing_exception, -20515);  
 DBGPLSQL:         25 TEXTNOD =   
 DBGPLSQL:         26 TEXTNOD =  archivelog_backup_not_found   exception;  
 DBGPLSQL:         27 TEXTNOD =  pragma exception_init(archivelog_backup_not_found, -20506);  
 DBGPLSQL:         28 TEXTNOD =   
 DBGPLSQL:         29 TEXTNOD =  alfrec      v$archived_log%ROWTYPE;  
 DBGPLSQL:         30 TEXTNOD =  dellog      boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         31 TEXTNOD =  deltarget    boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         32 TEXTNOD =  bmr       boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         33 TEXTNOD =  flash      boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         34 TEXTNOD =  pdbpitr     boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         35 TEXTNOD =  untilcancel   boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         36 TEXTNOD =  preplugin    boolean := FALSE; -- set by rman compiler  
 DBGPLSQL:         37 TEXTNOD =   
 DBGPLSQL:         38 TEXTNOD =  scn       number;  
 DBGPLSQL:         39 TEXTNOD =  stopthd     number;  
 DBGPLSQL:         40 TEXTNOD =  stopseq     number;  
 DBGPLSQL:         41 TEXTNOD =  stoprcv     boolean;  
 DBGPLSQL:         42 TEXTNOD =  rlc       number;   -- resetlogs count  
 DBGPLSQL:         43 TEXTNOD =  resetlogs_change number;   -- resetlogs SCN used when untilLog is set  
 DBGPLSQL:         44 TEXTNOD =  start_time  date;  
 DBGPLSQL:         45 TEXTNOD =  elapsed    number;  
 DBGPLSQL:         46 TEXTNOD =  hours     number;  
 DBGPLSQL:         47 TEXTNOD =  mins     number;  
 DBGPLSQL:         48 TEXTNOD =  secs     number;  
 DBGPLSQL:         49 TEXTNOD =  pstandby   number;  
 DBGPLSQL:         50 TEXTNOD =   
 DBGPLSQL:         51 TEXTNOD = --  
 DBGPLSQL:         52 TEXTNOD =  unnamed     varchar2(1024);  
 DBGPLSQL:         53 TEXTNOD =  dfname      varchar2(1024);  
 DBGPLSQL:         54 TEXTNOD =  newdfname    varchar2(1024);  
 DBGPLSQL:         55 TEXTNOD =  fileno      number := 0;  
 DBGPLSQL:         56 TEXTNOD =  recovdf     boolean := false;  
 DBGPLSQL:         57 TEXTNOD =  filelist     varchar2(512):=NULL;  
 DBGPLSQL:         58 TEXTNOD =  tmp       number:=0;  
 DBGPLSQL:         59 TEXTNOD =  toclause     boolean;  
 DBGPLSQL:         60 TEXTNOD =  tsnum      number;  
 DBGPLSQL:         61 TEXTNOD =  tsname      varchar2(32);  
 DBGPLSQL:         62 TEXTNOD =  pdbname     varchar2(128);  
 DBGPLSQL:         63 TEXTNOD =  bnewomf     boolean;  
 DBGPLSQL:         64 TEXTNOD =  dropf      boolean;  
 DBGPLSQL:         65 TEXTNOD =  createdf     boolean := false;  
 DBGPLSQL:         66 TEXTNOD =  type numTab_t is table of number index by binary_integer;  
 DBGPLSQL:         67 TEXTNOD =  df_offln_list  numTab_t;  
 DBGPLSQL:         68 TEXTNOD =  con_id      number := sys_context('userenv', 'con_id');  
 DBGPLSQL:         69 TEXTNOD =  internal_error  exception;  
 DBGPLSQL:         70 TEXTNOD =  pragma exception_init(internal_error, -600);  
 DBGPLSQL:         71 TEXTNOD =   
 DBGPLSQL:         72 TEXTNOD =  function continue_rcv(createdf OUT boolean) return boolean is  
 DBGPLSQL:         73 TEXTNOD =  begin  
 DBGPLSQL:         74 TEXTNOD =   createdf := false;  
 DBGPLSQL:         75 TEXTNOD =  <<do_cont_again>>  
 DBGPLSQL:         76 TEXTNOD =    begin  
 DBGPLSQL:         77 TEXTNOD =     krmicd.clearErrors;  
 DBGPLSQL:         78 TEXTNOD =     krmicd.execSql('alter database recover continue');  
 DBGPLSQL:         79 TEXTNOD =    exception  
 DBGPLSQL:         80 TEXTNOD =     when mr_cont_rcv then  
 DBGPLSQL:         81 TEXTNOD =      goto do_cont_again;  
 DBGPLSQL:         82 TEXTNOD =     when mr_need_log then  
 DBGPLSQL:         83 TEXTNOD =      return true;  
 DBGPLSQL:         84 TEXTNOD =     when mr_createdf then  
 DBGPLSQL:         85 TEXTNOD =      createdf := true;  
 DBGPLSQL:         86 TEXTNOD =      return true;  
 DBGPLSQL:         87 TEXTNOD =    end;  
 DBGPLSQL:         88 TEXTNOD =   return false;  
 DBGPLSQL:         89 TEXTNOD =  end;  
 DBGPLSQL:         90 TEXTNOD =   
 DBGPLSQL:         91 TEXTNOD = begin  
 DBGPLSQL:         92 TEXTNOD =   
 DBGPLSQL:         93 TEXTNOD =    
 DBGPLSQL:         94 PRMVAL = bmr := false; flash := false; pdbpitr := false; preplugin := false; dellog := false; deltarget := false;  
 DBGPLSQL:         95 TEXTNOD =   
 DBGPLSQL:         96 TEXTNOD =  toclause := krmicd.checkUntil(stopthd, stopseq);  
 DBGPLSQL:         97 TEXTNOD =   
 DBGPLSQL:         98 TEXTNOD =  select count(*) into pstandby from V$DATABASE  
 DBGPLSQL:         99 TEXTNOD =     where database_role='PHYSICAL STANDBY';  
 DBGPLSQL:        100 TEXTNOD =   
 DBGPLSQL:        101 TEXTNOD =  <<restart_recovery>> -- recovery is never restarted for bmr  
 DBGPLSQL:        102 TEXTNOD =   
 DBGPLSQL:        103 TEXTNOD =  begin   
 DBGPLSQL:        104 TEXTNOD =   select sysdate into start_time from x$dual;  
 DBGPLSQL:        105 TEXTNOD = --  
 DBGPLSQL:        106 TEXTNOD = --  
 DBGPLSQL:        107 TEXTNOD = --  
 DBGPLSQL:        108 TEXTNOD = --  
 DBGPLSQL:        109 TEXTNOD = --  
 DBGPLSQL:        110 TEXTNOD =   if not bmr and not flash and not pdbpitr and recovdf then  
 DBGPLSQL:        111 TEXTNOD =     deb('apply_log', 're-start recovery');  
 DBGPLSQL:        112 TEXTNOD =   
 DBGPLSQL:        113 TEXTNOD =     krmicd.execSQL('alter database recover datafile list clear');  
 DBGPLSQL:        114 TEXTNOD =     if filelist is not null then  
 DBGPLSQL:        115 TEXTNOD =      krmicd.execSql('alter database recover datafile list ' || filelist);  
 DBGPLSQL:        116 TEXTNOD =     end if;  
 DBGPLSQL:        117 TEXTNOD =     krmicd.execSql('alter database recover' || '  
 DBGPLSQL:        118 PRMVAL = if needed datafile 7  
 DBGPLSQL:        119 TEXTNOD = ');  
 DBGPLSQL:        120 TEXTNOD =     fileno := 0;  
 DBGPLSQL:        121 TEXTNOD =     recovdf := false;  
 DBGPLSQL:        122 TEXTNOD =    end if;  
 DBGPLSQL:        123 TEXTNOD =   exception   
 DBGPLSQL:        124 TEXTNOD =     when mr_need_log then  
 DBGPLSQL:        125 TEXTNOD =      krmicd.clearErrors;  
 DBGPLSQL:        126 TEXTNOD =   end;  
 DBGPLSQL:        127 TEXTNOD =   
 DBGPLSQL:        128 TEXTNOD = --  
 DBGPLSQL:        129 TEXTNOD = <<get_log>>  
 DBGPLSQL:        130 TEXTNOD =   
 DBGPLSQL:        131 TEXTNOD =  if createdf then  
 DBGPLSQL:        132 TEXTNOD =   createdf := false;  
 DBGPLSQL:        133 TEXTNOD =   raise mr_createdf;  
 DBGPLSQL:        134 TEXTNOD =  end if;  
 DBGPLSQL:        135 TEXTNOD =   
 DBGPLSQL:        136 TEXTNOD =  begin  
 DBGPLSQL:        137 TEXTNOD =   select thr, seq, scn, rls, rlc into  
 DBGPLSQL:        138 TEXTNOD =      alfrec.thread#, alfrec.sequence#, scn, alfrec.resetlogs_change#,  
 DBGPLSQL:        139 TEXTNOD =      rlc from x$kcrmx;  
 DBGPLSQL:        140 TEXTNOD =   
 DBGPLSQL:        141 TEXTNOD =  exception  
 DBGPLSQL:        142 TEXTNOD =   when no_data_found then  
 DBGPLSQL:        143 TEXTNOD =    if bmr then  
 DBGPLSQL:        144 TEXTNOD =      begin  
 DBGPLSQL:        145 TEXTNOD =       sys.dbms_backup_restore.bmrCancel;  
 DBGPLSQL:        146 TEXTNOD =      exception  
 DBGPLSQL:        147 TEXTNOD =       when bmr_block_errors then  
 DBGPLSQL:        148 TEXTNOD =         krmicd.writeMsg(8111);  
 DBGPLSQL:        149 TEXTNOD =      end;  
 DBGPLSQL:        150 TEXTNOD =    elsif flash then  
 DBGPLSQL:        151 TEXTNOD =      sys.dbms_backup_restore.flashbackCancel;  
 DBGPLSQL:        152 TEXTNOD =      krmicd.checkSetDatabase;  
 DBGPLSQL:        153 TEXTNOD =    elsif pdbpitr then  
 DBGPLSQL:        154 TEXTNOD =      sys.dbms_backup_restore.recoverCancel;  
 DBGPLSQL:        155 TEXTNOD =    elsif preplugin then  
 DBGPLSQL:        156 TEXTNOD =      sys.dbms_backup_restore.prePluginRecoveryCancel;  
 DBGPLSQL:        157 TEXTNOD =    end if;  
 DBGPLSQL:        158 TEXTNOD = --  
 DBGPLSQL:        159 TEXTNOD = --  
 DBGPLSQL:        160 TEXTNOD = --  
 DBGPLSQL:        161 TEXTNOD = --  
 DBGPLSQL:        162 TEXTNOD = --  
 DBGPLSQL:        163 TEXTNOD = --  
 DBGPLSQL:        164 TEXTNOD = --  
 DBGPLSQL:        165 TEXTNOD = --  
 DBGPLSQL:        166 TEXTNOD =   
 DBGPLSQL:        167 TEXTNOD = --  
 DBGPLSQL:        168 TEXTNOD =    delete_logs(FALSE, dellog, deltarget, preplugin);  
 DBGPLSQL:        169 TEXTNOD =   
 DBGPLSQL:        170 TEXTNOD =    return;  
 DBGPLSQL:        171 TEXTNOD =  end;  
 DBGPLSQL:        172 TEXTNOD =   
 DBGPLSQL:        173 TEXTNOD =  select resetlogs_change# into resetlogs_change from v$database_incarnation  
 DBGPLSQL:        174 TEXTNOD =    where status='CURRENT';  
 DBGPLSQL:        175 TEXTNOD =   
 DBGPLSQL:        176 TEXTNOD =  if (resetlogs_change=alfrec.resetlogs_change# and  
 DBGPLSQL:        177 TEXTNOD =    stopthd = alfrec.thread# and  
 DBGPLSQL:        178 TEXTNOD =    alfrec.sequence# >= stopseq)  
 DBGPLSQL:        179 TEXTNOD =  then  
 DBGPLSQL:        180 TEXTNOD =   stoprcv := FALSE;  
 DBGPLSQL:        181 TEXTNOD =   if bmr then  
 DBGPLSQL:        182 TEXTNOD =    begin  
 DBGPLSQL:        183 TEXTNOD =      sys.dbms_backup_restore.bmrCancel;  
 DBGPLSQL:        184 TEXTNOD =    exception  
 DBGPLSQL:        185 TEXTNOD =      when bmr_block_errors then  
 DBGPLSQL:        186 TEXTNOD =       krmicd.writeMsg(8111);  
 DBGPLSQL:        187 TEXTNOD =    end;  
 DBGPLSQL:        188 TEXTNOD =    stoprcv := TRUE;  
 DBGPLSQL:        189 TEXTNOD =   elsif flash then  
 DBGPLSQL:        190 TEXTNOD = --  
 DBGPLSQL:        191 TEXTNOD = --  
 DBGPLSQL:        192 TEXTNOD =    if alfrec.sequence# > stopseq then  
 DBGPLSQL:        193 TEXTNOD =      sys.dbms_backup_restore.flashbackCancel;  
 DBGPLSQL:        194 TEXTNOD =      krmicd.checkSetDatabase;  
 DBGPLSQL:        195 TEXTNOD =      stoprcv := TRUE;  
 DBGPLSQL:        196 TEXTNOD =    end if;  
 DBGPLSQL:        197 TEXTNOD =   elsif pdbpitr then  
 DBGPLSQL:        198 TEXTNOD =    sys.dbms_backup_restore.recoverCancel;  
 DBGPLSQL:        199 TEXTNOD =    stoprcv := TRUE;  
 DBGPLSQL:        200 TEXTNOD =   elsif preplugin then  
 DBGPLSQL:        201 TEXTNOD =    sys.dbms_backup_restore.prePluginRecoveryCancel;  
 DBGPLSQL:        202 TEXTNOD =    stoprcv := TRUE;  
 DBGPLSQL:        203 TEXTNOD =   else  
 DBGPLSQL:        204 TEXTNOD =    krmicd.execSql('alter database recover cancel');  
 DBGPLSQL:        205 TEXTNOD =    stoprcv := TRUE;  
 DBGPLSQL:        206 TEXTNOD =   end if;  
 DBGPLSQL:        207 TEXTNOD =   
 DBGPLSQL:        208 TEXTNOD =   if stoprcv then  
 DBGPLSQL:        209 TEXTNOD = --  
 DBGPLSQL:        210 TEXTNOD = --  
 DBGPLSQL:        211 TEXTNOD = --  
 DBGPLSQL:        212 TEXTNOD = --  
 DBGPLSQL:        213 TEXTNOD = --  
 DBGPLSQL:        214 TEXTNOD =   
 DBGPLSQL:        215 TEXTNOD = --  
 DBGPLSQL:        216 TEXTNOD =    delete_logs(FALSE, dellog, deltarget, preplugin);  
 DBGPLSQL:        217 TEXTNOD =    select abs(sysdate-start_time) into elapsed from x$dual;  
 DBGPLSQL:        218 TEXTNOD =    dur2time(elapsed, hours, mins, secs);  
 DBGPLSQL:        219 TEXTNOD = --  
 DBGPLSQL:        220 TEXTNOD =    krmicd.writeMsg(8181, to_char(hours, 'FM09') || ':' ||  
 DBGPLSQL:        221 TEXTNOD =               to_char(mins, 'FM09') || ':' ||  
 DBGPLSQL:        222 TEXTNOD =               to_char(secs, 'FM09'));      
 DBGPLSQL:        223 TEXTNOD =    return;  
 DBGPLSQL:        224 TEXTNOD =   end if;  
 DBGPLSQL:        225 TEXTNOD =  end if;  
 DBGPLSQL:        226 TEXTNOD =   
 DBGPLSQL:        227 TEXTNOD =  begin  
 DBGPLSQL:        228 TEXTNOD =   deb('log_apply', 'looking for log with scn ' ||scn||' thread='||  
 DBGPLSQL:        229 TEXTNOD =     alfrec.thread#||' sequence='||alfrec.sequence# ||' resetlogs scn '||  
 DBGPLSQL:        230 TEXTNOD =     alfrec.resetlogs_change#||' resetlogs time='||  
 DBGPLSQL:        231 TEXTNOD =     to_char(stamp2date(rlc)));  
 DBGPLSQL:        232 TEXTNOD =   
 DBGPLSQL:        233 TEXTNOD =   begin  
 DBGPLSQL:        234 TEXTNOD = --  
 DBGPLSQL:        235 TEXTNOD =    alfrec.name := krmicd.checkLog(scn,  
 DBGPLSQL:        236 TEXTNOD =                  alfrec.thread#,  
 DBGPLSQL:        237 TEXTNOD =                  alfrec.sequence#,  
 DBGPLSQL:        238 TEXTNOD =                  alfrec.recid,  
 DBGPLSQL:        239 TEXTNOD =                  alfrec.stamp,  
 DBGPLSQL:        240 TEXTNOD =                  alfrec.resetlogs_change#,  
 DBGPLSQL:        241 TEXTNOD =                  stamp2date(rlc),  
 DBGPLSQL:        242 TEXTNOD =                  alfrec.first_change#,  
 DBGPLSQL:        243 TEXTNOD =                  alfrec.next_change#,  
 DBGPLSQL:        244 TEXTNOD =                  alfrec.block_size,  
 DBGPLSQL:        245 TEXTNOD =                  preplugin);  
 DBGPLSQL:        246 TEXTNOD =   
 DBGPLSQL:        247 TEXTNOD =   exception  
 DBGPLSQL:        248 TEXTNOD =    when archivelog_backup_not_found or archivelog_missing_exception then  
 DBGPLSQL:        249 TEXTNOD =      if (untilcancel) then  
 DBGPLSQL:        250 TEXTNOD = --  
 DBGPLSQL:        251 TEXTNOD = --  
 DBGPLSQL:        252 TEXTNOD = --  
 DBGPLSQL:        253 TEXTNOD =       alfrec.name := NULL;  
 DBGPLSQL:        254 TEXTNOD =       krmicd.writeMsg(8194, to_char(alfrec.thread#),  
 DBGPLSQL:        255 TEXTNOD =                to_char(alfrec.sequence#));  
 DBGPLSQL:        256 TEXTNOD =      else  
 DBGPLSQL:        257 TEXTNOD = --  
 DBGPLSQL:        258 TEXTNOD = --  
 DBGPLSQL:        259 TEXTNOD = --  
 DBGPLSQL:        260 TEXTNOD =       raise;  
 DBGPLSQL:        261 TEXTNOD =      end if;  
 DBGPLSQL:        262 TEXTNOD =   end;  
 DBGPLSQL:        263 TEXTNOD =  exception  
 DBGPLSQL:        264 TEXTNOD =   when archivelog_backup_not_found then  
 DBGPLSQL:        265 TEXTNOD =    raise;  
 DBGPLSQL:        266 TEXTNOD =   when others then  
 DBGPLSQL:        267 TEXTNOD =    if (is_db_in_noarchivelog) then  
 DBGPLSQL:        268 TEXTNOD =      krmicd.writeMsg(8187, to_char(scn));  
 DBGPLSQL:        269 TEXTNOD =    else  
 DBGPLSQL:        270 TEXTNOD =      if pstandby = 1 then  
 DBGPLSQL:        271 TEXTNOD =       krmicd.clearErrors;  
 DBGPLSQL:        272 TEXTNOD = --  
 DBGPLSQL:        273 TEXTNOD =       delete_logs(FALSE, dellog, deltarget, preplugin);  
 DBGPLSQL:        274 TEXTNOD =       select abs(sysdate-start_time) into elapsed from x$dual;  
 DBGPLSQL:        275 TEXTNOD =       dur2time(elapsed, hours, mins, secs);  
 DBGPLSQL:        276 TEXTNOD = --  
 DBGPLSQL:        277 TEXTNOD =       krmicd.writeMsg(8181, to_char(hours, 'FM09') || ':' ||  
 DBGPLSQL:        278 TEXTNOD =                  to_char(mins, 'FM09') || ':' ||  
 DBGPLSQL:        279 TEXTNOD =                  to_char(secs, 'FM09'));  
 DBGPLSQL:        280 TEXTNOD =       return;  
 DBGPLSQL:        281 TEXTNOD =      else  
 DBGPLSQL:        282 TEXTNOD =       krmicd.writeMsg(8060);     -- unable to find log  
 DBGPLSQL:        283 TEXTNOD =       krmicd.writeMsg(8510, to_char(alfrec.thread#),  
 DBGPLSQL:        284 TEXTNOD =                  to_char(alfrec.sequence#));  
 DBGPLSQL:        285 TEXTNOD =       raise;  
 DBGPLSQL:        286 TEXTNOD =      end if;  
 DBGPLSQL:        287 TEXTNOD =    end if;  
 DBGPLSQL:        288 TEXTNOD =  end;  
 DBGPLSQL:        289 TEXTNOD =   
 DBGPLSQL:        290 TEXTNOD =  deb('log_apply', 'log file name returned is ' || alfrec.name );  
 DBGPLSQL:        291 TEXTNOD =   
 DBGPLSQL:        292 TEXTNOD =  begin  
 DBGPLSQL:        293 TEXTNOD =   
 DBGPLSQL:        294 TEXTNOD =   if alfrec.name is not NULL then  
 DBGPLSQL:        295 TEXTNOD =    if bmr then  
 DBGPLSQL:        296 TEXTNOD =     sys.dbms_backup_restore.bmrDoMediaRecovery(alfrec.name);  
 DBGPLSQL:        297 TEXTNOD =    elsif flash then  
 DBGPLSQL:        298 TEXTNOD =     sys.dbms_backup_restore.flashbackFiles(alfrec.name);  
 DBGPLSQL:        299 TEXTNOD =    elsif pdbpitr then  
 DBGPLSQL:        300 TEXTNOD =     sys.dbms_backup_restore.recoverDo(alfrec.name);  
 DBGPLSQL:        301 TEXTNOD =    elsif preplugin then  
 DBGPLSQL:        302 TEXTNOD =     sys.dbms_backup_restore.prePluginDoMediaRecovery(alfrec.name);  
 DBGPLSQL:        303 TEXTNOD =    else  
 DBGPLSQL:        304 TEXTNOD =     krmicd.writeMsg(8515, alfrec.name,  
 DBGPLSQL:        305 TEXTNOD =             to_char(alfrec.thread#),  
 DBGPLSQL:        306 TEXTNOD =             to_char(alfrec.sequence#));  
 DBGPLSQL:        307 TEXTNOD = --  
 DBGPLSQL:        308 TEXTNOD =     krmicd.execSql( 'alter database recover logfile ''' ||  
 DBGPLSQL:        309 TEXTNOD =              replace(alfrec.name,'''','''''') || '''');  
 DBGPLSQL:        310 TEXTNOD =    end if;  
 DBGPLSQL:        311 TEXTNOD =   
 DBGPLSQL:        312 TEXTNOD = --  
 DBGPLSQL:        313 TEXTNOD = --  
 DBGPLSQL:        314 TEXTNOD = --  
 DBGPLSQL:        315 TEXTNOD = --  
 DBGPLSQL:        316 TEXTNOD = --  
 DBGPLSQL:        317 TEXTNOD =   
 DBGPLSQL:        318 TEXTNOD = --  
 DBGPLSQL:        319 TEXTNOD =    delete_logs(FALSE, dellog, deltarget, preplugin);  
 DBGPLSQL:        320 TEXTNOD =   
 DBGPLSQL:        321 TEXTNOD =    if bmr then  
 DBGPLSQL:        322 TEXTNOD =     begin  
 DBGPLSQL:        323 TEXTNOD =       sys.dbms_backup_restore.bmrCancel;  
 DBGPLSQL:        324 TEXTNOD =     exception  
 DBGPLSQL:        325 TEXTNOD =       when bmr_block_errors then  
 DBGPLSQL:        326 TEXTNOD =        krmicd.writeMsg(8111);  
 DBGPLSQL:        327 TEXTNOD =     end;  
 DBGPLSQL:        328 TEXTNOD =    elsif flash then  
 DBGPLSQL:        329 TEXTNOD =     sys.dbms_backup_restore.flashbackCancel;  
 DBGPLSQL:        330 TEXTNOD =     krmicd.checkSetDatabase;  
 DBGPLSQL:        331 TEXTNOD =    elsif pdbpitr then  
 DBGPLSQL:        332 TEXTNOD =     sys.dbms_backup_restore.recoverCancel;  
 DBGPLSQL:        333 TEXTNOD =    elsif preplugin then  
 DBGPLSQL:        334 TEXTNOD =     sys.dbms_backup_restore.prePluginRecoveryCancel;  
 DBGPLSQL:        335 TEXTNOD =    end if;  
 DBGPLSQL:        336 TEXTNOD =    select abs(sysdate-start_time) into elapsed from x$dual;  
 DBGPLSQL:        337 TEXTNOD =    dur2time(elapsed, hours, mins, secs);  
 DBGPLSQL:        338 TEXTNOD = --  
 DBGPLSQL:        339 TEXTNOD =    krmicd.writeMsg(8181, to_char(hours, 'FM09') || ':' ||  
 DBGPLSQL:        340 TEXTNOD =               to_char(mins, 'FM09') || ':' ||  
 DBGPLSQL:        341 TEXTNOD =               to_char(secs, 'FM09'));     
 DBGPLSQL:        342 TEXTNOD =    return;  
 DBGPLSQL:        343 TEXTNOD =   else  
 DBGPLSQL:        344 TEXTNOD =    return;  
 DBGPLSQL:        345 TEXTNOD =   end if;  
 DBGPLSQL:        346 TEXTNOD =  exception  
 DBGPLSQL:        347 TEXTNOD =   when mr_cont_rcv then  
 DBGPLSQL:        348 TEXTNOD =    if continue_rcv(createdf) then  
 DBGPLSQL:        349 TEXTNOD =     goto get_log;  
 DBGPLSQL:        350 TEXTNOD =    end if;  
 DBGPLSQL:        351 TEXTNOD =   when mr_need_log then  
 DBGPLSQL:        352 TEXTNOD = --  
 DBGPLSQL:        353 TEXTNOD = --  
 DBGPLSQL:        354 TEXTNOD =    krmicd.clearErrors;  
 DBGPLSQL:        355 TEXTNOD =   
 DBGPLSQL:        356 TEXTNOD = --  
 DBGPLSQL:        357 TEXTNOD = --  
 DBGPLSQL:        358 TEXTNOD = --  
 DBGPLSQL:        359 TEXTNOD = --  
 DBGPLSQL:        360 TEXTNOD = --  
 DBGPLSQL:        361 TEXTNOD =    delete_logs(TRUE, dellog, deltarget, preplugin);  
 DBGPLSQL:        362 TEXTNOD =   
 DBGPLSQL:        363 TEXTNOD =    goto get_log;  
 DBGPLSQL:        364 TEXTNOD =   when mr_createdf then  
 DBGPLSQL:        365 TEXTNOD =    if (bmr or flash or pdbpitr) then  
 DBGPLSQL:        366 TEXTNOD =     raise;  
 DBGPLSQL:        367 TEXTNOD =    end if;  
 DBGPLSQL:        368 TEXTNOD =   
 DBGPLSQL:        369 TEXTNOD = --  
 DBGPLSQL:        370 TEXTNOD =    for df_rec in (select fnfno, fnnam, fnonm, ts.ts#, ts.name,  
 DBGPLSQL:        371 TEXTNOD =            fepfdi, fepdi,  
 DBGPLSQL:        372 TEXTNOD =            (case when pdb.con_id > 1 then  
 DBGPLSQL:        373 TEXTNOD =            pdb.name else null end) pdbname  
 DBGPLSQL:        374 TEXTNOD =    from x$kccfn fn, x$kccfe fe, v$tablespace ts, v$containers pdb  
 DBGPLSQL:        375 TEXTNOD =    where fn.fnunn = 1  
 DBGPLSQL:        376 TEXTNOD =     and fn.fnfno=fe.fenum  
 DBGPLSQL:        377 TEXTNOD =     and fe.fefnh=fnnum  
 DBGPLSQL:        378 TEXTNOD =     and fe.fetsn=ts.ts#  
 DBGPLSQL:        379 TEXTNOD =     and fe.con_id = ts.con_id  
 DBGPLSQL:        380 TEXTNOD =     and fe.con_id = pdb.con_id) loop  
 DBGPLSQL:        381 TEXTNOD =   
 DBGPLSQL:        382 TEXTNOD = --  
 DBGPLSQL:        383 TEXTNOD = --  
 DBGPLSQL:        384 TEXTNOD =     if (df_rec.fepdi > 0 or df_rec.fepfdi > 0) then  
 DBGPLSQL:        385 TEXTNOD =      raise;  
 DBGPLSQL:        386 TEXTNOD =     end if;  
 DBGPLSQL:        387 TEXTNOD =   
 DBGPLSQL:        388 TEXTNOD =     fileno := df_rec.fnfno;  
 DBGPLSQL:        389 TEXTNOD =     unnamed := df_rec.fnnam;  
 DBGPLSQL:        390 TEXTNOD =     dfname := df_rec.fnonm;  
 DBGPLSQL:        391 TEXTNOD =     tsnum := df_rec.ts#;  
 DBGPLSQL:        392 TEXTNOD =     tsname := df_rec.name;  
 DBGPLSQL:        393 TEXTNOD =     pdbname := df_rec.pdbname;  
 DBGPLSQL:        394 TEXTNOD =   
 DBGPLSQL:        395 TEXTNOD =     deb('apply_log', 'tsnum ' || tsnum);  
 DBGPLSQL:        396 TEXTNOD =     deb('apply_log', 'tsname ' || tsname);  
 DBGPLSQL:        397 TEXTNOD =     deb('apply_log', 'fileno ' || fileno);  
 DBGPLSQL:        398 TEXTNOD =     deb('apply_log', 'dfname ' || dfname);  
 DBGPLSQL:        399 TEXTNOD =     deb('apply_log', 'pdbname' || nvl(pdbname, 'NULL'));  
 DBGPLSQL:        400 TEXTNOD =   
 DBGPLSQL:        401 TEXTNOD =     deb('apply_log', 'file old name is ' || dfname);  
 DBGPLSQL:        402 TEXTNOD =   
 DBGPLSQL:        403 TEXTNOD =     recovdf := true;  
 DBGPLSQL:        404 TEXTNOD =     if krmicd.getDfInfo(fileno, tsnum, tsname, pdbname,  
 DBGPLSQL:        405 TEXTNOD =               newdfname, bnewomf, dropf)  
 DBGPLSQL:        406 TEXTNOD =     then  
 DBGPLSQL:        407 TEXTNOD =       if (newdfname is not null) then  
 DBGPLSQL:        408 TEXTNOD =        dfname := newdfname;  
 DBGPLSQL:        409 TEXTNOD =        deb('apply_log', 'file new name is ' || newdfname);  
 DBGPLSQL:        410 TEXTNOD =       else  
 DBGPLSQL:        411 TEXTNOD =        deb('apply_log', 'using name at creation ' || dfname);  
 DBGPLSQL:        412 TEXTNOD =       end if;  
 DBGPLSQL:        413 TEXTNOD =   
 DBGPLSQL:        414 TEXTNOD =       krmicd.writeMsg(6064, fileno, dfname);  
 DBGPLSQL:        415 TEXTNOD =       sys.dbms_backup_restore.createDatafile(fno => fileno,  
 DBGPLSQL:        416 TEXTNOD =                          newomf => bnewomf,  
 DBGPLSQL:        417 TEXTNOD =                          recovery => TRUE,  
 DBGPLSQL:        418 TEXTNOD =                          fname => dfname);  
 DBGPLSQL:        419 TEXTNOD =   
 DBGPLSQL:        420 TEXTNOD = --  
 DBGPLSQL:        421 TEXTNOD =       if filelist is not null then  
 DBGPLSQL:        422 TEXTNOD =        filelist := filelist || ', ' || fileno;  
 DBGPLSQL:        423 TEXTNOD =       else  
 DBGPLSQL:        424 TEXTNOD =        filelist := fileno;  
 DBGPLSQL:        425 TEXTNOD =       end if;  
 DBGPLSQL:        426 TEXTNOD =   
 DBGPLSQL:        427 TEXTNOD =     else  
 DBGPLSQL:        428 TEXTNOD =      dfname := null;  
 DBGPLSQL:        429 TEXTNOD =      deb('apply_log', 'no filename - ignore creation of file# '  
 DBGPLSQL:        430 TEXTNOD =               || fileno);  
 DBGPLSQL:        431 TEXTNOD =      deb('apply_log', 'This is recover database skip tablespace cmd');  
 DBGPLSQL:        432 TEXTNOD =   
 DBGPLSQL:        433 TEXTNOD =      if (df_offln_list.exists(fileno)) then  
 DBGPLSQL:        434 TEXTNOD =       deb('apply_log', 'file is already offlined ' || fileno);  
 DBGPLSQL:        435 TEXTNOD =   
 DBGPLSQL:        436 TEXTNOD =      else  
 DBGPLSQL:        437 TEXTNOD =   
 DBGPLSQL:        438 TEXTNOD =       df_offln_list(fileno) := 1;  
 DBGPLSQL:        439 TEXTNOD =   
 DBGPLSQL:        440 TEXTNOD =       if (dropf = true) then  
 DBGPLSQL:        441 TEXTNOD =        krmicd.writeMsg(6958, 'alter database datafile ' || fileno ||  
 DBGPLSQL:        442 TEXTNOD =                   ' offline drop');  
 DBGPLSQL:        443 TEXTNOD =        krmicd.execSql('alter database datafile ' || fileno ||  
 DBGPLSQL:        444 TEXTNOD =                ' offline drop');  
 DBGPLSQL:        445 TEXTNOD =       else  
 DBGPLSQL:        446 TEXTNOD =        krmicd.writeMsg(6958, 'alter database datafile ' || fileno ||  
 DBGPLSQL:        447 TEXTNOD =                   ' offline');  
 DBGPLSQL:        448 TEXTNOD =        krmicd.execSql('alter database datafile ' || fileno ||  
 DBGPLSQL:        449 TEXTNOD =                ' offline');  
 DBGPLSQL:        450 TEXTNOD =       end if;  
 DBGPLSQL:        451 TEXTNOD =      end if;  
 DBGPLSQL:        452 TEXTNOD =     end if;  
 DBGPLSQL:        453 TEXTNOD =    end loop;  
 DBGPLSQL:        454 TEXTNOD = --  
 DBGPLSQL:        455 TEXTNOD = --  
 DBGPLSQL:        456 TEXTNOD =    krmicd.clearErrors;  
 DBGPLSQL:        457 TEXTNOD =    goto restart_recovery;  
 DBGPLSQL:        458 TEXTNOD =  end;  
 DBGPLSQL:        459 TEXTNOD = end;  



So there are the steps that RMAN goes through


With RMAN the restore/recovery is 3 steps and works like this.  

RESTORE Process:
  1. Restore the necessary pieces of the database

RECOVER Process:

  1. Find and recover incremental backups of the database to bring the SCN as close as close as possible to the recovery point.

     NOTE : this happens as one process.  RMAN reads the backup sets and applies the blocks as it processes the backup sets,  Like a full restore, the backupset is streamed into the RMAN channels, and RMAN writes the necessary blocks to the files. 

Media recovery :
 
    NOTE : From an RMAN standpoint, media recovery is archive log processing only.  Incremental backup processing is considered recover

3) Identify the archive logs needed for recovery
4) Validate archive logs needed are on disk, and if not restore archive logs
5) recover database using archive logs on disk