数据恢复：Oracle数据库中实例恢复起点与终点及RBA

2017年12月11日

崔华

2983

在Oracle数据库的恢复中，有几个概念非常重要：On Disk RBA，Low Cache RBA。从哪里开始又到哪里结束？

在这篇文章里，我们证明了On Disk RBA不是Instance Recovery的终点，Instance Recovery的终点就是Current redo log file的最尾端。

DSI403e明确指出了Low CacheRBA和On Disk RBA各自的含义：

Low Cache RBA: The low RBA of the checkpoint queues indicate where recovery can begin. All buffer swith lower RBAs were already written. Note that the buffer, or buffers, at this low RBA may be in the middle of a disk write when this value is constructed.

On Disk RBA: The on disk RBA is the highest RBA that is definitely on disk. Instance recovery must apply redo at least up to here. There are unusual circumstances where the on disk RBA may actually be lower than the low cache RBA. In these circumstances, the dirty buffers could not be written because a log force is needed. If the instance dies without a log force, then the redo at the low cache RBA may not even exist. Process death during redo generation, and buffer invalidation due to offline immediate, may remove the buffer at the on disk RBA from the checkpoint queue.

从中我们可以看出：

1、可能会出现Low Cache RBA的值已被写入control文件，但它所对应的redo record和dirty buffer还没有被写入redo log和数据文件；

2、On Disk RBA只是表示Instance Recovery的时候至少要恢复到On Disk RBA这个点；说白了，它只是真正的current redo log file的最尾端一个前镜像。

3、可能会出现On Disk RBA比Low Cache RBA小的情况，如果Oracle发现存在这种情况，则会强制写redo；

实际上，Instance Recovery的起点是Low Cache RBA和Thread Checkpoint RBA中的最大值，Instance Recovery的终点就是current redo log file的最尾端。

Oracle在做Instance Recovery的时候是受隐含参数_two_pass的控制，其默认为true，这表示要Oracle做Instance Recovery的时候是采用Two Pass Recovery，即要扫描current redo log file两次。

Two Pass Recovery的核心是在做Instance Recovery时要去掉那些已经被写入数据文件的数据块所对应的redo record，Oracle称这些redo record为Block Written Record (BWR)。BWR所对应的op codes可能是23.1（这个我不确定，是猜的），如下是我从redo中dump的结果：

证明过程：我们同时开三个session，先在session 1做一些准备工作：

Session 1：

创建一个自己到自己的db link，这是为了规避Oracle对PL/SQL循环中commit的优化过程，确保后续的PL/SQL循环里每一次commit后redo都能被及时写入redo log：

SQL> create public database link CUIHUA112 connect to SCOTT identified by tiger using ‘cuihua112’;
Database link created

验证一下上述自己到自己的db link是否有效：

SQL> select count(*) from dba_objects;
  COUNT(*)
———-
     71962
SQL> select count(*) from dba_objects@cuihua112;
  COUNT(*)
———-
     71962

创建一个测试表T：

SQL> create table t(id number);
Table created

创建一个用于测试的存储过程，在PL/SQL循环里每隔1秒钟就向表T插入一条数据，每插入一条就commit一次：

SQL> create or replace procedure p_instance_recovery_demo is
  2    i number;
  3  begin
  4    for i in 1..100 loop
  5      insert into t@cuihua112 values (i);
  6      commit;
  7      dbms_lock.sleep(1);
  8    end loop;
  9  end p_instance_recovery_demo;
10  /
Procedure created

准备工作做完了，我开始在session 1中执行上述存储过程：

Session 1：
SQL> exec p_instance_recovery_demo;

……这里正在执行

然后我们到session 2中去查询表T的插入数据的情况，并同时确定T1中插入数据的物理存储位置：

Session 2:

SQL> select t.id,dbms_rowid.rowid_relative_fno(rowid)||’_’||dbms_rowid.rowid_block_number(rowid) location from t;

ID LOCATION

———- ——————————————————————————–

1 4_87284

2 4_87284

3 4_87284

4 4_87284

……省略显示部分内容

27 4_87284

28 4_87284

29 4_87284

30 4_87284

30 rows selected

从上述结果中我们可以看到，现在表T1中已被插入了30条记录，这些记录的物理存储位置都是file 4，block 87274。

在session 3中我执行一次thread checkpoint，同时马上紧跟着执行shutdown abort：

Session 3：

SQL> alter system checkpoint;
系统已更改。
SQL> shutdown abort;
ORACLE 例程已经关闭。

回到session 1，我们发现上述存储过程p_instance_recovery_demo已被Oracle中断：

Session 1：

SQL> exec p_instance_recovery_demo;

begin p_instance_recovery_demo; end;

ORA-03113: 通信通道的文件结尾

进程 ID: 5816

会话 ID: 24 序列号: 3

我们现在新开一个command窗口，先用BBED去看一下现在数据文件上的Thread Checkpoint RBA是多少。这里有一点背景知识需要交待，在Oracle 10g以上的版本里，Checkpoint RBA的位置跟Oracle 9i是不一样的，其起始位置是在数据文件头的offset 500处：

BBED> p kcvfhckp

回到上述command窗口，这里因为是将windows平台上Oracle 9i的BBED用于Oracle 11gR2，所以定位数据块的时候block number要往后错一位：

BBED> set file 4 block 2

FILE# 4

BLOCK# 2

BBED> set offset 500

OFFSET 500

BBED> dump

可以看到现在的Thread Checkpoint RBA是000001c3.0000ff0f.0010。

我们在来看一下表T的数据插入情况：

BBED> set file 4 block 87285

FILE# 4

BLOCK# 87285

BBED> map /v

File: C:\APP\CUIHUA\ORADATA\CUIHUA112\USERS01.DBF (4)

Block: 87285 Dba:0x010154f5

————————————————————

KTB Data Block (Table/Cluster)

struct kcbh, 20 bytes @0

ub1 type_kcbh @0

……省略显示部分内容

ub2 spare3_kcbh @18

struct kdbt[1], 4 bytes @114

b2 kdbtoffs @114

b2 kdbtnrow @116

sb2 kdbr[49] @118

ub1 freespace[7678] @216

ub1 rowdata[294] @7894

ub4 tailchk @8188

很明显，现在表T在磁盘上只有49条记录。

我们来看一下这些记录：

BBED> p *kdbr[0]

rowdata[288]

————

ub1 rowdata[288] @8182 0x2c

BBED> x /rn

rowdata[288] @8182

————

flag@8182: 0x2c (KDRHFL, KDRHFF, KDRHFH)

lock@8183: 0x00

cols@8184: 1

col 0[2] @8185: 1

BBED> p *kdbr[1]

rowdata[282]

————

ub1 rowdata[282] @8176 0x2c

BBED> x /rn

rowdata[282] @8176

————

flag@8176: 0x2c (KDRHFL, KDRHFF, KDRHFH)

lock@8177: 0x00

cols@8178: 1

col 0[2] @8179: 2

BBED> p *kdbr[48]

rowdata[0]

———-

ub1 rowdata[0] @7894 0x2c

BBED> x /rn

rowdata[0] @7894

———-

flag@7894: 0x2c (KDRHFL, KDRHFF, KDRHFH)

lock@7895: 0x01

cols@7896: 1

col 0[2] @7897: 49

从上述内容我们可以看出，表T现在在磁盘上的第1条记录的id列的值为1，第2条记录的id列的值为2，第49条记录的id列的值为49，这和我们预期的一致。

现在我们将上述shutdown abort后的库启动到mount状态，然后对control文件和current redo log file执行dump操作：

E:\>sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on 星期三 8月 1 10:20:58 2012

SQL> conn / as sysdba;

已连接到空闲例程。

SQL> startup mount

ORACLE 例程已经启动。

Total System Global Area 640286720 bytes

Fixed Size 1376492 bytes

Variable Size 234884884 bytes

Database Buffers 398458880 bytes

Redo Buffers 5566464 bytes

数据库装载完毕。

SQL> select group# from v$log where status=’CURRENT’;

GROUP#

———-

SQL> select member from v$logfile where group#=1;

MEMBER

——————————————————————————–

C:\APP\CUIHUA\ORADATA\CUIHUA112\REDO01.LOG

SQL> oradebug setmypid

已处理的语句

SQL> alter session set events ‘immediate trace name controlf level 3’;

会话已更改。

SQL> alter system dump logfile ‘C:\APP\CUIHUA\ORADATA\CUIHUA112\REDO01.LOG’;

系统已更改。

SQL> oradebug tracefile_name

c:\app\cuihua\diag\rdbms\cuihua112\cuihua112\trace\cuihua112_ora_4964.trc

我们从上述trace文件c:\app\cuihua\diag\rdbms\cuihua112\cuihua112\trace\cuihua112_ora_4964.trc中就可以看到现在上述库的控制文件和current redo log的内容。

先来看上述trace文件中包含的对控制文件的dump内容里的Low Cache RBA和On Disk RBA：

现在的Low Cache RBA是0x1c3.ff1a.0，刚才我们已经用BBED看到Thread Checkpoint RBA是000001c3.0000ff0f.0010，很显然现在Low Cache RBA大于Thread Checkpoint RBA，所以Oracle在做Instance Recovery的时候就会以Low Cache RBA为准。

SQL> select to_number(‘1c3′,’XXXXXXXX’) from dual;

TO_NUMBER(‘1C3′,’XXXXXXXX’)

—————————

451

SQL> select to_number(‘ff1a’,’XXXXXXXX’) from dual;

TO_NUMBER(‘FF1A’,’XXXXXXXX’)

—————————-

65306

从上面的结果里我们可以看出，Low Cache RBA是0x1c3.ff1a.0，转换过来就是Low Cache RBA的logfile sequence是451，logfile block number是65306。

另外，我们可以看到现在控制文件里记录的On Disk RBA是0x1c3.ff1d.0，转换过来就是On Disk RBA的logfile sequence是451，logfile block number是65309：

SQL> select to_number(‘1c3′,’XXXXXXXX’) from dual;

TO_NUMBER(‘1C3′,’XXXXXXXX’)

—————————

451

SQL> select to_number(‘ff1d’,’XXXXXXXX’) from dual;

TO_NUMBER(‘FF1D’,’XXXXXXXX’)

—————————-

65309

我们再来看上述trace文件中包含的对currentredo log file的dump内容里的尾端redorecord的情况。首先来看currentredo log file的尾端的插入记录：

REDORECORD – Thread:1 RBA: 0x0001c3.0000ff31.0110 LEN: 0x0140 VLD:0x01

SCN:0x0001.c018412d SUBSCN: 2 08/01/2012 09:56:46

CHANGE #1TYP:0 CLS:25 AFN:3 DBA:0x00c000c0 OBJ:4294967295 SCN:0x0001.c018412d SEQ:1OP:5.2 ENC:0 RBL:0

ktudhredo: slt: 0x0013 sqn: 0x00000000 flg: 0x0002 siz: 80 fbi: 0

uba:0x00c019b8.02d7.16 pxid: 0x0000.000.00000000

CHANGE #2TYP:0 CLS:26 AFN:3 DBA:0x00c019b8 OBJ:4294967295 SCN:0x0001.c018412d SEQ:1OP:5.1 ENC:0 RBL:0

ktudbredo: siz: 80 spc: 5148 flg: 0x1022 seq: 0x02d7 rec: 0x16

xid: 0x0005.013.000009f4

ktuburedo: slt: 19 rci: 0 opc: 11.1 objn: 82084 objd: 82084 tsn: 4

Undotype: Regular undo Undotype: Last buffer split: No

TablespaceUndo: No

0x00000000

KDO undorecord:

KTB Redo

op:0x04 ver: 0x01

compatbit: 4 (post-11) padding: 0

op:L itl: xid: 0x0003.007.0000091e uba: 0x00c000ec.0451.0f

flg:C— lkc: 0 scn:0x0001.c0184129

KDO Opcode: DRP row dependencies Disabled

xtype:XA flags: 0x00000000 bdba: 0x010154f4 hdba: 0x010154f2

itli:2 ispac: 0 maxfr: 4858

tabn: 0slot: 51(0x33)

CHANGE #3TYP:2 CLS:1 AFN:4 DBA:0x010154f4 OBJ:82084 SCN:0x0001.c018412cSEQ:1OP:11.2 ENC:0 RBL:0

KTB Redo

op:0x01 ver: 0x01

compatbit: 4 (post-11) padding: 0

op:F xid: 0x0005.013.000009f4 uba:0x00c019b8.02d7.16

KDO Opcode: IRP row dependencies Disabled

xtype:XA flags: 0x00000000 bdba: 0x010154f4 hdba: 0x010154f2

itli:2 ispac: 0 maxfr: 4858

tabn: 0slot: 51(0x33) size/delt: 6

fb: –H-FL–lb: 0x2 cc: 1

null: –

col 0:[ 2] c1 35

从上述内容我们可以看到，最后一条对object82084的插入记录（这里op codes为11.2，表示是insert操作）的第1列（即表T的id列）的插入值是0xc135，它所对应的RBA是0x0001c3.0000ff31.0110：

对象82084就是表T：

SQL> select owner,object_name fromdba_objects where object_id=82084;

OWNER OBJECT_NAME

————————————————–

SCOTT T

0xc135就是52：

SQL> select utl_raw.cast_to_number(‘c135’)from dual;

UTL_RAW.CAST_TO_NUMBER(‘C135’)

——————————

注意到这里差异就产生了。我们刚才用BBED查看了表T在磁盘上的最后一条记录，其id值是49。但这里对currentredo log file的dump清晰的告诉我们，上述表T的最后一条被成功插入的记录的id值是52。也就是说，id为50、51和52的那三条记录还在buffercache里，还没有被写回到数据文件。

另外我们刚才已经从对控制文件的dump内容看到On Disk RBA的值是0x1c3.ff1d.0，而上述插入id值为52的这条redo record的RBA是0x0001c3.0000ff31.0110，即现在的On DiskRBA小于id值为52的这条redorecord所在的RBA。如果Oracle在做InstanceRecovery的时候只恢复到On DiskRBA，那么就意味着id为52的这条记录就真的丢掉了。

我们接着来看currentredo log file尾端的最后一条redorecord：

从上面的内容我们可以看到，现在currentredo log file尾端的最后一条redorecord对应的RBA是0x0001c3.0000ff34.0010，翻译过来就是currentredo log file尾端的最后一条redorecord对应的logfilesequence是451，logfileblock number是65332：

SQL> select to_number(‘1c3′,’XXXXXXXX’)from dual;

TO_NUMBER(‘1C3′,’XXXXXXXX’)

—————————

451

SQL> select to_number(‘ff34′,’XXXXXXXX’)from dual;

TO_NUMBER(‘FF34′,’XXXXXXXX’)

—————————-

65332

好了，我们现在回到上述command窗口来把上述数据库open。在open完毕后我们马上紧跟着执行对当前控制文件的dump操作：

SQL> alter database open;
数据库已更改。
SQL> alter session set events ‘immediatetrace name controlf level 3’;
会话已更改。

很显然，Oracle在open上述库的过程中做了Instance Recovery，我们现在去看相关的alert log里记录的内容：

从上述alert log我们可以知道，Oracle做InstanceRecovery的起点是logseq 451,block 65306；终点是logseq451, block 65333。

从之前的对控制文件的dump我们可以看到控制文件里记录的Low CacheRBA是0x1c3.ff1a.0，转换过来就是Low CacheRBA的logfile sequence是451，logfile block number是65306。”这和alert log里记录的Instance Recovery的起点一致，即InstanceRecovery的起点就是Low CacheRBA和Thread Checkpoint RBA中的最大值。

另外，控制文件里记录的On DiskRBA是0x1c3.ff1d.0，转换过来就是On DiskRBA的logfile sequence是451，logfile block number是65309。显然这个和alert log里记录的InstanceRecovery的终点不一致，所以On DiskRBA不是InstanceRecovery的终点。

从之前的对currentredo log的dump我们可以看到在shutdownabort时current redo log的最后一条redorecord所对应的RBA是0x0001c3.0000ff34.0010，转换过来就是currentredo log file的最后一条redorecord对应的logfile sequence是451，logfile block number是65332，这个再往后错一位就匹配上了alert log里记录的Instance Recovery的终点。即InstanceRecovery的终点就是currentredo log file的最尾端。

我们来看一下开库后现在表T的数据情况：

SQL> select count(*) from scott.t;

COUNT(*)

———-

SQL> select max(id) from scott.t;

MAX(ID)

———-

显然，最后插入的那条id为52的记录没有丢失。

至此，我们已经完成了整个的证明过程。最后我们来看一下我们开库后马上做的那个对控制文件的dump的内容：

从上述内容我们可以看到，Oracle在Open上述库后马上递增了Low CacheRBA和On Disk RBA。Oracle做完了所有的Instance Recovery工作才用当时的recovery checkpoint去更新控制文件。