ORACLE实例恢复过程详细分析--使用dump、BBED等多种工具结合分析
---友情提示，内容较多，可以从博文左上的+目录选择小节方便阅读。
实验思路： --实验相关TRACE文件：http://download.csdn.net/detail/q947817003/6646723
1.数据库OPEN,，做DML操作不提交，查看检查点。
2.SHUTDOWN ABORT并重启到MOUNT并查询检查点
3.DUMP控制文件查看CHECKPOINT_CHANGE#/RBA
4.DUMP数据文件查看CHECKPOINT_CHANGE#/RBA，与DUMP控制文件对比
5.DUMP REDO日志文件，查看、对比CHECKPOINT_CHANGE#/RBA
6.使用BBED查看数据文件头中的CHECKPOINT_CHANGE#/RBA
7.执行EVENT事件的语句，OPEN数据库，再DUMP控制文件
8.分析OPEN时，通过ALERT日志查看的恢复过程--前滚
9.分析OPEN时，EVENT事件生成的TRACE中查看恢复过程--前滚
10.OPEN数据库时，通过ALERT日志及EVENT事件生成的TRACE中信息解析实例恢复的回滚
11.分析OPEN后的控制文件信息
参考资料及感谢：
guoyJoe http://blog.csdn.net/guoyJoe/article/details/9034425
dbsnake http://www.dbsnake.com/oracle-instance-recovery-end-point.html
实验结论有：
1.控制文件提供恢复所需当前REDO日志的RBA信息，当前REDO日志提供具体的用于恢复的日志内容，最终是将日志内容应用于数据文件。--实例恢复三者不能缺。
2.数据库OPEN时开始实例恢复，先应用日志内容，应用完后从alert日志中来看是已经可以连接至数据库，此时如果UNDO未完成，就有用户发出操作，数据库进程会将回滚后的数据发送至用户--可能会有等待。
3.重要的一点，数据文件、当前REDO日志文件、控制文件正常时实例恢复无需DBA干预，自动完成哈哈。
4.如果当前REDO日志丢了，只能做不完全恢复了。
关于实例恢复起止点：--来自dbsnake
可能会出现On Disk RBA比Low Cache RBA小的情况，如果Oracle发现存在这种情况，则会强制写redo。
On Disk RBA只是表示Instance Recovery的时候至少要恢复到On Disk RBA，它只是真正的current redo log file的最尾端一个前镜像。
实例恢复的起点是：Low Cache RBA和Thread Checkpoint RBA中的较大值；
实例恢复的终点就是current redo log file的最尾端。
Oracle在做实例恢复的时候是受隐含参数_two_pass的控制，其默认为true，这表示要Oracle做实例恢复的时候是采用Two Pass Recovery，即要扫描current redo log file两次。
Two Pass Recovery的核心是在做实例恢复时要去掉那些已经被写入数据文件的数据块所对应的redo record，Oracle称这些redo record为Block Written Record (BWR)。
###################################################################
1.数据库正常运行，多种途径查看数据库中检查点
在普通用户下执行DML操作不提交
BYS@ bys3>set time on
13:18:17 BYS@ bys3>select * from a;
--此表在USER表空间。
B
----------
55
8
0
3
13:18:21 BYS@ bys3>delete a;
4 rows deleted.
13:18:36 BYS@ bys3>select * from a;
no rows selected
再打开一个会话（同一会话切换用户会提交操作），多种途径查看数据库中检查点：详见：http://blog.csdn.net/q947817003/article/details/11590735
SYS@ bys3>set time on
13:18:44 SYS@ bys3>col name for a35
13:18:52 SYS@ bys3>select dbid,name,checkpoint_change# from v$database;
DBID NAME CHECKPOINT_CHANGE#
---------- ----------------------------------- ------------------
3358363031 BYS3 1991217
13:18:59 SYS@ bys3>select file#,name,checkpoint_change#,to_char(checkpoint_time,'yyyy-mm-dd hh24:mi:ss') cptime from v$datafile;
FILE# NAME CHECKPOINT_CHANGE# CPTIME
---------- ----------------------------------- ------------------ -------------------
1 /u01/oradata/bys3/system01.dbf 1991217 2013-12-02 13:17:26
2 /u01/oradata/bys3/sysaux01.dbf 1991217 2013-12-02 13:17:26
3 /u01/oradata/bys3/undotbs01.dbf 1991217 2013-12-02 13:17:26
4 /u01/oradata/bys3/user01.dbf 1991217 2013-12-02 13:17:26
13:19:25 SYS@ bys3>select name,checkpoint_change# from v$datafile_header;
NAME CHECKPOINT_CHANGE#
----------------------------------- ------------------
/u01/oradata/bys3/system01.dbf 1991217
/u01/oradata/bys3/sysaux01.dbf 1991217
/u01/oradata/bys3/undotbs01.dbf 1991217
/u01/oradata/bys3/user01.dbf
1991217
当前当前REDO日志使用情况：
13:19:57 SYS@ bys3>col member for a30
13:20:01 SYS@ bys3>select a.member,a.type,b.thread#,b.sequence#,b.bytes/1024/1024 MB,b.status,b.archived from v$logfile a,v$log b where a.group#=b.group#;
MEMBER TYPE THREAD# SEQUENCE# MB STATUS ARC
------------------------------ ------- ---------- ---------- ---------- ---------------- ---
/u01/oradata/bys3/redo01.log ONLINE 1 106 50 INACTIVE YES
/u01/oradata/bys3/redo02.log ONLINE 1 107 50 CURRENT NO
/u01/oradata/bys3/redo03.log ONLINE 1 105 50 INACTIVE YES
###################################################################
2.模拟断电--shutdown abort，并重启到MOUNT 查询检查点
13:20:02 SYS@ bys3>shutdown abort; ----13:22:11执行完此命令
ORACLE instance shut down.
13:22:11 SYS@ bys3>
alert日志： --推荐个小方法：把alert日志做一个软链接到ORACLE用户家目录，查看方便。
[oracle@bys3 ~]$ cat alert_bys3.log
Mon Dec 02 13:22:09 2013
Shutting down instance (abort)
License high water mark = 4
USER (ospid: 846): terminating the instance
Instance terminated by USER, pid = 846
Mon Dec 02 13:22:11 2013
Instance shutdown complete
######################################
重启数据库到MOUNT，从数据库中查看数据库中检查点、控制文件及数据文件头检查点，一致则无需介质恢复
数据库MOUNT状态下直接在数据库中使用SQL语句查询：
SYS@ bys3>select status from v$instance;
STATUS
------------
MOUNTED
SYS@ bys3>select dbid,name,checkpoint_change# from v$database; --数据库全局-检查点 SCN，在控制文件中
DBID NAME CHECKPOINT_CHANGE#
---------- --------- ------------------
3358363031 BYS3 1991217
SYS@ bys3>select file#,name,checkpoint_change#,to_char(checkpoint_time,'yyyy-mm-dd hh24:mi:ss') cptime from v$datafile; --checkpoint scn,表示该数据文件最近一次执行检查点操作时的SCN，在控制文件中。
FILE# NAME CHECKPOINT_CHANGE# CPTIME
---------- ----------------------------------- ------------------ -------------------
1 /u01/oradata/bys3/system01.dbf 1991217 2013-12-02 13:17:26
2 /u01/oradata/bys3/sysaux01.dbf 1991217 2013-12-02 13:17:26
3 /u01/oradata/bys3/undotbs01.dbf 1991217 2013-12-02 13:17:26
4 /u01/oradata/bys3/user01.dbf 1991217 2013-12-02 13:17:26
SYS@ bys3>select name,checkpoint_change# from v$datafile_header; --CHECKPOINT_CHANGE#表示该数据文件最近一次执行检查点操作时的SCN，在数据文件头
NAME CHECKPOINT_CHANGE#
----------------------------------- ------------------
/u01/oradata/bys3/system01.dbf 1991217
/u01/oradata/bys3/sysaux01.dbf 1991217
/u01/oradata/bys3/undotbs01.dbf 1991217
/u01/oradata/bys3/user01.dbf 1991217
###################################################################
3.DUMP控制文件查看CHECKPOINT_CHANGE#/RBA
更详细DUMP控制文件方式见：http://blog.csdn.net/q947817003/article/details/16370273
SYS@ bys3>alter session set events 'immediate trace name controlf level 12';
Session altered.
SYS@ bys3>select value from v$diag_info where name like 'Default%';
VALUE
------------------------------------------------------------------------------
/u01/diag/rdbms/bys3/bys3/trace/bys3_ora_980.trc
查看TRACE文件： --截取部分内容
***************************************************************************
DATABASE ENTRY
***************************************************************************
(size = 316, compat size = 316, section max = 1, section in-use = 1,
last-recid= 0, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 1, numrecs = 1)
11/14/2013 14:23:19
DB Name "BYS3"
Database flags = 0x00404001 0x00001200
Controlfile Creation Timestamp 11/14/2013 14:23:21
Incmplt recovery scn: 0x0000.00000000
Resetlogs scn: 0x0000.00000001 Resetlogs Timestamp 11/14/2013 14:23:19
Prior resetlogs scn: 0x0000.00000000 Prior resetlogs Timestamp 01/01/1988 00:00:00
Redo Version: compatible=0xb200000
#Data files = 4, #Online files = 4
Database checkpoint: Thread=1 scn: 0x0000.001e6231
Threads: #Enabled=1, #Open=1, Head=1, Tail=1
###############
可以看到检查点的信息：Database checkpoint: Thread=1 scn: 0x0000.001e6231
换算为十进制的SCN为：
---与上一步查询对应
SYS@ bys3>select to_number('1e6231','xxxxxxxxx') from dual;
TO_NUMBER('1C8E12','XXXXXXXXX')
-------------------------------
1991217
###############
***************************************************************************
CHECKPOINT PROGRESS RECORDS
***************************************************************************
(size = 8180, compat size = 8180, section max = 4, section in-use = 0,
last-recid= 0, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 2, numrecs = 4)
THREAD #1 - status:0x2 flags:0x0 dirty:104
low cache rba:(0x6b.3.0) on disk rba:(0x6b.197.0) ---数据文件检查点 Scn以及stop scn值据说来自于当前REDO日志
on disk scn: 0x0000.001e638d 12/02/2013 13:21:37
resetlogs scn: 0x0000.00000001 11/14/2013 14:23:19
heartbeat: 833133356 mount id: 3360007946
################
在检查点进程记录部分，记录了Dirty Buffer的数量是104.
包含Low Cache RBA和On Disk RBA的信息，
low cache rba:(0x6b.3.0) on disk rba:(0x6b.197.0)
-- low cache rba:(0x6b.3.0): 实例恢复的起点：107号日志，第3个块，第0个字节
--on disk rba:(0x6b.197.0)： 实例恢复的终点：107号日志，第407个块，第0个字节 --最前面结论是实例恢复终点实际为current redo log file的最尾端，但是在控制文件、日志中记录的是这个
on disk rba
on disk scn: 0x0000.001e638d 12/02/2013 13:21:37
数据库恢复的检查点终点是SCN--0x0000.001e638d，十进制是：1991565。
On-Disk RBA的SCN是1991565，这是实例恢复的终点。
数据库的恢复SCN范围也就由此确定，即SCN范围：最后检查点：1991217--On-Disk RBA，用SCN表示即：1991217 ===>>>1991565
***************************************************************************
DATA FILE RECORDS
***************************************************************************
(size = 520, compat size = 520, section max = 100, section in-use = 4,
last-recid= 7, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 7, numrecs = 100)
DATA FILE #1: DATA FILE #2: DATA FILE #3: 和DATA FILE #3差不多，并且在本实验中不涉及，精简篇幅就省略了。
DATA FILE #4:
name #8: /u01/oradata/bys3/user01.dbf
creation size=6400 block size=8192 status=0xe head=8 tail=8 dup=1
tablespace 4, index=5 krfil=4 prev_file=0
unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
Checkpoint cnt:167 scn: 0x0000.001e6231 12/02/2013 13:17:26 ---cnt:167是检查点计算，来自数据文件。
Stop scn: 0xffff.ffffffff 12/02/2013 13:16:13 --STOP SCN是FFFF说明未正常关闭数据库，所以需要实例恢复
Creation Checkpointed at scn: 0x0000.000034f9 11/14/2013 14:26:26
thread:1 rba:(0x1.ce8a.10)
enabled threads: 01000000 00000000 00000000 00000000 00000000 00000000
Offline scn: 0x0000.00000000 prev_range: 0
Online Checkpointed at scn: 0x0000.00000000
thread:0 rba:(0x0.0.0)
enabled threads: 00000000 00000000 00000000 00000000 00000000 00000000
Hot Backup end marker scn: 0x0000.00000000
aux_file is NOT DEFINED
Plugged readony: NO
Plugin scnscn: 0x0000.00000000
Plugin resetlogs scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
Foreign creation scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
Foreign checkpoint scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
Online move state: 0
########################
这里在第1步做DML操作时，所在的是USER表空间。
DATA FILE #4: 中的检查点信息如下：
Checkpoint cnt:167 scn: 0x0000.001e6231 12/02/2013 13:17:26
--控制文件中保存的数据文件检查点SCN＝1e6231 转成10进制为1991217，与前文吻合
Stop scn: 0xffff.ffffffff 12/11/2012 22:53:05
--结束的SCN填无穷大，说明是异常关机的，重启数据库必须做实例恢复
###################################################################
4.DUMP数据文件查看CHECKPOINT_CHANGE#/RBA，与DUMP控制文件对比
更详细DUMP数据文件方式见：http://blog.csdn.net/q947817003/article/details/16369041
SYS@ bys3>alter system set events 'immediate trace name file_hdrs level 3'; --最好和上一步DUMP控制文件在不同的会话
System altered.
SYS@ bys3>select value from v$diag_info where name like 'Default%';
VALUE
----------------------------------------------------------------------
/u01/diag/rdbms/bys3/bys3/trace/bys3_ora_1010.trc
查看TRACE文件： --截取部分内容--
Tablespace #4 - USERS rel_fn:4
Creation at scn: 0x0000.000034f9 11/14/2013 14:26:26
Backup taken at scn: 0x0000.00000000 01/01/1988 00:00:00 thread:0
reset logs count:0x318f5cd7 scn: 0x0000.00000001
prev reset logs count:0x0 scn: 0x0000.00000000
recovered at 12/02/2013 13:17:26
status:0x4 root dba:0x00000000 chkpt cnt: 168 ctl cnt:167
begin-hot-backup file size: 0
Checkpointed at scn: 0x0000.001e6231 12/02/2013 13:17:26 -------数据文件中检查点计数cnt:168比控制文件中Checkpoint cnt:167 多1，检查点 scn: 0x0000.001e6231与前文吻合
thread:1 rba:(0x6b.2.10) --------REDO日志的地址0x6b.2.10--－> 107号日志，第2号块，第16个字节
enabled threads: 01000000 00000000 00000000 00000000 00000000 00000000
Backup Checkpointed at scn: 0x0000.00000000
thread:0 rba:(0x0.0.0)
enabled threads: 00000000 00000000 00000000 00000000 00000000 00000000
External cache id: 0x0 0x0 0x0 0x0
Absolute fuzzy scn: 0x0000.00000000
Recovery fuzzy scn: 0x0000.00000000 01/01/1988 00:00:00
Terminal Recovery Stamp 01/01/1988 00:00:00
Platform Information: Creation Platform ID: 10
Current Platform ID: 10 Last Platform ID: 10
DUMP OF TEMP FILES: 1 files in database
第3步中：《《注意：
从控制文件中得到重做日志恢复起始地址如下：
low cache rba:(0x6b.3.0) on disk rba:(0x6b.197.0)
-- low cache rba:(0x6b.3.0):
实例恢复的起点：107号日志，第3个块，第0个字节
--on disk rba:(0x6b.197.0)：
实例恢复的终点：107号日志，第407个块，第0个字节 --具体是不是终点，最后讨论
on disk scn: 0x0000.001e638d 12/02/2013 13:21:37
数据库恢复的检查点终点是SCN--0x0000.001e638d，十进制是：1991565。
On-Disk RBA的SCN是1991565，这是实例恢复的终点。
数据库的恢复SCN范围也就由此确定，即SCN范围：最后检查点：1991217--On-Disk RBA，用SCN表示即：1991217 ===>>>1991565》》
--说明：
实例恢复的起点是Low Cache RBA和Thread Checkpoint RBA中的最大值，实例恢复的终点就是current redo log file的最尾端而不是On-Disk RBA。
这样，本实验中实例恢复的起始的重做日志是以控制文件中的low cache rba:(0x6b.3.0)开始恢复，而不是从文件头的thread:1 rba:(0x6b.2.10)
########################################################################
5.DUMP REDO日志文件 --在第一步已经确定了当前日志是redo02.log
更详细方法，见：http://blog.csdn.net/q947817003/article/details/16370203
SYS@ bys3>alter system dump logfile '/u01/oradata/bys3/redo02.log';
System altered.
SYS@ bys3>select value from v$diag_info where name like 'Default%';
VALUE
------------------------------------------------------------------
/u01/diag/rdbms/bys3/bys3/trace/bys3_ora_1906.trc
REDO日志DUMP最后一个REDO RECORD 的一部分CHANGE #1： --不知道如何解读，留白吧？？？
REDO RECORD - Thread:1 RBA: 0x00006b.00000194.0084 LEN: 0x0418 VLD: 0x09
SCN: 0x0000.001e638c SUBSCN: 1 12/02/2013 13:21:37
CHANGE #1 TYP:2 CLS:1 AFN:1 DBA:0x004007e1 OBJ:288 SCN:0x0000.001e6386 SEQ:2 OP:11.5 ENC:0 RBL:0
KTB Redo
op: 0x11 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: F xid: 0x0009.017.00000642 uba: 0x00c00cac.00f9.28
Block cleanout record, scn: 0x0000.001e638b ver: 0x01 opt: 0x02, entries follow...
itli: 2 flg: 2 scn: 0x0000.001e6386
KDO Op code: URP row dependencies Disabled
xtype: XA flags: 0x00000000 bdba: 0x004007e1 hdba: 0x004007e0
itli: 1 ispac: 0 maxfr: 4863
tabn: 0 slot: 1(0x1) flag: 0x2c lock: 1 ckix: 182
ncol: 19 nnew: 6 size: -7
col 4: [ 7] 78 71 0c 02 0e 16 26
col 5: *NULL*
col 6: [ 7] 78 71 0c 02 0e 17 26
col 7: [21]
c0 06 60 3d 13 34 56 13 34 56 13 34 56 13 34 56 13 34 56 1e 0b
col 9: [ 1] 80
col 10: [ 1] 80
###################################################################
6：使用BBED查看数据文件头CHECKPOINT_CHANGE#及rba
[oracle@bys3 ~]$ cat par.bbd
blocksize=8192
listfile=bbedfile.txt
mode=edit
[oracle@bys3 ~]$ cat bbedfile.txt
1 /u01/oradata/bys3/system01.dbf 524288000
2 /u01/oradata/bys3/sysaux01.dbf 340787200
3 /u01/oradata/bys3/undotbs01.dbf 209715200
4 /u01/oradata/bys3/user01.dbf 52428800
[oracle@bys3 ~]$ bbed parfile=par.bbd
Password:
BBED: Release 2.0.0.0.0 - Limited Production on Sun Dec 1 22:29:18 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
************ !!! For Oracle Internal Use only !!! ***************
BBED> set file 4 block 1
FILE# 4
BLOCK# 1
BBED> map /v
File: /u01/oradata/bys3/user01.dbf (4)
Block: 1 Dba:0x01000001
------------------------------------------------------------
Data File Header
struct kcvfh, 860 bytes @0
struct kcvfhbfh, 20 bytes @0
struct kcvfhhdr, 76 bytes @20
ub4 kcvfhrdb @96
struct kcvfhcrs, 8 bytes @100
ub4 kcvfhcrt @108
ub4 kcvfhrlc @112
struct kcvfhrls, 8 bytes @116
ub4 kcvfhbti @124
struct kcvfhbsc, 8 bytes @128
ub2 kcvfhbth @136
ub2 kcvfhsta @138
struct kcvfhckp, 36 bytes @484
ub4 kcvfhcpc @140
ub4 kcvfhrts @144
ub4 kcvfhccc @148
struct kcvfhbcp, 36 bytes @152
ub4 kcvfhbhz @312
struct kcvfhxcd, 16 bytes @316
sword kcvfhtsn @332
ub2 kcvfhtln @336
text kcvfhtnm[30] @338
ub4 kcvfhrfn @368
struct kcvfhrfs, 8 bytes @372
ub4 kcvfhrft @380
struct kcvfhafs, 8 bytes @384
ub4 kcvfhbbc @392
ub4 kcvfhncb @396
ub4 kcvfhmcb @400
ub4 kcvfhlcb @404
ub4 kcvfhbcs @408
ub2 kcvfhofb @412
ub2 kcvfhnfb @414
ub4 kcvfhprc @416
struct kcvfhprs, 8 bytes @420
struct kcvfhprfs, 8 bytes @428
ub4 kcvfhtrt @444
ub4 tailchk @8188
BBED> print kcvfhckp
struct kcvfhckp, 36 bytes @484
struct kcvcpscn, 8 bytes @484
ub4 kscnbas @484 0x001e6231
ub2 kscnwrp @488 0x0000
ub4 kcvcptim @492 0x31a859e6
ub2 kcvcpthr @496 0x0001
union u, 12 bytes @500
struct kcvcprba, 12 bytes @500
ub4 kcrbaseq @500 0x0000006b
ub4 kcrbabno @504 0x00000002
ub2 kcrbabof @508 0x0010
ub1 kcvcpetb[0] @512 0x02
ub1 kcvcpetb[1] @513 0x00
ub1 kcvcpetb[2] @514 0x00
ub1 kcvcpetb[3] @515 0x00
ub1 kcvcpetb[4] @516 0x00
ub1 kcvcpetb[5] @517 0x00
ub1 kcvcpetb[6] @518 0x00
ub1 kcvcpetb[7] @519 0x00
BBED> set offset 500
OFFSET 500
BBED> dump /v ---@500开始，4字节表示日志序号，4字节表示块号，2字节表示日志块中第几个字节，表示的是数据文件头的RBA信息
从数据块中计算出的RBA信息与print kcvfhckp中的一致，就不重复算了。
关于日志块大小，详见：http://blog.csdn.net/q947817003/article/details/11350359
File: /u01/oradata/bys3/user01.dbf (4)
Block: 1 Offsets: 500 to 1011 Dba:0x01000001
-------------------------------------------------------
6b000000 02000000 10000400 02000000 l k...............
00000000 00000000 00000000 00000000 l ................
00000000 00000000 00000000 00000000 l ................
省略。。。。
<16 bytes per line>
这里CHKPOINT_SCN信息是：
struct kcvcpscn, 8 bytes @484
ub4 kscnbas @484 0x001e6231
ub2 kscnwrp @488 0x0000
这三行就是检查点的SCN信息，kscnbas--0x001c8e12，kscnwrp--0x0000ub4 --实验有效的4个byte： 0x0000
scn计算方法：SCN=(SCN_WRP * 4294967296) + SCN_BAS --SCN的详细介绍及计算：http://blog.csdn.net/q947817003/article/details/11590983
所以此处的SCN就是：0x0000.001e6231；10进制SCN号为：1991217
RBA信息是：
struct kcvcprba, 12 bytes @500
ub4 kcrbaseq @500 0x0000006b --序号，
ub4 kcrbabno @504 0x00000002 --块号
ub2 kcrbabof @508 0x0010 --字节号
换算为十进制表示为：107号日志，2号块，16字节
与上一步DUMP数据文件信息得出的一致：
thread:1 rba:(0x6b.2.10)
--重做日志的地址0x6b.2.10--－> 107号日志，第2号块，第16个字节
###################################################################
7.执行EVENT事件的语句，OPEN数据库后立刻DUMP控制文件
注意事项：要把EVENT事件的语句执行上，不然实验所需数据不连贯哈哈
关于下面用到的10013/10015事件，分别是在Startup时跟踪事务恢复，在事务恢复后做Dump回退段头信息。
EVENT事件详见http://blog.csdn.net/q947817003/article/details/16359765
说明：--在这里用这两个语句不知道到底能不能DUMP出详细的REDO应用及回滚信息，从生成的TRACE文件来看有这方面信息，好像不太详细。。。
SYS@ bys3>alter session set events '10013 trace name context forever,level 1';
Session altered.
SYS@ bys3>alter session set events '10015 trace name context forever,level 1';
Session altered.
SYS@ bys3>alter database open;
Database altered.
SYS@ bys3>select value from v$diag_info where name like 'Default%';
VALUE
----------------------------------------------------------------------
/u01/diag/rdbms/bys3/bys3/trace/bys3_ora_1955.trc
另开一会话在OPEN数据库后立刻执行：
SYS@ bys3>alter session set events 'immediate trace name controlf level 12';
Session altered.
SYS@ bys3>select value from v$diag_info where name like 'Default%';
VALUE
------------------------------------------------------------------------------
/u01/diag/rdbms/bys3/bys3/trace/bys3_ora_2108.trc
##################################################################
8.分析OPEN时，通过ALERT日志查看的恢复过程--前滚
[oracle@bys3 ~]$ cat alert_bys3.log
Mon Dec 02 20:35:20 2013
alter database open
Beginning crash recovery of 1 threads --开始实例恢复
Started redo scan --开始扫描REDO日志
Completed redo scan --完成扫描REDO日志
read 202 KB redo, 104 data blocks need recovery --需要恢复的数据块104块，REDO日志202KB，按low cache rba--on disk rba来算是407-3=404个日志块，一个日志块大小是512字节，正好202KB。
Started redo application at
Thread 1: logseq 107, block 3 --这里可以看到，是从107号日志第3块开始应用REDO-与第3步中low cache rba:(0x6b.3.0)吻合
Recovery of Online Redo Log: Thread 1 Group 2 Seq 107 Reading mem 0
Mem# 0: /u01/oradata/bys3/redo02.log --所使用REDO日志文件，与第一步查询吻合。
Completed redo application of 0.16MB
Completed crash recovery at
Thread 1: logseq 107, block 407, scn 2011565 --完成实例恢复的位置，与第3步中on disk rba:(0x6b.197.0)吻合
104 data blocks read, 104 data blocks written, 202 redo k-bytes read --实例恢复涉及信息统计
Mon Dec 02 20:35:20 2013
LGWR: STARTING ARCH PROCESSES ----可以看到 实例恢复完成后，ARCH进程启动
Mon Dec 02 20:35:21 2013
ARC0 started with pid=19, OS id=2112
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Thread 1 advanced to log sequence 108 (thread open)
Thread 1 opened at log sequence 108
Current log# 3 seq# 108 mem# 0: /u01/oradata/bys3/redo03.log
Successful open of redo thread 1 ----可以看到 实例恢复完成后，REDO日志启动
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Mon Dec 02 20:35:22 2013
SMON: enabling cache recovery
Mon Dec 02 20:35:22 2013
ARC1 started with pid=20, OS id=2116
Mon Dec 02 20:35:22 2013
ARC2 started with pid=21, OS id=2122
ARC1: Archival started
ARC2: Archival started
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
ARC2: Becoming the heartbeat ARCH
Mon Dec 02 20:35:23 2013
ARC3 started with pid=22, OS id=2126
还有段ALERT日志涉及回滚放在下一小节
################################################################
9.分析OPEN时，EVENT事件生成的TRACE中查看恢复过程--前滚
TRACE文件内容：
Thread 1 checkpoint: logseq 107, block 2, scn 1991217
cache-low rba: logseq 107, block 3 --这一段信息与MOUNT时DUMP控制文件的一样
on-disk rba: logseq 107, block 407, scn 1991565
start recovery at logseq 107, block 3, scn 0 --实例恢复起点： MOUNT时DUMP控制文件的low cache rba:(0x6b.3.0)
*** 2013-12-02 20:35:20.739
Started writing zeroblks thread 1 seq 107 blocks 407-414
*** 2013-12-02 20:35:20.745
Completed writing zeroblks thread 1 seq 107
==== Redo read statistics for thread 1 ====
Total physical reads (from disk and memory): 4096Kb
-- Redo read_disk statistics --这个应该是实例恢复期间REDO读写统计
Read rate (ASYNC): 202Kb in 0.22s => 0.90 Mb/sec --REDO的速度-202KB与ALERT日志中对应
Longest record: 17Kb, moves: 0/287 (0%)
Longest LWN: 18Kb, moves: 0/99 (0%), moved: 0Mb
Last redo scn: 0x0000.001e638c (1991564) --最后一个REDO的SCN：与On-Disk RBA的SCN是1991565差1
----------------------------------------------
----- Recovery Hash Table Statistics ---------
Hash table buckets = 262144
Longest hash chain = 1
Average hash chain = 104/104 = 1.0
Max compares per lookup = 1
Avg compares per lookup = 1120/1224 = 0.9
----------------------------------------------
*** 2013-12-02 20:35:20.749
KCRA: start recovery claims for 104 data blocks
*** 2013-12-02 20:35:20.781
KCRA: blocks processed = 104/104, claimed = 104, eliminated = 0
*** 2013-12-02 20:35:20.783
Recovery of Online Redo Log: Thread 1 Group 2 Seq 107 Reading mem 0
*** 2013-12-02 20:35:20.815
Completed redo application of 0.16MB --与ALERT中对照
*** 2013-12-02 20:35:20.944
Completed recovery checkpoint --可以看到 实例恢复完后做了检查点
----- Recovery Hash Table Statistics ---------
Hash table buckets = 262144
Longest hash chain = 1
Average hash chain = 104/104 = 1.0
Max compares per lookup = 1
Avg compares per lookup = 1224/1224 = 1.0
----------------------------------------------
Recovery sets nab of thread 1 seq 107 to 407 with 8 zeroblks
##################################################################
10.OPEN数据库时，通过ALERT日志及EVENT事件生成的TRACE中信息解析实例恢复的回滚
能力有限，解析不了，留着以后解决吧。
ALERT日志中回滚信息：
[1955] Successfully onlined Undo Tablespace 2. --
Undo initialization finished serial:0 start:985058364 end:985058674 diff:310 (3 seconds) --从这句看应该是有回滚操作，能力有限，没更好解释。。。
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is AL32UTF8
Archived Log entry 77 added for thread 1 sequence 107 ID 0xc82cb897 dest 1:
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Starting background process QMNC
Mon Dec 02 20:35:24 2013
QMNC started with pid=23, OS id=2130
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
Completed: alter database open
#############################
EVENT事件生成的TRACE中信息
*** 2013-12-02 20:35:22.989
Acq rollback segment SYSTEM
Rec rollback segment _SYSSMU1_3056155133$
Recovering transaction (1, 21) --看这里好像是SYSTEM回滚段做的事务恢复
Marking transaction (1, 21) dead
Rec rollback segment _SYSSMU2_3692097322$
Rec rollback segment _SYSSMU3_3366438251$
Rec rollback segment _SYSSMU4_3660460897$
Rec rollback segment _SYSSMU5_1917899003$
Rec rollback segment _SYSSMU6_3107841501$
Rec rollback segment _SYSSMU7_1420906157$
Rec rollback segment _SYSSMU8_2178365988$
Rec rollback segment _SYSSMU9_1689884801$
Rec rollback segment _SYSSMU10_3239467560$
*** 2013-12-02 20:35:23.225
Recovering transaction (1, 21) ----这个好像是回滚的第一步中未提交的事务，不知道具体如何查询验证
Marking transaction (1, 21) dead
Acq rollback segment _SYSSMU1_3056155133$
Acq rollback segment _SYSSMU2_3692097322$
Acq rollback segment _SYSSMU3_3366438251$
Acq rollback segment _SYSSMU4_3660460897$
Acq rollback segment _SYSSMU5_1917899003$
Acq rollback segment _SYSSMU6_3107841501$
Acq rollback segment _SYSSMU7_1420906157$
Acq rollback segment _SYSSMU8_2178365988$
Acq rollback segment _SYSSMU9_1689884801$
Acq rollback segment _SYSSMU10_3239467560$
kwqmnich: current time:: 12: 35: 23: 0
kwqmnich: instance no 0 repartition flag 1
kwqmnich: initialized job cache structure
*** 2013-12-02 20:35:24.574
ktsmgtur(): TUR was not tuned for 25928 secs
ktsmg_advance_slot(): MMNL advances slot after 25928 seconds
################################################################################
11.分析OPEN后的控制文件信息--能力有限分析较少
TRACE文件内容
DATABASE ENTRY
***************************************************************************
(size = 316, compat size = 316, section max = 1, section in-use = 1,
last-recid= 0, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 1, numrecs = 1)
11/14/2013 14:23:19
DB Name "BYS3"
Database flags = 0x00404001 0x00001200
Controlfile Creation Timestamp 11/14/2013 14:23:21
Incmplt recovery scn: 0x0000.00000000
Resetlogs scn: 0x0000.00000001 Resetlogs Timestamp 11/14/2013 14:23:19
Prior resetlogs scn: 0x0000.00000000 Prior resetlogs Timestamp 01/01/1988 00:00:00
Redo Version: compatible=0xb200000
#Data files = 4, #Online files = 4
Database checkpoint: Thread=1 scn: 0x0000.001eb1b0 --检查点已经更新
Threads: #Enabled=1, #Open=1, Head=1, Tail=1
enabled threads: 01000000 00000000 00000000 00000000 00000000 00000000
Max log members = 5, Max data members = 1
Arch list: Head=3, Tail=3, Force scn: 0x0000.001b6c94scn: 0x0000.00000000
Activation ID: 3358374039
SCN compatibility 1
Auto-rollover enabled
Controlfile Checkpointed at scn: 0x0000.001eb212 12/02/2013 20:35:25
thread:0 rba:(0x0.0.0)
enabled threads: 00000000 00000000 00000000 00000000 00000000 00000000
***************************************************************************
CHECKPOINT PROGRESS RECORDS
***************************************************************************
(size = 8180, compat size = 8180, section max = 4, section in-use = 0,
last-recid= 0, old-recno = 0, last-recno = 0)
(extent = 1, blkno = 2, numrecs = 4)
THREAD #1 - status:0x2 flags:0x0 dirty:43
low cache rba:(0x6c.3.0) on disk rba:(0x6c.76.0) --on disk rba已经递增
on disk scn: 0x0000.001eb212 12/02/2013 20:35:24 --on disk scn已经递增
resetlogs scn: 0x0000.00000001 11/14/2013 14:23:19
heartbeat: 833141767 mount id: 3360007946
posted on 2013-12-03 10:51 love so much 阅读(844) 评论(0) 编辑 收藏 举报
