In my previous blog post about Datafile Name mapping for a Refreshable Clone PDB, I had presented only a portion of the trace file for the ALTER PLUGGABLE DATABASE RO_PDB REFRESH command.
Here is the full listing of that trace file (I have already explained the AFN mapping of FILE#s)
Trace file /opt/oracle/diag/rdbms/cdb2/CDB2/trace/CDB2_ora_6159.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
Build label: RDBMS_19.12.0.0.0DBRU_LINUX.X64_210715
ORACLE_HOME: /opt/oracle/product/19c/dbhome_1
System name: Linux
Node name: ora19cs2
Release: 4.14.35-1902.10.4.1.el7uek.x86_64
Version: #2 SMP Mon Jan 27 14:13:38 PST 2020
Machine: x86_64
Instance name: CDB2
Redo thread mounted by this instance: 1
Oracle process number: 59
Unix process pid: 6159, image: oracle@ora19cs2
*** 2021-12-04T17:39:25.431585+08:00 (RO_PDB(5))
*** SESSION ID:(377.22911) 2021-12-04T17:39:25.431608+08:00
*** CLIENT ID:() 2021-12-04T17:39:25.431613+08:00
*** SERVICE NAME:(CDB2) 2021-12-04T17:39:25.431617+08:00
*** MODULE NAME:(sqlplus@ora19cs2 (TNS V1-V3)) 2021-12-04T17:39:25.431622+08:00
*** ACTION NAME:() 2021-12-04T17:39:25.431626+08:00
*** CLIENT DRIVER:(SQL*PLUS) 2021-12-04T17:39:25.431630+08:00
*** CONTAINER ID:(5) 2021-12-04T17:39:25.431634+08:00
JIT: pid 6159 requesting stop
*** 2021-12-04T17:39:48.052938+08:00 (RO_PDB(5))
Started Serial Media Recovery
This is Foreign Recovery:- HotClone:1 Pre-Plugin:0 HotClone_for_Refresh:1. The Redo going to be applied in Current PDB(Target) will be from Foreign PDB(Source) and there will be file# conversion. Source AFN is from Foreign DB and Target AFN is on Current(local) DB. Dumping Source PDB:3 to Target PDB:5 AFN mapping.
Source AFN:26 = Target AFN:47
Source AFN:32 = Target AFN:49
Source AFN:12 = Target AFN:46
Source AFN:31 = Target AFN:48
Source AFN:9 = Target AFN:43
Source AFN:11 = Target AFN:45
Source AFN:10 = Target AFN:44
Dumping database incarnation table:
Resetlogs 0 scn and time: 0x0000000000f22944 11/30/2021 22:58:02
Dumping PDB pathvec - index 0
0000 : pdb 5, dbinc 3, pdbinc 0
db rls 0x0000000000f22944 rlc 1090018682
incscn 0x0000000000000000 ts 0
br scn 0x0000000000000000 ts 0
er scn 0x0000000000000000 ts 0
0001 : pdb 5, dbinc 2, pdbinc 0
db rls 0x0000000000e88404 rlc 1084312848
incscn 0x0000000000000000 ts 0
br scn 0x0000000000000000 ts 0
er scn 0x0000000000000000 ts 0
Recovery target incarnation = 3, activation ID = 0
Influx buffer limit = 39160 min(50% x 78320, 100000)
Start recovery at thread 1 ckpt scn 16121330 logseq 37 block 41766
*** 2021-12-04T17:39:48.430170+08:00 (RO_PDB(5))
Media Recovery add redo thread 1
*** 2021-12-04T17:39:48.494955+08:00 (RO_PDB(5))
Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/archivelog/2021_12_04/o1_mf_1_37_jtpcbxyv_.arc
*** 2021-12-04T17:39:48.868915+08:00 (RO_PDB(5))
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
*** 2021-12-04T17:39:51.447683+08:00 (RO_PDB(5))
Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/foreign_archivelog/ORCLPDB1/2021_12_04/o1_mf_1_38_jtpfttmz_.arc
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
*** 2021-12-04T17:40:04.041793+08:00 (RO_PDB(5))
==== Redo read statistics for thread 1 ====
Total physical reads (from disk and memory): 89402Kb
-- Redo read_disk statistics --
Read rate (SYNC): 89402Kb in 15.61s => 5.59 Mb/sec
Total redo bytes: 89402Kb Longest record: 24Kb, moves: 78/213168 moved: 0Mb (0%)
Longest LWN: 2052Kb, reads: 3089
Last redo scn: 0x0000000000f7e789 (16246665)
Change vector header moves = 31243/386616 (8%)
----------------------------------------------
*** 2021-12-04T17:40:04.041915+08:00 (RO_PDB(5))
Media Recovery drop redo thread 1
*** 2021-12-04T17:40:07.389420+08:00 (RO_PDB(5))
KCBR: Number of read descriptors = 1024
KCBR: Media recovery blocks read (ASYNC) = 650
KCBR: Influx buffers flushed = 40 times
KCBR: Reads = 30 reaps (5 null, 8 wait), 2 all
KCBR: Redo cache copies/changes = 15025/15025
*** 2021-12-04T17:40:07.389466+08:00 (RO_PDB(5))
Completed Media Recovery
----- Abridged Call Stack Trace -----
(deleted by me)
The interesting parts are :
"Start recovery at thread 1 ckpt scn 16121330 logseq 37 block 41766"
and
"Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/archivelog/2021_12_04/o1_mf_1_37_jtpcbxyv_.arc"
and
"Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/foreign_archivelog/ORCLPDB1/2021_12_04/o1_mf_1_38_jtpfttmz_.arc"
It identifies the SCN from which it needs to recover transactions from the source CDB (ORCLCDB) and PDB (ORCLPDB1). In a MultiTenant environment, all the PDBs share the same Redo Thread -- so any ArchiveLog may have transactions of multple PDBs.
For the purpose of refresh RO_PDB in CDB2, it identifies the entries from the source CDB ArchiveLogs. For Log Sequence#28, it explicitly identifies the ORCLPDB1 (not the whole CDB) entries as "foreign archivelog". However, this "foreign archivelog" is later automaticallly purged by ORCLCDB as I can see in the ORCLCDB alert log entry
2021-12-04T17:40:07.555215+08:00 Deleted Oracle managed file /opt/oracle/FRA/ORCLCDB/ORCLCDB/foreign_archivelog/ORCLPDB1/2021_12_04/o1_mf_1_38_jtpfttmz_.arc
However, sometimes the Refresh requires to read Redo Entries where an ArchiveLog has not been completely generated. For example, a later Refresh at 22:41 required a partial ArchiveLog for Sequence#41
Start recovery at thread 1 ckpt scn 16246668 logseq 0 block 0 *** 2021-12-04T22:41:32.365818+08:00 (RO_PDB(5)) Media Recovery add redo thread 1 *** 2021-12-04T22:41:32.370629+08:00 (RO_PDB(5)) Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/archivelog/2021_12_04/o1_mf_1_38_jtpzhl2s_.arc *** 2021-12-04T22:41:32.470154+08:00 (RO_PDB(5)) Log read is SYNCHRONOUS though disk_asynch_io is enabled! *** 2021-12-04T22:41:39.259689+08:00 (RO_PDB(5)) Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/archivelog/2021_12_04/o1_mf_1_39_jtpzhxck_.arc Log read is SYNCHRONOUS though disk_asynch_io is enabled! *** 2021-12-04T22:41:42.187854+08:00 (RO_PDB(5)) Media Recovery Log /opt/oracle/FRA/ORCLCDB/ORCLCDB/archivelog/2021_12_04/o1_mf_1_40_jtpzhy18_.arc Log read is SYNCHRONOUS though disk_asynch_io is enabled! *** 2021-12-04T22:41:42.773949+08:00 (RO_PDB(5)) Media Recovery Log /opt/oracle/product/19c/dbhome_1/dbs/archparlog_1_41_f1dfc534_1084312848.arc Log read is SYNCHRONOUS though disk_asynch_io is enabled!
Sequence#41 was still an Online Redo Log at ORCLCDB and had not yet been archived (In fact, the source ORCLPDB FRA was full and ORCLPDB was unable to Archive Log files). So, it seems that for Sequence#41, a Partial Extract was obtained so as to Refresh the Clone PDB.
This doesn't seem to be documented.
No comments:
Post a Comment