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)
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.