用event 10013验证实例恢复的终点？

最新推荐文章于 2022-12-07 17:57:10 发布

derek

最新推荐文章于 2022-12-07 17:57:10 发布

阅读量902

点赞数

分类专栏： oracle 文章标签： thread dependencies statistics terminal disk object

oracle 专栏收录该内容

141 篇文章 1 订阅

订阅专栏

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

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

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: 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
 
SQL>

提取检查点信息即可：

***************************************************************************
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 地址：(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> 
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信息如下：

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

create table tab_recover(object_id) 2 as select object_id from sys.dba_objects where rownum..." />

derek

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
用event 10013验证实例恢复的终点？

这个测试源于微博上一个哥们的一个问题，如下图：SQL> SHOW USERUSER IS "ROGER"SQL> CREATE TABLE tab_recover(object_id) 2 AS SELECT object_id FROM sys.dba_objects WHERE rownum 101; TABLE created. SQL> S
复制链接

扫一扫

专栏目录