oracle获取一天的最后1d,【学习笔记】Oracle里Instance Recovery的终点研究笔记-CSDN博客

【学习笔记】Oracle里Instance Recovery的终点研究笔记

时间:2016-12-10 19:24 来源:Oracle研究中心作者:网络点击:

次

天萃荷净

Oracle研究中心学习笔记：分享一篇关于Oracle里Instance Recovery的终点研究笔记。

本站文章除注明转载外，均为本站原创：转载自love wife & love life —Roger 的Oracle技术博客

本文链接地址: 用event 10013验证实例恢复的终点？

这个测试源于微博上一个哥们的一个问题，如下图：

SQL> SHOW USER

USER IS "ROGER"

SQL> CREATE TABLE tab_recover(object_id)

2 AS SELECT object_id FROM sys.dba_objects WHERE rohttp://www.oracleplus.netwnum < 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

100 ROWS selected.

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.

这里一个，删除了3条数据。上面这里做delete操作之前之所以切换redo 是因为dump信息太多了，查看不方便，这里我切换以后，删除几条记录，就dump，那么logfile的dump内容就很少了，非常的直观。

—–log file dump

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.

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: 0×000025.00000002.0010 SCN: 0×0000.0044821b –> 4489755

REDO RECORD – Thread:1 RBA: 0×000025.00000003.0010 SCN: 0×0000.0044821f –> 4489759

REDO RECORD – Thread:1 RBA: 0×000025.00000004.0010 SCN: 0×0000.00448222 –> 4489762

最后一条记录是RBA: 0×000025.00000004.0010 转换为10进制为logseq 37,block 4，对应scn为4489762。

另外，dump下controlfile ：

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

提取检查点信息即可：

***************************************************************************

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

----------------------

THREAD #1 对于redo 组1

dirty:41 说明有41个redo block需要scan

—low cache rba 地址：(0×24.4.0) 转换为10进制为36.4

—on disk rba地址：(0×25.5.0) 转换为10进制为37.5

—on disk scn ： 0×0000.00448223 转换为10进制为 4489763

——设置event 10013 跟instance recovery

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> oradebug tracefile_name

/home/ora10g/admin/roger/udump/roger_ora_22259.trc

SQL> conn roger/roger

Connected.

SQL> SELECT COUNT(*) FROM tab_recover;

COUNT(*)

----------

97 ----此时一共是97条记录(前面我们delete了3条记录)

此时的alert log信息如下：

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信息如下：

*** 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的终点

--------------------------------------ORACLE-DBA----------------------------------------

最权威、专业的Oracle案例资源汇总之【学习笔记】Oracle里Instance Recovery的终点研究笔记