用event 10013验证实例恢复的终点？
本站文章除注明转载外，均为本站原创： 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
本文链接地址: 用event 10013验证实例恢复的终点？
这个测试源于微博上一个哥们的一个问题，如下图：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 |
SQL> show user USER is "ROGER" SQL> create table tab_recover(object_id) 2 as select object_id from sys.dba_objects where rownum < 101; Table created. SQL> select * from v$log; GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- --------- 1 1 34 52428800 1 YES INACTIVE 4469425 01-AUG-12 2 1 35 52428800 1 YES INACTIVE 4489487 01-AUG-12 3 1 36 52428800 1 NO CURRENT 4489640 01-AUG-12 SQL> select * from v$logfile; GROUP# STATUS TYPE MEMBER IS_ ---------- ------- ------- ------------------------------------------------------------ --- 3 ONLINE /home/ora10g/oradata/roger/redo03.log NO 2 ONLINE /home/ora10g/oradata/roger/redo02.log NO 1 ONLINE /home/ora10g/oradata/roger/redo01.log NO SQL> select dbms_rowid.rowid_relative_fno(rowid) file#, 2 dbms_rowid.rowid_block_number(rowid) blk# 3 from tab_recover; FILE# BLK# ---------- ---------- 4 7500 4 7500 4 7500 4 7500 4 7500 4 7500 4 7500 4 7500 4 7500 .............. 4 7500 100 rows selected. SQL> SQL> alter system switch logfile; System altered. SQL> select * from v$log; GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- --------- 1 1 37 52428800 1 NO CURRENT 4489744 01-AUG-12 2 1 35 52428800 1 YES INACTIVE 4489487 01-AUG-12 3 1 36 52428800 1 YES ACTIVE 4489640 01-AUG-12 SQL> select * from v$logfile; GROUP# STATUS TYPE MEMBER IS_ ---------- ------- ------- ------------------------------------------------------------ --- 3 ONLINE /home/ora10g/oradata/roger/redo03.log NO 2 ONLINE /home/ora10g/oradata/roger/redo02.log NO 1 ONLINE /home/ora10g/oradata/roger/redo01.log NO SQL> delete from tab_recover where rownum <2; 1 row deleted. SQL> commit; Commit complete. SQL> delete from tab_recover where rownum <2; 1 row deleted. SQL> commit; Commit complete. SQL> delete from tab_recover where rownum <2; 1 row deleted. SQL> commit; Commit complete. SQL> conn /as sysdba Connected. SQL> shutdown abort; ORACLE instance shut down. SQL> |
这里一个，删除了3条数据。上面这里做delete操作之前之所以切换redo 是因为dump信息太多了，查看不方便，
这里我切换以后，删除几条记录，就dump，那么logfile的dump内容就很少了，非常的直观。
—–log file dump
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 |
SQL> startup mount ORACLE instance started. Total System Global Area 167772160 bytes Fixed Size 1272600 bytes Variable Size 142607592 bytes Database Buffers 20971520 bytes Redo Buffers 2920448 bytes Database mounted. SQL> alter system dump logfile '/home/ora10g/oradata/roger/redo01.log'; System altered. SQL> DUMP OF REDO FROM FILE '/home/ora10g/oradata/roger/redo01.log' Opcodes *.* RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff Times: creation thru eternity FILE HEADER: Compatibility Vsn = 169870592=0xa200500 Db ID=2466925865=0x930a4d29, Db Name='ROGER' Activation ID=2492566025=0x94918a09 Control Seq=5659=0x161b, File size=102400=0x19000 File Number=1, Blksiz=512, File Type=2 LOG descrip:"Thread 0001, Seq# 0000000037, SCN 0x000000448210-0xffffffffffff" thread: 1 nab: 0xffffffff seq: 0x00000025 hws: 0x1 eot: 1 dis: 0 resetlogs count: 0x2efc8e56 scn: 0x0000.003db1ec (4043244) resetlogs terminal rcv count: 0x0 scn: 0x0000.00000000 prev resetlogs count: 0x2dab5350 scn: 0x0000.000cf315 (848661) prev resetlogs terminal rcv count: 0x0 scn: 0x0000.00000000 Low scn: 0x0000.00448210 (4489744) 08/01/2012 04:43:44 Next scn: 0xffff.ffffffff 01/01/1988 00:00:00 Enabled scn: 0x0000.003db1ec (4043244) 07/10/2012 21:10:46 Thread closed scn: 0x0000.00448210 (4489744) 08/01/2012 04:43:44 Disk cksum: 0xec94 Calc cksum: 0xec94 Terminal recovery stop scn: 0x0000.00000000 Terminal recovery 01/01/1988 00:00:00 Most recent redo scn: 0x0000.00000000 Largest LWN: 0 blocks End-of-redo stream : No Unprotected mode Miscellaneous flags: 0x0 Thread internal enable indicator: thr: 0, seq: 0 scn: 0x0000.00000000 REDO RECORD - Thread:1 RBA: 0x000025.00000002.0010 LEN: 0x01d4 VLD: 0x0d SCN: 0x0000.0044821b SUBSCN: 1 08/01/2012 04:44:15 CHANGE #1 TYP:0 CLS: 1 AFN:4 DBA:0x01001d4c OBJ:56818 SCN:0x0000.004481b7 SEQ: 2 OP:11.3 KTB Redo op: 0x01 ver: 0x01 op: F xid: 0x0006.005.000002e6 uba: 0x00800346.04db.28 KDO Op code: DRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 2 ispac: 0 maxfr: 4858 tabn: 0 slot: 0(0x0) CHANGE #2 TYP:0 CLS:27 AFN:2 DBA:0x00800059 OBJ:4294967295 SCN:0x0000.004481e6 SEQ: 2 OP:5.2 ktudh redo: slt: 0x0005 sqn: 0x000002e6 flg: 0x0012 siz: 148 fbi: 0 uba: 0x00800346.04db.28 pxid: 0x0000.000.00000000 CHANGE #3 TYP:0 CLS:27 AFN:2 DBA:0x00800059 OBJ:4294967295 SCN:0x0000.0044821b SEQ: 1 OP:5.4 ktucm redo: slt: 0x0005 sqn: 0x000002e6 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x00800346.04db.28 ext: 2 spc: 2742 fbi: 0 CHANGE #4 TYP:0 CLS:28 AFN:2 DBA:0x00800346 OBJ:4294967295 SCN:0x0000.004481e6 SEQ: 1 OP:5.1 ktudb redo: siz: 148 spc: 2892 flg: 0x0012 seq: 0x04db rec: 0x28 xid: 0x0006.005.000002e6 ktubl redo: slt: 5 rci: 0 opc: 11.1 objn: 56818 objd: 56818 tsn: 4 Undo type: Regular undo Begin trans Last buffer split: No Temp Object: No Tablespace Undo: No 0x00000000 prev ctl uba: 0x00800346.04db.27 prev ctl max cmt scn: 0x0000.0031bb84 prev tx cmt scn: 0x0000.0031bbb4 txn start scn: 0x0000.004481bc logon user: 79 prev brb: 8389445 prev bcl: 0 KDO undo record: KTB Redo op: 0x03 ver: 0x01 op: Z KDO Op code: IRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 2 ispac: 0 maxfr: 4858 tabn: 0 slot: 0(0x0) size/delt: 6 fb: --H-FL-- lb: 0x0 cc: 1 null: - col 0: [ 2] c1 15 REDO RECORD - Thread:1 RBA: 0x000025.00000003.0010 LEN: 0x01d4 VLD: 0x0d SCN: 0x0000.0044821f SUBSCN: 1 08/01/2012 04:44:21 CHANGE #1 TYP:2 CLS: 1 AFN:4 DBA:0x01001d4c OBJ:56818 SCN:0x0000.0044821b SEQ: 2 OP:11.3 KTB Redo op: 0x01 ver: 0x01 op: F xid: 0x0004.00e.000002b5 uba: 0x008005be.034a.19 KDO Op code: DRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 3 ispac: 0 maxfr: 4858 tabn: 0 slot: 1(0x1) CHANGE #2 TYP:0 CLS:23 AFN:2 DBA:0x00800039 OBJ:4294967295 SCN:0x0000.004481e8 SEQ: 1 OP:5.2 ktudh redo: slt: 0x000e sqn: 0x000002b5 flg: 0x0012 siz: 148 fbi: 0 uba: 0x008005be.034a.19 pxid: 0x0000.000.00000000 CHANGE #3 TYP:0 CLS:23 AFN:2 DBA:0x00800039 OBJ:4294967295 SCN:0x0000.0044821f SEQ: 1 OP:5.4 ktucm redo: slt: 0x000e sqn: 0x000002b5 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x008005be.034a.19 ext: 2 spc: 4068 fbi: 0 CHANGE #4 TYP:0 CLS:24 AFN:2 DBA:0x008005be OBJ:4294967295 SCN:0x0000.004481e7 SEQ: 1 OP:5.1 ktudb redo: siz: 148 spc: 4218 flg: 0x0012 seq: 0x034a rec: 0x19 xid: 0x0004.00e.000002b5 ktubl redo: slt: 14 rci: 0 opc: 11.1 objn: 56818 objd: 56818 tsn: 4 Undo type: Regular undo Begin trans Last buffer split: No Temp Object: No Tablespace Undo: No 0x00000000 prev ctl uba: 0x008005be.034a.18 prev ctl max cmt scn: 0x0000.0031bd66 prev tx cmt scn: 0x0000.0031bd70 txn start scn: 0x0000.0044821b logon user: 79 prev brb: 8390061 prev bcl: 0 KDO undo record: KTB Redo op: 0x03 ver: 0x01 op: Z KDO Op code: IRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 3 ispac: 0 maxfr: 4858 tabn: 0 slot: 1(0x1) size/delt: 6 fb: --H-FL-- lb: 0x0 cc: 1 null: - col 0: [ 2] c1 2d REDO RECORD - Thread:1 RBA: 0x000025.00000004.0010 LEN: 0x01ec VLD: 0x0d SCN: 0x0000.00448222 SUBSCN: 1 08/01/2012 04:44:24 CHANGE #1 TYP:2 CLS: 1 AFN:4 DBA:0x01001d4c OBJ:56818 SCN:0x0000.0044821f SEQ: 2 OP:11.3 KTB Redo op: 0x01 ver: 0x01 op: F xid: 0x0007.022.00000307 uba: 0x00800623.0502.07 KDO Op code: DRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 1 ispac: 0 maxfr: 4858 tabn: 0 slot: 2(0x2) CHANGE #2 TYP:0 CLS:29 AFN:2 DBA:0x00800069 OBJ:4294967295 SCN:0x0000.004481ea SEQ: 2 OP:5.2 ktudh redo: slt: 0x0022 sqn: 0x00000307 flg: 0x0012 siz: 172 fbi: 0 uba: 0x00800623.0502.07 pxid: 0x0000.000.00000000 CHANGE #3 TYP:0 CLS:29 AFN:2 DBA:0x00800069 OBJ:4294967295 SCN:0x0000.00448222 SEQ: 1 OP:5.4 ktucm redo: slt: 0x0022 sqn: 0x00000307 srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x00800623.0502.07 ext: 2 spc: 7132 fbi: 0 CHANGE #4 TYP:0 CLS:30 AFN:2 DBA:0x00800623 OBJ:4294967295 SCN:0x0000.004481ea SEQ: 1 OP:5.1 ktudb redo: siz: 172 spc: 7306 flg: 0x0012 seq: 0x0502 rec: 0x07 xid: 0x0007.022.00000307 ktubl redo: slt: 34 rci: 0 opc: 11.1 objn: 56818 objd: 56818 tsn: 4 Undo type: Regular undo Begin trans Last buffer split: No Temp Object: No Tablespace Undo: No 0x00000000 prev ctl uba: 0x00800623.0502.06 prev ctl max cmt scn: 0x0000.0031bbb6 prev tx cmt scn: 0x0000.0031bbcf txn start scn: 0x0000.0044821f logon user: 79 prev brb: 8390158 prev bcl: 0 KDO undo record: KTB Redo op: 0x04 ver: 0x01 op: L itl: xid: 0xffff.000.00000000 uba: 0x00000000.0000.00 flg: C--- lkc: 0 scn: 0x0000.004481b5 KDO Op code: IRP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x01001d4c hdba: 0x01001d4b itli: 1 ispac: 0 maxfr: 4858 tabn: 0 slot: 2(0x2) size/delt: 6 fb: --H-FL-- lb: 0x0 cc: 1 null: - col 0: [ 2] c1 1d ---最后一条记录 END OF REDO DUMP ----- Redo read statistics for thread 1 ----- Read rate (ASYNC): 1Kb in 0.04s => 0.04 Mb/sec Total physical reads: 4096Kb Longest record: 0Kb, moves: 0/3 (0%) Change moves: 0/12 (0%), moved: 0Mb Longest LWN: 0Kb, moves: 0/3 (0%), moved: 0Mb Last redo scn: 0x0000.00448222 (4489762) ---------------------------------------------- |
此时current redo logfile的3条redo 记录：
REDO RECORD – Thread:1 RBA: 0x000025.00000002.0010 SCN: 0x0000.0044821b –> 4489755
REDO RECORD – Thread:1 RBA: 0x000025.00000003.0010 SCN: 0x0000.0044821f –> 4489759
REDO RECORD – Thread:1 RBA: 0x000025.00000004.0010 SCN: 0x0000.00448222 –> 4489762
最后一条记录是RBA: 0x000025.00000004.0010 转换为10进制为logseq 37,block 4，对应scn为4489762。
另外，dump下controlfile ：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
SQL> alter session set events 'immediate trace name controlf level 3'; Session altered. SQL> SELECT a.VALUE || b.symbol || c.instance_name || '_ora_' || d.spid || '.trc' TRACE_FILE_NAME 2 FROM (SELECT VALUE FROM v$parameter WHERE NAME = 'user_dump_dest') a, 3 (SELECT SUBSTR (VALUE, -6, 1) symbol FROM v$parameter 4 WHERE NAME = 'user_dump_dest') b, 5 (SELECT instance_name FROM v$instance) c, 6 (SELECT spid FROM v$session s, v$process p, v$mystat m 7 WHERE s.paddr = p.addr AND s.SID = m.SID AND m.statistic# = 0) d 8 / TRACE_FILE_NAME -------------------------------------------------------------------------------- /home/ora10g/admin/roger/udump/roger_ora_22477.trc SQL> |
提取检查点信息即可：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 |
*************************************************************************** CHECKPOINT PROGRESS RECORDS *************************************************************************** (size = 8180, compat size = 8180, section max = 11, section in-use = 0, last-recid= 0, old-recno = 0, last-recno = 0) (extent = 1, blkno = 2, numrecs = 11) THREAD #1 - status:0x2 flags:0x0 dirty:41 low cache rba:(0x24.4.0) on disk rba:(0x25.5.0) on disk scn: 0x0000.00448223 08/01/2012 04:44:24 resetlogs scn: 0x0000.003db1ec 07/10/2012 21:10:46 heartbeat: 790109170 mount id: 2494401634 .......省略部分内容 THREAD #8 - status:0x0 flags:0x0 dirty:0 low cache rba:(0x0.0.0) on disk rba:(0x0.0.0) on disk scn: 0x0000.00000000 01/01/1988 00:00:00 resetlogs scn: 0x0000.00000000 01/01/1988 00:00:00 heartbeat: 0 mount id: 0 SQL> select to_number('24','xxxx') from dual 2 union all 3 select to_number('4','xxxx') from dual 4 union all 5 select to_number('25','xxxx') from dual 6 union all 7 select to_number('5','xxxx') from dual; TO_NUMBER('24','XXXX') ---------------------- 36 4 37 5 |
THREAD #1 对于redo 组1
dirty:41 说明有41个redo block需要scan
—low cache rba 地址：(0x24.4.0) 转换为10进制为36.4
—on disk rba地址：(0x25.5.0) 转换为10进制为37.5
—on disk scn ： 0x0000.00448223 转换为10进制为 4489763
——设置event 10013 跟instance recovery
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
SQL> oradebug setmypid Statement processed. SQL> alter session set events '10013 trace name context forever, level 1'; Session altered. SQL> alter database open; Database altered. SQL> SQL> oradebug tracefile_name /home/ora10g/admin/roger/udump/roger_ora_22259.trc SQL> SQL> conn roger/roger Connected. SQL> select count(*) from tab_recover; COUNT(*) ---------- 97 ----此时一共是97条记录（前面我们delete了3条记录） |
此时的alert log信息如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 |
Wed Aug 01 04:56:01 PDT 2012 alter database open Wed Aug 01 04:56:01 PDT 2012 Beginning crash recovery of 1 threads Wed Aug 01 04:56:01 PDT 2012 Started redo scan Wed Aug 01 04:56:01 PDT 2012 Completed redo scan 76 redo blocks read, 41 data blocks need recovery Wed Aug 01 04:56:01 PDT 2012 Started redo application at Thread 1: logseq 36, block 4 Wed Aug 01 04:56:01 PDT 2012 Recovery of Online Redo Log: Thread 1 Group 3 Seq 36 Reading mem 0 Mem# 0: /home/ora10g/oradata/roger/redo03.log Wed Aug 01 04:56:01 PDT 2012 Recovery of Online Redo Log: Thread 1 Group 1 Seq 37 Reading mem 0 Mem# 0: /home/ora10g/oradata/roger/redo01.log Wed Aug 01 04:56:01 PDT 2012 Completed redo application Wed Aug 01 04:56:01 PDT 2012 Completed crash recovery at Thread 1: logseq 37, block 5, scn 4509763 41 data blocks read, 41 data blocks written, 76 redo blocks read Wed Aug 01 04:56:01 PDT 2012 LGWR: STARTING ARCH PROCESSES ARC0 started with pid=17, OS id=22678 Wed Aug 01 04:56:01 PDT 2012 ARC0: Archival started ARC1: Archival started LGWR: STARTING ARCH PROCESSES COMPLETE ARC1 started with pid=18, OS id=22680 Wed Aug 01 04:56:01 PDT 2012 Thread 1 advanced to log sequence 38 (thread open) Thread 1 opened at log sequence 38 |
event 10013 的trace信息如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 |
*** 2012-08-01 04:56:01.282 Thread 1 checkpoint: logseq 36, block 2, scn 4489641 cache-low rba: logseq 36, block 4 on-disk rba: logseq 37, block 5, scn 4489763 ---on disk rba地址 start recovery at logseq 36, block 4, scn 0 ----- Redo read statistics for thread 1 ----- Read rate (ASYNC): 38Kb in 0.04s => 0.93 Mb/sec Total physical reads: 4132Kb Longest record: 8Kb, moves: 0/76 (0%) Longest LWN: 13Kb, moves: 0/22 (0%), moved: 0Mb Last redo scn: 0x0000.00448222 (4489762) ---------------------------------------------- ----- Recovery Hash Table Statistics --------- Hash table buckets = 32768 Longest hash chain = 1 Average hash chain = 41/41 = 1.0 Max compares per lookup = 1 Avg compares per lookup = 114/155 = 0.7 ---------------------------------------------- *** 2012-08-01 04:56:01.323 KCRA: start recovery claims for 41 data blocks *** 2012-08-01 04:56:01.357 KCRA: blocks processed = 41/41, claimed = 41, eliminated = 0 *** 2012-08-01 04:56:01.357 Recovery of Online Redo Log: Thread 1 Group 3 Seq 36 Reading mem 0 *** 2012-08-01 04:56:01.360 Recovery of Online Redo Log: Thread 1 Group 1 Seq 37 Reading mem 0 *** 2012-08-01 04:56:01.360 Completed redo application *** 2012-08-01 04:56:01.392 Completed recovery checkpoint ----- Recovery Hash Table Statistics --------- Hash table buckets = 32768 Longest hash chain = 1 Average hash chain = 41/41 = 1.0 Max compares per lookup = 1 Avg compares per lookup = 155/155 = 1.0 ---------------------------------------------- DBRM(kskinitrm) cpu_count (fudge enabled): old(0) -> new(1) kwqmnich: current time:: 11: 56: 2 kwqmnich: instance no 0 check_only flag 1 kwqmnich: initialized job cache structure 从10013 event trace可以得到如下信息： Thread checkpoint: logseq 36, block 2, scn 4489641 cache-low rba: logseq 36, block 4 on-disk rba: logseq 37, block 5, scn 4489763 start recovery at logseq 36, block 4, scn 0 |
我们可以清楚的看到，这里low rba明显要比thread checkpoint大，从最后一行的
start recovery at logseq 可以看出，实例恢复的起点是low cache rba。
从前面的alert log我们可以清楚的看到，恢复的终点地址是：4509763，很明显
这个scn要大于on disk scn 4489763。
所以实例恢复的终点不是on disk rba。
有一点比较奇怪的是，current logfile的最后一条记录scn为4489762，最后一条记录为logseq 37，block 4.
不知道这个block 5是怎么出来，难得哪个地方不对 ？这里有可能信息还没来得及写入到logfile，
我就shutdown abort了，这里进行实例恢复可能还利用了undo，看来这个问题还需要进一步探讨。
备注：最后看微博，发现dbsnake已经写了一篇比较详细的文章：Oracle里Instance Recovery的终点
One Response to “用event 10013验证实例恢复的终点？”
good
Leave a Reply
You must be logged in to post a comment.