recover database提示日志已经应用，1数据文件未应用

xifenfei

做了跨越resetlogs的试验http://www.xifenfei.com/2129.html
其中发现一个问题：

1. RMAN> recover database;
   
2. 
   
3. Starting recover at 2011-12-12 13:49:36
   
4. using channel ORA_DISK_1
   
5. 
   
6. starting media recovery
   
7. 
   
8. archived log for thread 1 with sequence 1 is already on disk as file /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_1_7gc3ojqw_.arc
   
9. archived log for thread 1 with sequence 2 is already on disk as file /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_2_7gc3okx8_.arc
   
10. archived log for thread 1 with sequence 3 is already on disk as file /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_3_7gc3onnq_.arc
    
11. archived log for thread 1 with sequence 4 is already on disk as file /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_4_7gc3wnvf_.arc
    
12. archived log for thread 1 with sequence 5 is already on disk as file /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_5_7gc3wt48_.arc
    
13. archived log file name=/opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_1_7gc3ojqw_.arc thread=1 sequence=1
    
14. archived log file name=/opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_2_7gc3okx8_.arc thread=1 sequence=2
    
15. archived log file name=/opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_3_7gc3onnq_.arc thread=1 sequence=3
    
16. archived log file name=/opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_4_7gc3wnvf_.arc thread=1 sequence=4
    
17. archived log file name=/opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_5_7gc3wt48_.arc thread=1 sequence=5
    
18. unable to find archived log
    
19. archived log thread=1 sequence=6
    
20. RMAN-00571: ===========================================================
    
21. RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
    
22. RMAN-00571: ===========================================================
    
23. RMAN-03002: failure of recover command at 12/12/2011 13:49:39
    
24. RMAN-06054: media recovery requesting unknown archived log for thread 1 with sequence 6 and starting SCN of 12882851

复制代码

通过这里看出来
sequence=5的归档日志已经应用

然后resetlogs打开数据库

1. RMAN> alter database open resetlogs;
   
2. 
   
3. RMAN-00571: ===========================================================
   
4. RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
   
5. RMAN-00571: ===========================================================
   
6. RMAN-03002: failure of alter db command at 12/12/2011 14:06:04
   
7. ORA-01092: ORACLE instance terminated. Disconnection forced
   
8. ORA-00600: internal error code, arguments: [2898], [5], [12], [], [], [], [], [], [], [], [], []
   
9. Process ID: 26406
   
10. Session ID: 96 Serial number: 7
    
11. RMAN-00571: ===========================================================
    
12. RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
    
13. RMAN-00571: ===========================================================
    
14. ORA-03114: not connected to ORACLE
    
15. RMAN-00571: ===========================================================
    
16. RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
    
17. RMAN-00571: ===========================================================
    
18. RMAN-03002: failure of alter db command at 12/12/2011 14:06:04
    
19. ORA-01092: ORACLE instance terminated. Disconnection forced
    
20. ORA-00600: internal error code, arguments: [2898], [5], [12], [], [], [], [], [], [], [], [], []
    
21. Process ID: 26406
    
22. Session ID: 96 Serial number: 7

复制代码

查看日志文件

1. Mon Dec 12 14:05:59 2011
   
2. SMON: enabling cache recovery
   
3. [26406] Successfully onlined Undo Tablespace 2.
   
4. Undo initialization finished serial:0 start:1208679594 end:1208679684 diff:90 (0 seconds)
   
5. Dictionary check beginning
   
6. File #5 is offline, but is part of an online tablespace.
   
7. data file 5: '/opt/oracle/oradata/ora11g/example01.dbf'
   
8. Errors in file /opt/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_26406.trc  (incident=4953):
   
9. ORA-00600: internal error code, arguments: [2898], [5], [12], [], [], [], [], [], [], [], [], []
   
10. Incident details in: /opt/oracle/diag/rdbms/ora11g/ora11g/incident/incdir_4953/ora11g_ora_26406_i4953.trc
    
11. Mon Dec 12 14:06:02 2011
    
12. Dumping diagnostic data in directory=[cdmp_20111212140602], requested by (instance=1, osid=26406), summary=[incident=4953].
    
13. Use ADRCI or Support Workbench to package the incident.
    
14. See Note 411.1 at My Oracle Support for error and packaging details.
    
15. Errors in file /opt/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_26406.trc:
    
16. ORA-00600: internal error code, arguments: [2898], [5], [12], [], [], [], [], [], [], [], [], []
    
17. Errors in file /opt/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_26406.trc:
    
18. ORA-00600: internal error code, arguments: [2898], [5], [12], [], [], [], [], [], [], [], [], []
    
19. Error 600 happened during db open, shutting down database
    
20. USER (ospid: 26406): terminating the instance due to error 600
    
21. Mon Dec 12 14:06:03 2011
    
22. Instance terminated by USER, pid = 26406
    
23. ORA-1092 signalled during: alter database open resetlogs...
    
24. opiodr aborting process unknown ospid (26406) as a result of ORA-1092
    
25. Mon Dec 12 14:06:04 2011
    
26. ORA-1092 : opitsk aborting process

复制代码

打开数据库，数据库open，但是还报错，其中一个trace文件

1. *** 2011-12-12 14:17:46.627
   
2. Started Serial Media Recovery
   
3. Datafile 5 belongs to incarnation with resetlogs SCN : 12881971, timestamp: 2de0acea
   
4. Media Recovery apply resetlogs offline range for datafile 5, incarnation : 1
   
5. Datafile 5 belongs to incarnation with resetlogs SCN : 12881971, timestamp: 2de0acea
   
6. Dumping database incarnation table:
   
7. Resetlogs 0 scn and time: 0x0000.00c493a4 12/12/2011 14:05:53
   
8. Resetlogs 1 scn and time: 0x0000.00c49033 12/12/2011 13:17:30
   
9. Recovery target incarnation = 4, activation ID = 0
   
10. Influx buffer limit = 37449 min(50% x 74898, 100000)
    
11. Start recovery at thread 1 ckpt scn 12881971 logseq 1 block 2
    
12. Initial buffer sizes: read 1024K, overflow 832K, change 805K
    
13. 
    
14. *** 2011-12-12 14:17:46.725
    
15. Media Recovery add redo thread 1
    
16. 
    
17. *** 2011-12-12 14:18:47.348
    
18. Media Recovery Log 2011_12_12/o1_mf_1_1_7gc3ojqw_.arc
    
19. 
    
20. *** 2011-12-12 14:19:00.198
    
21. Media Recovery Log /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_1_7gc3ojqw_.arc
    
22. Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    
23. Datafile 5 belongs to incarnation with resetlogs SCN : 12881971, timestamp: 2de0acea
    
24. 
    
25. *** 2011-12-12 14:19:15.911
    
26. Media Recovery Log /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_2_7gc3okx8_.arc
    
27. Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    
28. 
    
29. *** 2011-12-12 14:19:22.638
    
30. Media Recovery Log /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_3_7gc3onnq_.arc
    
31. Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    
32. 
    
33. *** 2011-12-12 14:19:31.007
    
34. Media Recovery Log /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_4_7gc3wnvf_.arc
    
35. Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    
36. Datafile 5 belongs to incarnation with resetlogs SCN : 12881971, timestamp: 2de0acea
    
37. 
    
38. *** 2011-12-12 14:19:37.116
    
39. Media Recovery Log /opt/oracle/fast_recovery_area/ORA11G/archivelog/2011_12_12/o1_mf_1_5_7gc3wt48_.arc
    
40. Log read is SYNCHRONOUS though disk_asynch_io is enabled!
    
41. Initial buffer sizes: read 1024K, overflow 832K, change 805K
    
42. Thread 1 initialized for new incarnation 1 at scn 12882852
    
43. Media Recovery current incarnation depth : 0
    
44. File 5 (stop scn 12882852) completed recovery at checkpoint scn 12882852

复制代码

查询相关视图

1. SQL> select file#,online_status,to_char(change#,'999999999999') from v$recover_file;
   
2. 
   
3.      FILE# ONLINE_ TO_CHAR(CHANG
   
4. ---------- ------- -------------
   
5.          5 OFFLINE      12881970
   
6. 
   
7. SQL> select file#,to_char(checkpoint_change#,'999999999999') from v$datafile;
   
8. 
   
9.      FILE# TO_CHAR(CHECK
   
10. ---------- -------------
    
11.          1      12902896
    
12.          2      12902896
    
13.          3      12902896
    
14.          4      12902896
    
15.          5             0
    
16. 
    
17. SQL> select FILE#,to_char(checkpoint_change#,'999999999999') from v$datafile_header;
    
18. 
    
19.      FILE# TO_CHAR(CHECK
    
20. ---------- -------------
    
21.          1      12902896
    
22.          2      12902896
    
23.          3      12902896
    
24.          4      12902896
    
25.          5      12881970

复制代码

通过这些证明datafile 5没有应用sequence=5


然后我手工应用 redo log 5 to   datafile 5，问题解决，datafile 5 正常online






问题：为什么在rman 做recover时候，提示已经应用了req 5，而最后resetlogs时候，有出现datafile 5没有应用该日志，需要人工去引用

Liu Maclean(刘相兵

看下 DATAFILE 5是何时开始OFFLINE的？

可以用 scn_to_timestamp 转换12881970 得到。

Maclean Liu(刘相兵

跑一下这个post里的 SQL 脚本 ， 上传结果 http://www.oracledatabase12g.com ... BF%A1%E6%81%AF.html

xifenfei

TABLESPACE_NAME                            TS#                                  -------------------------------- -------------                                  FILENAME                                                                        --------------------------------------------------------------------------------        FILE# STATUS  ENABLED    CREATION_CHANGE# CREATION_TIME                 ------------- ------- ---------- ---------------- -----------------------       CHECKPOINT_CHANG CHECKPOINT_TIME         OFFLINE_CHANGE#  ONLINE_CHANGE#        ---------------- ----------------------- ---------------- ----------------      ONLINE_TIME             ONLINE_CHANGE#   ONLINE_TIME                            ----------------------- ---------------- -----------------------                BYTES                 BLOCK_SIZE                                                ------------------ -------------                                                #SYSTEM#                                     0                                  #/opt/oracle/oradata/ora11g/system01.dbf#                                                   1 SYSTEM  READ WRITE                7 17-SEP-2011 09:46:08                  12930137 12-DEC-2011 16:52:50            12882851         12882852      12-DEC-2011 14:27:18                   0                                               765,460,480          8192                                                #EXAMPLE#                                    6                                  #/opt/oracle/oradata/ora11g/example01.dbf#                                                  5 OFFLINE READ WRITE          1026256 31-OCT-2011 16:06:10
这里出现datafile 5 offline，是我今天下午第二次恢复的时候
Mon Dec 12 15:29:29 2011
ALTER DATABASE RECOVER  datafile 5  
Media Recovery Start
Serial Media Recovery started
Media Recovery Complete (ora11g)
Completed: ALTER DATABASE RECOVER  datafile 5  
Mon Dec 12 15:29:42 2011
alter database datafile 5 offline
Completed: alter database datafile 5 offline

本来是online，我敲打成了offline，然后刚刚跑这个命令后，我改成online成功了

[ 本帖最后由 xifenfei 于 2011-12-12 21:26 编辑 ]

xifenfei

说明：
现在的库是的第二次恢复的结果，第一次恢复结果就是如同blog中记录，因为第一次库恢复成功的库，已经被是删除，很难找回那个时间点的现场了

Maclean Liu(刘相兵

我觉得 没有recover datafile 5 和 当时 其状态有关系

xifenfei

我两次测试，都是datafile 5没有被完全恢复和其他文件同一个scn(第一次比较明显，正好相差了一个日志文件)

无论数据文件5是什么状态的，也不可能恢复的时候应用了部分日志文件，而部分没有应该（因为在恢复过程中需要的那几个归档日志，都是我特意切换日志的，这个过程中，不存在让datafile 5的状态发生改变）

kevinlin.ora

这实验是dbitr呢，还是正常全部恢复？