PDB Recovery Isolation in 21c

 In my previous blog post, where I demonstrated PDB Flashback, I had alluded to the "PDB Recovery Isolation" feature of 21c.

Here is a demonstration.

On the Primary, I issue only two commands to create a new PDB from an *existing, active* PDB (a PDB that is in Read-Write mode and is not  PDB$SEED) :  The source PDBHKC is active and you will notice the Archive Log Sequence# being incremented significantly as transactions are in-flight and continuing while PDBKC is being CREATEd and OPENed.

SQL> create pluggable database pdbnew from pdbhkc;

Pluggable database created.

SQL> alter pluggable database pdbnew open;

Pluggable database altered.

SQL> quit

These are the relevant Primary Database Alert entries (not every entry) :

2022-05-08T22:32:56.582810+08:00
create pluggable database pdbnew from pdbhkc

2022-05-08T22:33:02.783531+08:00
PDBNEW(6):Endian type of dictionary set to little

2022-05-08T22:33:03.103173+08:00
****************************************************************
Pluggable Database PDBNEW with pdb id - 6 is created as UNUSABLE.
If any errors are encountered before the pdb is marked as NEW,
then the pdb must be dropped
local undo-1, localundoscn-0x000000000000011d
****************************************************************
PDBNEW(6):Media Recovery Start
2022-05-08T22:33:03.293420+08:00
PDBNEW(6):Serial Media Recovery started
PDBNEW(6):max_pdb is 6
2022-05-08T22:33:03.393288+08:00
PDBNEW(6):Recovery of Online Redo Log: Thread 1 Group 1 Seq 73 Reading mem 0
PDBNEW(6):  Mem# 0: /u02/oradata/DB213H1/redo01.log
2022-05-08T22:33:03.541053+08:00
Thread 1 advanced to log sequence 75 (LGWR switch),  current SCN: 4931897
  Current log# 3 seq# 75 mem# 0: /u02/oradata/DB213H1/redo03.log
2022-05-08T22:33:03.541508+08:00
PDBNEW(6):Recovery of Online Redo Log: Thread 1 Group 2 Seq 74 Reading mem 0
PDBNEW(6):  Mem# 0: /u02/oradata/DB213H1/redo02.log
2022-05-08T22:33:03.598468+08:00
PDBNEW(6):Incomplete Recovery applied until change 4931866 time 05/08/2022 22:33:02
PDBNEW(6):NET  (PID:16256): Media Recovery Complete [dbsdrv.c:15048]
2022-05-08T22:33:03.615889+08:00
NET  (PID:16388): Archived Log entry 119 added for B-1102494684.T-1.S-74 ID 0x7fbfe6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:03.786205+08:00
PDBNEW(6):Pluggable database PDBNEW pseudo opening
PDBNEW(6):SUPLOG: Initialize PDB SUPLOG SGA, old value 0x0, new value 0x18
PDBNEW(6):Autotune of undo retention is turned on.
PDBNEW(6):Undo initialization recovery: Parallel FPTR failed: start:15704441 end:15704446 diff:5 ms (0.0 seconds)
PDBNEW(6):Undo initialization recovery: err:0 start: 15704439 end: 15704511 diff: 72 ms (0.1 seconds)
PDBNEW(6):[16256] Successfully onlined Undo Tablespace 2.
PDBNEW(6):Undo initialization online undo segments: err:0 start: 15704512 end: 15704530 diff: 18 ms (0.0 seconds)
PDBNEW(6):Undo initialization finished serial:0 start:15704439 end:15704538 diff:99 ms (0.1 seconds)
PDBNEW(6):Database Characterset for PDBNEW is AL32UTF8
PDBNEW(6):Pluggable database PDBNEW pseudo closing
PDBNEW(6):JIT: pid 16256 requesting stop
PDBNEW(6):Closing sequence subsystem (15704602605).
PDBNEW(6):Buffer Cache flush started: 6
PDBNEW(6):Buffer Cache flush finished: 6
Completed: create pluggable database pdbnew from pdbhkc


2022-05-08T22:33:18.209272+08:00
alter pluggable database pdbnew open
2022-05-08T22:33:18.210926+08:00
PDBNEW(6):Pluggable database PDBNEW opening in read write
PDBNEW(6):SUPLOG: Initialize PDB SUPLOG SGA, old value 0x0, new value 0x18
PDBNEW(6):Autotune of undo retention is turned on.
PDBNEW(6):Endian type of dictionary set to little
PDBNEW(6):Undo initialization recovery: Parallel FPTR complete: start:15718778 end:15718780 diff:2 ms (0.0 seconds)
PDBNEW(6):Undo initialization recovery: err:0 start: 15718778 end: 15718780 diff: 2 ms (0.0 seconds)
PDBNEW(6):[16256] Successfully onlined Undo Tablespace 2.
PDBNEW(6):Undo initialization online undo segments: err:0 start: 15718780 end: 15718873 diff: 93 ms (0.1 seconds)
PDBNEW(6):Undo initialization finished serial:0 start:15718778 end:15718875 diff:97 ms (0.1 seconds)
PDBNEW(6):Database Characterset for PDBNEW is AL32UTF8
PDBNEW(6):Deleting old file#13 from file$
PDBNEW(6):Deleting old file#14 from file$
PDBNEW(6):Deleting old file#15 from file$
PDBNEW(6):Adding new file#22 to file$(old file#13).             fopr-1, newblks-35840, oldblks-19200
PDBNEW(6):Adding new file#23 to file$(old file#14).             fopr-1, newblks-47360, oldblks-15360
PDBNEW(6):Adding new file#24 to file$(old file#15).             fopr-1, newblks-12800, oldblks-12800
PDBNEW(6):Successfully created internal service PDBNEW at open
****************************************************************
Post plug operations are now complete.
Pluggable database PDBNEW with pdb id - 6 is now marked as NEW.
****************************************************************
PDBNEW(6):SUPLOG: Set PDB SUPLOG SGA at PDB OPEN, old 0x18, new 0x0 (no suplog)


2022-05-08T22:33:21.760166+08:00
Thread 1 advanced to log sequence 81 (LGWR switch),  current SCN: 4933127
  Current log# 3 seq# 81 mem# 0: /u02/oradata/DB213H1/redo03.log


2022-05-08T22:33:23.162867+08:00
PDBNEW(6):Opening pdb with no Resource Manager plan active
Pluggable database PDBNEW opened read write
Completed: alter pluggable database pdbnew open

(The "Deleting old file#" and "Adding new file#" entries are simply about updating the controlfile)

Note that Log Sequence# has moved from 72 to 81 during the course of the CREATE and OPEN of the new PDB.

These are the Standby Alert Log entries :

2022-05-08T22:32:57.237583+08:00
ARC0 (PID:1354): Archived Log entry 55 added for B-1102494684.T-1.S-73 ID 0x7f7ae6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:32:57.237902+08:00
 rfs (PID:12549): Opened LNO:5 for DBID:3870017436 B-1102494684.T-1.S-74 [krsr.c:18143]
2022-05-08T22:32:57.386776+08:00
PR00 (PID:1438): Media Recovery Waiting for T-1.S-74 (in transit) [krsm.c:6185]
2022-05-08T22:32:57.388789+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 74 Reading mem 0
  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_5_k5yt8yjw_.log
2022-05-08T22:33:02.900342+08:00
Recovery created pluggable database PDBNEW
PDBNEW(6):Tablespace-SYSTEM during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #22 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_system_k7ho4s6r_.dbf'.
PDBNEW(6):Tablespace-SYSAUX during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #23 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_sysaux_k7ho4s6s_.dbf'.
PDBNEW(6):Tablespace-UNDOTBS1 during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #24 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_undotbs1_k7ho4s6t_.dbf'.
PDBNEW(6):Tablespace-TEMP during PDB create offlined since source is in r/w mode or this is a refresh clone
2022-05-08T22:33:03.709388+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-75 [krsr.c:18143]
2022-05-08T22:33:03.724813+08:00
ARC2 (PID:1362): Archived Log entry 56 added for B-1102494684.T-1.S-74 ID 0x7fbbe6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:04.051241+08:00
PR00 (PID:1438): Media Recovery Waiting for T-1.S-75 (in transit) [krsm.c:6185]
2022-05-08T22:33:04.052945+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 75 Reading mem 0
  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_4_k5yt8y5f_.log
2022-05-08T22:33:07.786948+08:00
 rfs (PID:12549): Opened LNO:5 for DBID:3870017436 B-1102494684.T-1.S-76 [krsr.c:18143]
2022-05-08T22:33:07.811804+08:00
ARC0 (PID:1354): Archived Log entry 57 added for B-1102494684.T-1.S-75 ID 0x7f7ae6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:07.926136+08:00
PR00 (PID:1438): Media Recovery Waiting for T-1.S-76 (in transit) [krsm.c:6185]
2022-05-08T22:33:07.927698+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 76 Reading mem 0
  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_5_k5yt8yjw_.log
2022-05-08T22:33:08.525489+08:00
PDBNEW(6):Full restore complete of datafile 24 /u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_undotbs1_k7ho53ny_.dbf.  Elapsed time: 0:00:01
PDBNEW(6):  checkpoint is 4932003
PDBNEW(6):  last deallocation scn is 3928601
PDBNEW(6):Datafile #24 has been copied to the standby.
2022-05-08T22:33:11.424337+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-77 [krsr.c:18143]
2022-05-08T22:33:11.492712+08:00
PR00 (PID:1438): Media Recovery Waiting for T-1.S-77 (in transit) [krsm.c:6185]
2022-05-08T22:33:11.494117+08:00
ARC2 (PID:1362): Archived Log entry 58 added for B-1102494684.T-1.S-76 ID 0x7fbbe6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:11.552303+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 77 Reading mem 0
  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_4_k5yt8y5f_.log
2022-05-08T22:33:12.363978+08:00
PDBNEW(6):Full restore complete of datafile 23 /u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_sysaux_k7ho54o6_.dbf.  Elapsed time: 0:00:04
PDBNEW(6):  checkpoint is 4932003
PDBNEW(6):  last deallocation scn is 3862144
PDBNEW(6):Datafile #23 has been copied to the standby.
2022-05-08T22:33:14.572554+08:00
 rfs (PID:12549): Opened LNO:5 for DBID:3870017436 B-1102494684.T-1.S-78 [krsr.c:18143]
2022-05-08T22:33:14.572781+08:00
Trying to expand controlfile section 11 for Oracle Managed Files
Expanded controlfile section 11 from 56 to 112 records
Requested to grow by 56 records; added 2 blocks of records
2022-05-08T22:33:14.585789+08:00
ARC0 (PID:1354): Archived Log entry 59 added for B-1102494684.T-1.S-77 ID 0x7f7ae6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:14.650210+08:00
PR00 (PID:1438): Media Recovery Waiting for T-1.S-78 (in transit) [krsm.c:6185]
2022-05-08T22:33:14.698805+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 78 Reading mem 0
  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_5_k5yt8yjw_.log
2022-05-08T22:33:15.936076+08:00
PDBNEW(6):Full restore complete of datafile 22 /u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_system_k7ho58jz_.dbf.  Elapsed time: 0:00:03
PDBNEW(6):  checkpoint is 4932003
PDBNEW(6):  last deallocation scn is 3860354
PDBNEW(6):Datafile #22 has been copied to the standby.
2022-05-08T22:33:15.948328+08:00
PDBNEW(6):PDB Side Media Recovery started for pdbid(6)
PDBNEW(6):.... (PID:12667): Managed Recovery starting Real Time Apply [krsm.c:15865]
PDBNEW(6):max_pdb is 6
2022-05-08T22:33:16.031099+08:00
PDBNEW(6):Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_75_k7ho53pg_.arc
2022-05-08T22:33:16.045816+08:00
PDBNEW(6):Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_76_k7ho57fz_.arc
2022-05-08T22:33:16.076227+08:00
PDBNEW(6):Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_77_k7ho5bgp_.arc
PDBNEW(6):.... (PID:12667): Media Recovery Waiting for T-1.S-78 (in transit) [krsm.c:6185]
2022-05-08T22:33:16.106119+08:00
PDBNEW(6):Media Recovery of Online Log [Thread=1, Seq=78]
2022-05-08T22:33:16.106586+08:00
PDBNEW(6):Recovery of Online Redo Log: Thread 1 Group 5 Seq 78 Reading mem 0
PDBNEW(6):  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_5_k5yt8yjw_.log
PDBNEW(6):PSR[6]:influxScn=4932081,nxtCkptScn=4932081,minScn=4932004,krdsini=0,krsmrs=9082,nof=0,kcvrlc=1102494684,kcvrls=2601843
PDBNEW(6):The merge request has been submitted by side recovery for pdbid 6
2022-05-08T22:33:16.114934+08:00
PR00 (PID:1438): Background Media Recovery cancelled with status 16037 [krd.c:27039]
PSR: Background Media Recovery will be reactivated in an attempt to take over PDB side recovery sessions
2022-05-08T22:33:16.119431+08:00
Errors in file /u01/app/oracle/diag/rdbms/db213h1_stdby/DB213H1/trace/DB213H1_pr00_1438.trc:
ORA-16037: user requested cancel of managed recovery operation
PR00 (PID:1438): Managed Recovery not using Real Time Apply [krsm.c:15876]
Recovery interrupted!
Recovered data files to a consistent state at change 4932082
Stopping change tracking
2022-05-08T22:33:16.347544+08:00
Errors in file /u01/app/oracle/diag/rdbms/db213h1_stdby/DB213H1/trace/DB213H1_pr00_1438.trc:
ORA-16037: user requested cancel of managed recovery operation
2022-05-08T22:33:17.205906+08:00
PDBNEW(6):.... (PID:12667): Side Recovery Complete [krds.c:1584]
2022-05-08T22:33:17.250805+08:00
ARC3 (PID:1364): Archived Log entry 60 added for B-1102494684.T-1.S-78 ID 0x7fd0e6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:17.251185+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-79 [krsr.c:18143]
2022-05-08T22:33:20.411643+08:00
ARC1 (PID:1360): Archived Log entry 61 added for B-1102494684.T-1.S-79 ID 0x7fd1e6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:20.411942+08:00
 rfs (PID:12549): Opened LNO:5 for DBID:3870017436 B-1102494684.T-1.S-80 [krsr.c:18143]
2022-05-08T22:33:21.944250+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-81 [krsr.c:18143]
2022-05-08T22:33:21.944465+08:00
ARC2 (PID:1362): Archived Log entry 62 added for B-1102494684.T-1.S-80 ID 0x7fbbe6abae9c LAD:1 [krse.c:4933]

I have extracted below the important entries on the Standby that show the behaviour of PDB Recovery Isolation --- that Oracle at the Standby handles Recovery of the new PDB separately

2022-05-08T22:33:02.900342+08:00
Recovery created pluggable database PDBNEW
PDBNEW(6):Tablespace-SYSTEM during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #22 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_system_k7ho4s6r_.dbf'.
PDBNEW(6):Tablespace-SYSAUX during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #23 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_sysaux_k7ho4s6s_.dbf'.
PDBNEW(6):Tablespace-UNDOTBS1 during PDB create offlined since source is in r/w mode or this is a refresh clone
PDBNEW(6):File #24 added to control file as '/u02/oradata/DB213H1_STDBY/DE81F2476C7F3F80E0538338A8C0063E/datafile/o1_mf_undotbs1_k7ho4s6t_.dbf'.
PDBNEW(6):Tablespace-TEMP during PDB create offlined since source is in r/w mode or this is a refresh clone

PDBNEW(6):PDB Side Media Recovery started for pdbid(6)
PDBNEW(6):.... (PID:12667): Managed Recovery starting Real Time Apply [krsm.c:15865]
PDBNEW(6):max_pdb is 6

PDBNEW(6):Recovery of Online Redo Log: Thread 1 Group 5 Seq 78 Reading mem 0
PDBNEW(6):  Mem# 0: /u02/oradata/DB213H1_STDBY/onlinelog/o1_mf_5_k5yt8yjw_.log
PDBNEW(6):PSR[6]:influxScn=4932081,nxtCkptScn=4932081,minScn=4932004,krdsini=0,krsmrs=9082,nof=0,kcvrlc=1102494684,kcvrls=2601843
PDBNEW(6):The merge request has been submitted by side recovery for pdbid 6
2022-05-08T22:33:16.114934+08:00
PR00 (PID:1438): Background Media Recovery cancelled with status 16037 [krd.c:27039]
PSR: Background Media Recovery will be reactivated in an attempt to take over PDB side recovery sessions
2022-05-08T22:33:16.119431+08:00
Errors in file /u01/app/oracle/diag/rdbms/db213h1_stdby/DB213H1/trace/DB213H1_pr00_1438.trc:
ORA-16037: user requested cancel of managed recovery operation
PR00 (PID:1438): Managed Recovery not using Real Time Apply [krsm.c:15876]
Recovery interrupted!
Recovered data files to a consistent state at change 4932082
Stopping change tracking
2022-05-08T22:33:16.347544+08:00
Errors in file /u01/app/oracle/diag/rdbms/db213h1_stdby/DB213H1/trace/DB213H1_pr00_1438.trc:
ORA-16037: user requested cancel of managed recovery operation
2022-05-08T22:33:17.205906+08:00
PDBNEW(6):.... (PID:12667): Side Recovery Complete [krds.c:1584]

2022-05-08T22:33:17.250805+08:00
ARC3 (PID:1364): Archived Log entry 60 added for B-1102494684.T-1.S-78 ID 0x7fd0e6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:17.251185+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-79 [krsr.c:18143]
2022-05-08T22:33:20.411643+08:00
ARC1 (PID:1360): Archived Log entry 61 added for B-1102494684.T-1.S-79 ID 0x7fd1e6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:20.411942+08:00
 rfs (PID:12549): Opened LNO:5 for DBID:3870017436 B-1102494684.T-1.S-80 [krsr.c:18143]
2022-05-08T22:33:21.944250+08:00
 rfs (PID:12549): Opened LNO:4 for DBID:3870017436 B-1102494684.T-1.S-81 [krsr.c:18143]
2022-05-08T22:33:21.944465+08:00
ARC2 (PID:1362): Archived Log entry 62 added for B-1102494684.T-1.S-80 ID 0x7fbbe6abae9c LAD:1 [krse.c:4933]
2022-05-08T22:33:37.537823+08:00
all data files of pdbid 6 are brought online.
 Started logmerger process
2022-05-08T22:33:37.592170+08:00

IM on ADG: Start of Empty Journal

IM on ADG: End of Empty Journal
PR00 (PID:12697): Managed Recovery starting Real Time Apply [krsm.c:15865]
max_pdb is 6
2022-05-08T22:33:37.736778+08:00
Parallel Media Recovery started with 2 slaves
2022-05-08T22:33:37.858641+08:00
Stopping change tracking
2022-05-08T22:33:37.914220+08:00
PR00 (PID:12697): Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_78_k7ho5f5y_.arc [krd.c:9408]
2022-05-08T22:33:38.024387+08:00
PR00 (PID:12697): Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_79_k7ho5jc9_.arc [krd.c:9408]
2022-05-08T22:33:38.548017+08:00
PR00 (PID:12697): Media Recovery Log /u01/app/oracle/DB213H1_STDBY/archivelog/2022_05_08/o1_mf_1_80_k7ho5kvg_.arc [krd.c:9408]
2022-05-08T22:33:38.764339+08:00
PR00 (PID:12697): Media Recovery Waiting for T-1.S-81 (in transit) [krsm.c:6185]
2022-05-08T22:33:38.764667+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 81 Reading mem 0

First, it identifies that the Source PDB is in Read-Write mode.

Then it begins a "Side Media Recovery" for the new PDB PDBNEW(6).

Later, it temporarily halts recovery of the full Standby CDB to merge the  "Side Recovery".

Finally, it resumes "normal" Recovery of the Standby from ArchiveLog Sequence 78 onwards.