下午协助客户做异机备份恢复测试，平台是AIX 5.3使用tsm备份。在源生产机上备份了数据库和控制文件，准备从磁带库上恢复到测试机时RMAN报找到不备份的控制文件，之后crosscheck了一把:
RMAN> set DBID=575015651
executing command: SET DBID
database name is "PRMDB1" and DBID is 575015651
RMAN> run {
2> allocate channel c1 type sbt_tape parms 'ENV=(TDPO_OPTFILE=/usr/tivoli/tsm/client/oracle/bin64/tdpo.opt)';
3> debug on;
4> crosscheck backup;
5> debug off;
6> release channel c1;
7> }
allocated channel: c1
channel c1: sid=323 devtype=SBT_TAPE
channel c1: Data Protection for Oracle: version 5.3.3.0
.................
DBGMISC: executing command crosscheck [16:33:04.695]
DBGRPC: krmxpoq: xc=4569134136, action="0000001 FINISHED70", col_l=18, ind=0, sid=321
DBGRPC: krmxr: xc=4569134136 chid=default rpc count=1
DBGRPC: krmxpoq: xc=4569145944, action="0000005 FINISHED3", col_l=17, ind=0, sid=323
DBGRPC: krmxr: xc=4569145944 chid=c1 rpc count=5
DBGRPC: ENTERED krmqgns
DBGRPC: krmqgns: looking for work for channel default (krmqgns)
DBGRPC: krmqgns: commands remaining to be executed: (krmqgns)
DBGRPC: CMD type=crosscheck id=1 status=NOT STARTED
DBGRPC: 1 STEP id=1 status=NOT STARTED chid=c1
DBGRPC: 2 STEP id=2 status=NOT STARTED chid=default
DBGRPC: krmqgns: channel default assigned step 2 (krmqgns)
DBGRPC: (krmqgns)
DBGRPC: EXITED krmqgns with status 0
DBGRPC: ENTERED krmqgns
DBGRPC: krmqgns: looking for work for channel c1 (krmqgns)
DBGRPC: krmqgns: commands remaining to be executed: (krmqgns)
DBGRPC: CMD type=crosscheck id=1 status=NOT STARTED
DBGRPC: 1 STEP id=1 status=NOT STARTED chid=c1
DBGRPC: 2 STEP id=2 status=STARTED chid=default
DBGRPC: krmqgns: channel c1 assigned step 1 (krmqgns)
DBGRPC: (krmqgns)
DBGRPC: EXITED krmqgns with status 0
DBGRPC: krmxcis: xc=4569134136 chid=default calling pcicmp
DBGRPC: krmxcis: xc=4569145944 chid=c1 calling pcicmp
DBGRPC: krmxr: xc=4569134136 chid=default calling peicnt
DBGPLSQL: ENTERED change [16:33:04.951]
DBGPLSQL: channel default: started, command:651 [16:33:04.951] (change)
DBGPLSQL: EXITED change with status OK [16:33:04.954]
DBGRPC: krmxr: xc=4569134136 finished step
DBGRPC: ENTERED krmqgns
DBGRPC: krmqgns: channel default finished step 2 (krmqgns)
DBGRPC: krmqgns: looking for work for channel default (krmqgns)
DBGRPC: krmqgns: commands remaining to be executed: (krmqgns)
DBGRPC: CMD type=crosscheck id=1 status=STARTED
DBGRPC: 1 STEP id=1 status=STARTED chid=c1
DBGRPC: krmqgns: no work found for channel default (krmqgns)
DBGRPC: (krmqgns)
DBGRPC: EXITED krmqgns with status 1
DBGRPC: krmxr: xc=4569145944 chid=c1 calling peicnt
DBGPLSQL: ENTERED change [16:33:04.955]
DBGPLSQL: channel c1: started, command:651 [16:33:04.955] (change)
DBGPLSQL: channel c1: processing (file/handle=archPRMDB1_736683220_1_%r,
recid=1, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:04.956] (change)
DBGPLSQL: channel c1: force: 0 [16:33:04.956] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=6
DBGRPC: krmxrpc: xc=4569145944 RPC #6 completed immediately
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r, rc=5 [16:33:05.004] (change)
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r, Modified rc=4 [16:33:05.004] (change)
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r, found=FALSE [16:33:05.004] (change)
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r not found for cmd 651 [16:33:05.004] (change)
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r mismatch: FALSE force: 0 [16:33:05.004] (change)
DBGPLSQL: channel c1: file archPRMDB1_736683220_1_%r not updated on repository, old_status:X same as new_status:X [16:33:05.004] (change)
DBGMISC: ENTERED krmzlog [16:33:05.004]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.005] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.005]
RMAN-08517: backup piece handle=archPRMDB1_736683220_1_%r recid=1 stamp=736683221
DBGMISC: EXITED krmzlog [16:33:05.005] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_03luhpd6_1_1,recid=2, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.005] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.005] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=7
DBGRPC: krmxrpc: xc=4569145944 RPC #7 completed immediately
DBGPLSQL: channel c1: file full_03luhpd6_1_1, rc=5 [16:33:05.029] (change)
DBGPLSQL: channel c1: file full_03luhpd6_1_1, Modified rc=4 [16:33:05.029] (change)
DBGPLSQL: channel c1: file full_03luhpd6_1_1, found=FALSE [16:33:05.030] (change)
DBGPLSQL: channel c1: file full_03luhpd6_1_1 not found for cmd 651 [16:33:05.030] (change)
DBGPLSQL: channel c1: file full_03luhpd6_1_1 mismatch: FALSE force: 0 [16:33:05.030] (change)
DBGPLSQL: channel c1: file full_03luhpd6_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.030] (change)
DBGMISC: ENTERED krmzlog [16:33:05.030]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.030] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.030]
RMAN-08517: backup piece handle=full_03luhpd6_1_1 recid=2 stamp=736683430
DBGMISC: EXITED krmzlog [16:33:05.030] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_04luhpg2_1_1,recid=3, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.031] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.031] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=8
DBGRPC: krmxrpc: xc=4569145944 RPC #8 completed immediately
DBGPLSQL: channel c1: file full_04luhpg2_1_1, rc=5 [16:33:05.050] (change)
DBGPLSQL: channel c1: file full_04luhpg2_1_1, Modified rc=4 [16:33:05.050] (change)
DBGPLSQL: channel c1: file full_04luhpg2_1_1, found=FALSE [16:33:05.050] (change)
DBGPLSQL: channel c1: file full_04luhpg2_1_1 not found for cmd 651 [16:33:05.050] (change)
DBGPLSQL: channel c1: file full_04luhpg2_1_1 mismatch: FALSE force: 0 [16:33:05.050] (change)
DBGPLSQL: channel c1: file full_04luhpg2_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.050] (change)
DBGMISC: ENTERED krmzlog [16:33:05.050]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.050] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.050]
RMAN-08517: backup piece handle=full_04luhpg2_1_1 recid=3 stamp=736683522
DBGMISC: EXITED krmzlog [16:33:05.051] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_05luhpin_1_1,recid=4, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.051] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.051] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=9
DBGRPC: krmxrpc: xc=4569145944 RPC #9 completed immediately
DBGPLSQL: channel c1: file full_05luhpin_1_1, rc=5 [16:33:05.069] (change)
DBGPLSQL: channel c1: file full_05luhpin_1_1, Modified rc=4 [16:33:05.069] (change)
DBGPLSQL: channel c1: file full_05luhpin_1_1, found=FALSE [16:33:05.070] (change)
DBGPLSQL: channel c1: file full_05luhpin_1_1 not found for cmd 651 [16:33:05.070] (change)
DBGPLSQL: channel c1: file full_05luhpin_1_1 mismatch: FALSE force: 0 [16:33:05.070] (change)
DBGPLSQL: channel c1: file full_05luhpin_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.070] (change)
DBGMISC: ENTERED krmzlog [16:33:05.070]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.070] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.070]
RMAN-08517: backup piece handle=full_05luhpin_1_1 recid=4 stamp=736683608
DBGMISC: EXITED krmzlog [16:33:05.070] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_06luhpiv_1_1,recid=5, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.070] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.071] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=10
DBGRPC: krmxrpc: xc=4569145944 RPC #10 completed immediately
DBGPLSQL: channel c1: file full_06luhpiv_1_1, rc=5 [16:33:05.089] (change)
DBGPLSQL: channel c1: file full_06luhpiv_1_1, Modified rc=4 [16:33:05.089] (change)
DBGPLSQL: channel c1: file full_06luhpiv_1_1, found=FALSE [16:33:05.090] (change)
DBGPLSQL: channel c1: file full_06luhpiv_1_1 not found for cmd 651 [16:33:05.090] (change)
DBGPLSQL: channel c1: file full_06luhpiv_1_1 mismatch: FALSE force: 0 [16:33:05.090] (change)
DBGPLSQL: channel c1: file full_06luhpiv_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.090] (change)
DBGMISC: ENTERED krmzlog [16:33:05.090]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.090] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.090]
RMAN-08517: backup piece handle=full_06luhpiv_1_1 recid=5 stamp=736683616
DBGMISC: EXITED krmzlog [16:33:05.091] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=cf_7_1,recid=6, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.091] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.091] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=11
DBGRPC: krmxrpc: xc=4569145944 RPC #11 completed immediately
DBGPLSQL: channel c1: file cf_7_1, rc=5 [16:33:05.110] (change)
DBGPLSQL: channel c1: file cf_7_1, Modified rc=4 [16:33:05.110] (change)
DBGPLSQL: channel c1: file cf_7_1, found=FALSE [16:33:05.110] (change)
DBGPLSQL: channel c1: file cf_7_1 not found for cmd 651 [16:33:05.110] (change)
DBGPLSQL: channel c1: file cf_7_1 mismatch: FALSE force: 0 [16:33:05.110] (change)
DBGPLSQL: channel c1: file cf_7_1 not updated on repository, old_status:X same as new_status:X [16:33:05.110] (change)
DBGMISC: ENTERED krmzlog [16:33:05.110]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.111] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.111]
RMAN-08517: backup piece handle=cf_7_1 recid=6 stamp=736683625
DBGMISC: EXITED krmzlog [16:33:05.111] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_08luhqr0_1_1,recid=7, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.111] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.111] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=12
DBGRPC: krmxrpc: xc=4569145944 RPC #12 completed immediately
DBGPLSQL: channel c1: file full_08luhqr0_1_1, rc=5 [16:33:05.129] (change)
DBGPLSQL: channel c1: file full_08luhqr0_1_1, Modified rc=4 [16:33:05.130] (change)
DBGPLSQL: channel c1: file full_08luhqr0_1_1, found=FALSE [16:33:05.130] (change)
DBGPLSQL: channel c1: file full_08luhqr0_1_1 not found for cmd 651 [16:33:05.130] (change)
DBGPLSQL: channel c1: file full_08luhqr0_1_1 mismatch: FALSE force: 0 [16:33:05.130] (change)
DBGPLSQL: channel c1: file full_08luhqr0_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.130] (change)
DBGMISC: ENTERED krmzlog [16:33:05.130]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.130] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.130]
RMAN-08517: backup piece handle=full_08luhqr0_1_1 recid=7 stamp=736684896
DBGMISC: EXITED krmzlog [16:33:05.130] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_09luhqvr_1_1,recid=8, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.130] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.131] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=13
DBGRPC: krmxrpc: xc=4569145944 RPC #13 completed immediately
DBGPLSQL: channel c1: file full_09luhqvr_1_1, rc=5 [16:33:05.149] (change)
DBGPLSQL: channel c1: file full_09luhqvr_1_1, Modified rc=4 [16:33:05.149] (change)
DBGPLSQL: channel c1: file full_09luhqvr_1_1, found=FALSE [16:33:05.150] (change)
DBGPLSQL: channel c1: file full_09luhqvr_1_1 not found for cmd 651 [16:33:05.150] (change)
DBGPLSQL: channel c1: file full_09luhqvr_1_1 mismatch: FALSE force: 0 [16:33:05.150] (change)
DBGPLSQL: channel c1: file full_09luhqvr_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.150] (change)
DBGMISC: ENTERED krmzlog [16:33:05.150]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.150] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.150]
RMAN-08517: backup piece handle=full_09luhqvr_1_1 recid=8 stamp=736685053
DBGMISC: EXITED krmzlog [16:33:05.150] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=cf_10_1,recid=9, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.151] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.151] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=14
DBGRPC: krmxrpc: xc=4569145944 RPC #14 completed immediately
DBGPLSQL: channel c1: file cf_10_1, rc=5 [16:33:05.161] (change)
DBGPLSQL: channel c1: file cf_10_1, Modified rc=4 [16:33:05.161] (change)
DBGPLSQL: channel c1: file cf_10_1, found=FALSE [16:33:05.162] (change)
DBGPLSQL: channel c1: file cf_10_1 not found for cmd 651 [16:33:05.162] (change)
DBGPLSQL: channel c1: file cf_10_1 mismatch: FALSE force: 0 [16:33:05.162] (change)
DBGPLSQL: channel c1: file cf_10_1 not updated on repository, old_status:X same as new_status:X [16:33:05.162] (change)
DBGMISC: ENTERED krmzlog [16:33:05.162]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.162] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.162]
RMAN-08517: backup piece handle=cf_10_1 recid=9 stamp=736685062
DBGMISC: EXITED krmzlog [16:33:05.162] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=archPRMDB1_736685075_11_%r,recid=10, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.163] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.163] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=15
DBGRPC: krmxrpc: xc=4569145944 RPC #15 completed immediately
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r, rc=5 [16:33:05.190] (change)
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r, Modified rc=4 [16:33:05.190] (change)
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r, found=FALSE [16:33:05.190] (change)
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r not found for cmd 651 [16:33:05.190] (change)
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r mismatch: FALSE force: 0 [16:33:05.190] (change)
DBGPLSQL: channel c1: file archPRMDB1_736685075_11_%r not updated on repository, old_status:X same as new_status:X [16:33:05.190] (change)
DBGMISC: ENTERED krmzlog [16:33:05.190]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.191] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.191]
RMAN-08517: backup piece handle=archPRMDB1_736685075_11_%r recid=10 stamp=736685076
DBGMISC: EXITED krmzlog [16:33:05.191] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_0cluhrqs_1_1,recid=11, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.191] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.191] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=16
DBGRPC: krmxrpc: xc=4569145944 RPC #16 completed immediately
DBGPLSQL: channel c1: file full_0cluhrqs_1_1, rc=5 [16:33:05.210] (change)
DBGPLSQL: channel c1: file full_0cluhrqs_1_1, Modified rc=4 [16:33:05.211] (change)
DBGPLSQL: channel c1: file full_0cluhrqs_1_1, found=FALSE [16:33:05.211] (change)
DBGPLSQL: channel c1: file full_0cluhrqs_1_1 not found for cmd 651 [16:33:05.211] (change)
DBGPLSQL: channel c1: file full_0cluhrqs_1_1 mismatch: FALSE force: 0 [16:33:05.211] (change)
DBGPLSQL: channel c1: file full_0cluhrqs_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.211] (change)
DBGMISC: ENTERED krmzlog [16:33:05.211]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.211] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.211]
RMAN-08517: backup piece handle=full_0cluhrqs_1_1 recid=11 stamp=736685916
DBGMISC: EXITED krmzlog [16:33:05.211] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_0dluhs0l_1_1,recid=12, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.212] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.212] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=17
DBGRPC: krmxrpc: xc=4569145944 RPC #17 completed immediately
DBGPLSQL: channel c1: file full_0dluhs0l_1_1, rc=5 [16:33:05.229] (change)
DBGPLSQL: channel c1: file full_0dluhs0l_1_1, Modified rc=4 [16:33:05.229] (change)
DBGPLSQL: channel c1: file full_0dluhs0l_1_1, found=FALSE [16:33:05.229] (change)
DBGPLSQL: channel c1: file full_0dluhs0l_1_1 not found for cmd 651 [16:33:05.229] (change)
DBGPLSQL: channel c1: file full_0dluhs0l_1_1 mismatch: FALSE force: 0 [16:33:05.229] (change)
DBGPLSQL: channel c1: file full_0dluhs0l_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.229] (change)
DBGMISC: ENTERED krmzlog [16:33:05.230]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.230] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.230]
RMAN-08517: backup piece handle=full_0dluhs0l_1_1 recid=12 stamp=736686103
DBGMISC: EXITED krmzlog [16:33:05.230] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=cf_14_1,recid=13, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.230] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.230] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=18
DBGRPC: krmxrpc: xc=4569145944 RPC #18 completed immediately
DBGPLSQL: channel c1: file cf_14_1, rc=5 [16:33:05.250] (change)
DBGPLSQL: channel c1: file cf_14_1, Modified rc=4 [16:33:05.250] (change)
DBGPLSQL: channel c1: file cf_14_1, found=FALSE [16:33:05.250] (change)
DBGPLSQL: channel c1: file cf_14_1 not found for cmd 651 [16:33:05.250] (change)
DBGPLSQL: channel c1: file cf_14_1 mismatch: FALSE force: 0 [16:33:05.250] (change)
DBGPLSQL: channel c1: file cf_14_1 not updated on repository, old_status:X same as new_status:X [16:33:05.250] (change)
DBGMISC: ENTERED krmzlog [16:33:05.250]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.250] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.251]
RMAN-08517: backup piece handle=cf_14_1 recid=13 stamp=736686112
DBGMISC: EXITED krmzlog [16:33:05.251] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=archPRMDB1_736686125_15_%r,recid=14, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.251] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.251] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=19
DBGRPC: krmxrpc: xc=4569145944 RPC #19 completed immediately
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r, rc=5 [16:33:05.270] (change)
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r, Modified rc=4 [16:33:05.270] (change)
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r, found=FALSE [16:33:05.270] (change)
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r not found for cmd 651 [16:33:05.270] (change)
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r mismatch: FALSE force: 0 [16:33:05.270] (change)
DBGPLSQL: channel c1: file archPRMDB1_736686125_15_%r not updated on repository, old_status:X same as new_status:X [16:33:05.270] (change)
DBGMISC: ENTERED krmzlog [16:33:05.270]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.271] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.271]
RMAN-08517: backup piece handle=archPRMDB1_736686125_15_%r recid=14 stamp=736686126
DBGMISC: EXITED krmzlog [16:33:05.271] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_0glul24s_1_1,recid=15, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.271] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.271] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=20
DBGRPC: krmxrpc: xc=4569145944 RPC #20 completed immediately
DBGPLSQL: channel c1: file full_0glul24s_1_1, rc=5 [16:33:05.294] (change)
DBGPLSQL: channel c1: file full_0glul24s_1_1, Modified rc=4 [16:33:05.294] (change)
DBGPLSQL: channel c1: file full_0glul24s_1_1, found=FALSE [16:33:05.294] (change)
DBGPLSQL: channel c1: file full_0glul24s_1_1 not found for cmd 651 [16:33:05.294] (change)
DBGPLSQL: channel c1: file full_0glul24s_1_1 mismatch: FALSE force: 0 [16:33:05.294] (change)
DBGPLSQL: channel c1: file full_0glul24s_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.294] (change)
DBGMISC: ENTERED krmzlog [16:33:05.294]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.295] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.295]
RMAN-08517: backup piece handle=full_0glul24s_1_1 recid=15 stamp=736790684
DBGMISC: EXITED krmzlog [16:33:05.295] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=full_0hlul2ab_1_1,recid=16, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.295] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.295] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=21
DBGRPC: krmxrpc: xc=4569145944 RPC #21 completed immediately
DBGPLSQL: channel c1: file full_0hlul2ab_1_1, rc=5 [16:33:05.315] (change)
DBGPLSQL: channel c1: file full_0hlul2ab_1_1, Modified rc=4 [16:33:05.315] (change)
DBGPLSQL: channel c1: file full_0hlul2ab_1_1, found=FALSE [16:33:05.315] (change)
DBGPLSQL: channel c1: file full_0hlul2ab_1_1 not found for cmd 651 [16:33:05.315] (change)
DBGPLSQL: channel c1: file full_0hlul2ab_1_1 mismatch: FALSE force: 0 [16:33:05.315] (change)
DBGPLSQL: channel c1: file full_0hlul2ab_1_1 not updated on repository, old_status:X same as new_status:X [16:33:05.315] (change)
DBGMISC: ENTERED krmzlog [16:33:05.315]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.315] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.316]
RMAN-08517: backup piece handle=full_0hlul2ab_1_1 recid=16 stamp=736790860
DBGMISC: EXITED krmzlog [16:33:05.316] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=cf_18_1,recid=17, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.316] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.316] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=22
DBGRPC: krmxrpc: xc=4569145944 RPC #22 completed immediately
DBGPLSQL: channel c1: file cf_18_1, rc=5 [16:33:05.334] (change)
DBGPLSQL: channel c1: file cf_18_1, Modified rc=4 [16:33:05.334] (change)
DBGPLSQL: channel c1: file cf_18_1, found=FALSE [16:33:05.334] (change)
DBGPLSQL: channel c1: file cf_18_1 not found for cmd 651 [16:33:05.334] (change)
DBGPLSQL: channel c1: file cf_18_1 mismatch: FALSE force: 0 [16:33:05.334] (change)
DBGPLSQL: channel c1: file cf_18_1 not updated on repository, old_status:X same as new_status:X [16:33:05.334] (change)
DBGMISC: ENTERED krmzlog [16:33:05.335]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.335] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.335]
RMAN-08517: backup piece handle=cf_18_1 recid=17 stamp=736790870
DBGMISC: EXITED krmzlog [16:33:05.335] elapsed time [00:00:00:00.000]
DBGPLSQL: channel c1: processing (file/handle=archPRMDB1_736790884_19_%r,recid=18, old_status=X, hdl_isdisk=0, devicetype=SBT_TAPE) [16:33:05.335] (change)
DBGPLSQL: channel c1: force: 0 [16:33:05.335] (change)
DBGRPC: krmxrpc: xc=4569145944 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.VALIDATEBACKUPPIECE
DBGRPC: krmxrpc: xc=4569145944 chid=c1 rpc count(non-blocking)=23
DBGRPC: krmxrpc: xc=4569145944 RPC #23 completed immediately
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r, rc=5 [16:33:05.354] (change)
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r, Modified rc=4 [16:33:05.354] (change)
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r, found=FALSE [16:33:05.354] (change)
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r not found for cmd 651 [16:33:05.354] (change)
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r mismatch: FALSE force: 0 [16:33:05.354] (change)
DBGPLSQL: channel c1: file archPRMDB1_736790884_19_%r not updated on repository, old_status:X same as new_status:X [16:33:05.354] (change)
DBGMISC: ENTERED krmzlog [16:33:05.354]
RMAN-08074: crosschecked backup piece: found to be 'EXPIRED'
DBGMISC: EXITED krmzlog [16:33:05.355] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.355]
RMAN-08517: backup piece handle=archPRMDB1_736790884_19_%r recid=18 stamp=736790885
DBGMISC: EXITED krmzlog [16:33:05.355] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.355]
RMAN-06206: Crosschecked 18 objects
DBGMISC: EXITED krmzlog [16:33:05.355] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzlog [16:33:05.355]
........................
released channel: c1
居然所有的备份都显示为’EXPIRED’的！管理备份的技术人员反映tsm没有部署任何备份策略，怀疑是RMAN的配置问题；但实际上RMAN就算备份已经处于obsolete状态了，也不会自动去删除备份导致变成’EXPIRED’的过期状态。
显然这还是TSM备份软件配置的问题，仔细检查过tdpo.opt文件后发现测试机上的TDPO_OWNER设置为oracle，而实际生产机上的TDPO_OWNER则不是oracle，因为安全级别的问题，客户在安装生产库时没有建立我们常见的oracle用户，而是在dba组内建立了其他数据库管理用户名。虽然不甚了解TSM，但多少也玩过Veritas的NBU，显然tdpo.opt文件中的TDPO_OWNER参数是用来识别tsm备份的拥有者的，客户在生产库上是以非oracle用户名的用户产生的备份，因此tsm server认为在oracle用户名下并没有任何实际备份，从而导致RMAN去crosscheck的时候返回的都是expired状态。将tdpo.opt中的TDPO_OWNER改回和原生产库中一致:
RMAN> set DBID=575015651
executing command: SET DBID
database name is "PRMDB1" and DBID is 575015651
RMAN> run {
2> allocate channel c1 type sbt_tape parms 'ENV=(TDPO_OPTFILE=/usr/tivoli/tsm/client/oracle/bin64/tdpo.opt)';
3> crosscheck backup;
4> release channel c1;
5> }
allocated channel: c1
channel c1: sid=321 devtype=SBT_TAPE
channel c1: Data Protection for Oracle: version 5.3.3.0
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=archPRMDB1_736683220_1_%r recid=1 stamp=736683221
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_03luhpd6_1_1 recid=2 stamp=736683430
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_04luhpg2_1_1 recid=3 stamp=736683522
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_05luhpin_1_1 recid=4 stamp=736683608
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_06luhpiv_1_1 recid=5 stamp=736683616
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=cf_7_1 recid=6 stamp=736683625
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_08luhqr0_1_1 recid=7 stamp=736684896
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_09luhqvr_1_1 recid=8 stamp=736685053
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=cf_10_1 recid=9 stamp=736685062
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=archPRMDB1_736685075_11_%r recid=10 stamp=736685076
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_0cluhrqs_1_1 recid=11 stamp=736685916
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_0dluhs0l_1_1 recid=12 stamp=736686103
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=cf_14_1 recid=13 stamp=736686112
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=archPRMDB1_736686125_15_%r recid=14 stamp=736686126
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_0glul24s_1_1 recid=15 stamp=736790684
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=full_0hlul2ab_1_1 recid=16 stamp=736790860
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=cf_18_1 recid=17 stamp=736790870
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=archPRMDB1_736790884_19_%r recid=18 stamp=736790885
Crosschecked 18 objects
released channel: c1
/* RMAN验证备份片为'AVAILABLE'可用状态 */
/* 之后对生产库做了异机的不完全恢复 */
RMAN> run {
2> allocate channel c1 type sbt_tape parms 'ENV=(TDPO_OPTFILE=/usr/tivoli/tsm/client/oracle/bin64/tdpo.opt)';
3> restore controlfile;
4> release channel c1;
5> }
allocated channel: c1
channel c1: sid=321 devtype=SBT_TAPE
channel c1: Data Protection for Oracle: version 5.3.3.0
Starting restore at 03-DEC-10
channel c1: starting datafile backupset restore
channel c1: restoring control file
channel c1: reading from backup piece cf_18_1
channel c1: restored backup piece 1
piece handle=cf_18_1 tag=TAG20101203T160749
channel c1: restore complete, elapsed time: 00:00:35
output filename=/dev/rprm1dbg1_ctl1
output filename=/dev/rprm1dbg2_ctl1
output filename=/dev/rprm1dbg3_ctl1
Finished restore at 03-DEC-10
released channel: c1
RMAN> startup mount;
database is already started
database mounted
RMAN> run {
2> allocate channel c1 type sbt_tape parms 'ENV=(TDPO_OPTFILE=/usr/tivoli/tsm/client/oracle/bin64/tdpo.opt)';
3> set until time "to_timestamp('20101202 15:00:00','yyyymmdd hh24:mi:ss')";
4> restore database ;
5> recover database;
6> release channel c1;
7> }
allocated channel: c1
channel c1: sid=320 devtype=SBT_TAPE
channel c1: Data Protection for Oracle: version 5.3.3.0
executing command: SET until clause
Starting restore at 03-DEC-10
channel c1: starting datafile backupset restore
channel c1: specifying datafile(s) to restore from backup set
restoring datafile 00001 to /dev/rprm1dbg1_sys1
restoring datafile 00002 to /dev/rprm1dbg1_undo1
restoring datafile 00003 to /dev/rprm1dbg1_aux1
restoring datafile 00004 to /dev/rprm1dbg1_undo2
restoring datafile 00005 to /dev/rprm1dbg1_4g01
channel c1: reading from backup piece full_0cluhrqs_1_1
channel c1: restored backup piece 1
piece handle=full_0cluhrqs_1_1 tag=FULL_BACKUP
channel c1: restore complete, elapsed time: 00:09:46
Finished restore at 03-DEC-10
Starting recover at 03-DEC-10
starting media recovery
channel c1: starting archive log restore to default destination
channel c1: restoring archive log
archive log thread=2 sequence=10
channel c1: restoring archive log
archive log thread=1 sequence=9
channel c1: restoring archive log
archive log thread=2 sequence=11
channel c1: restoring archive log
archive log thread=1 sequence=10
channel c1: reading from backup piece archPRMDB1_736686125_15_%r
channel c1: restored backup piece 1
piece handle=archPRMDB1_736686125_15_%r tag=TAG20101202T110205
channel c1: restore complete, elapsed time: 00:00:03
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_1_9_736342307.dbf thread=1 sequence=9
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_2_10_736342307.dbf thread=2 sequence=10
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_2_11_736342307.dbf thread=2 sequence=11
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_1_10_736342307.dbf thread=1 sequence=10
channel c1: starting archive log restore to default destination
channel c1: restoring archive log
archive log thread=2 sequence=12
channel c1: restoring archive log
archive log thread=1 sequence=11
channel c1: reading from backup piece archPRMDB1_736790884_19_%r
channel c1: restored backup piece 1
piece handle=archPRMDB1_736790884_19_%r tag=TAG20101203T160804
channel c1: restore complete, elapsed time: 00:00:15
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_2_12_736342307.dbf thread=2 sequence=12
archive log filename=/oracle/admin/PRMDB1/arc/archPRMDB1_1_11_736342307.dbf thread=1 sequence=11
media recovery complete, elapsed time: 00:00:05
Finished recover at 03-DEC-10
released channel: c1
RMAN> alter database open;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of alter db command at 12/03/2010 17:06:52
ORA-01589: must use RESETLOGS or NORESETLOGS option for database open
RMAN> alter database open resetlogs;
database opened
new incarnation of database registered in recovery catalog
starting full resync of recovery catalog
full resync complete
alert.log:
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 1 of thread 1, type 32769 in header is not log file
ORA-00312: online log 1 thread 1: '/dev/rprm1dbg1_redo1'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 2 of thread 1, type 7 in header is not log file
ORA-00312: online log 2 thread 1: '/dev/rprm1dbg3_redo1'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 3 of thread 1, type 257 in header is not log file
ORA-00312: online log 3 thread 1: '/dev/rprm1dbg1_redo3'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 4 of thread 1, type 25902 in header is not log file
ORA-00312: online log 4 thread 1: '/dev/rprm1dbg3_redo3'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 5 of thread 1, type 49672 in header is not log file
ORA-00312: online log 5 thread 1: '/dev/rprm1dbg1_redo5'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 6 of thread 1, type 21317 in header is not log file
ORA-00312: online log 6 thread 1: '/dev/rprm1dbg3_redo5'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 7 of thread 2, type 65534 in header is not log file
ORA-00312: online log 7 thread 2: '/dev/rprm1dbg1_redo2'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 8 of thread 2, type 9506 in header is not log file
ORA-00312: online log 8 thread 2: '/dev/rprm1dbg3_redo2'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 9 of thread 2, type 65534 in header is not log file
ORA-00312: online log 9 thread 2: '/dev/rprm1dbg1_redo4'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 10 of thread 2, type 46 in header is not log file
ORA-00312: online log 10 thread 2: '/dev/rprm1dbg3_redo4'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 11 of thread 2, type 196 in header is not log file
ORA-00312: online log 11 thread 2: '/dev/rprm1dbg1_redo6'
Fri Dec 3 17:07:10 2010
Errors in file /oracle/admin/PRMDB1/udump/prmdb11_ora_221220.trc:
ORA-00367: checksum error in log file header
ORA-00316: log 12 of thread 2, type 1 in header is not log file
ORA-00312: online log 12 thread 2: '/dev/rprm1dbg3_redo6'
Fri Dec 3 17:07:10 2010
RESETLOGS after incomplete recovery UNTIL CHANGE 471235
Resetting resetlogs activation ID 575019235 (0x224618e3)
Fri Dec 3 17:08:02 2010
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo3.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo3.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
Fri Dec 3 17:08:29 2010
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo5.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo5.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
Fri Dec 3 17:09:26 2010
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo4.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo4.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
Fri Dec 3 17:09:53 2010
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo6.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo6.
WARNING: Oracle recommends creating new datafiles on devices with zero offset.
The command "/usr/sbin/mklv -y LVname -T O -w n -s n -r n VGname NumPPs" can be used.
Please contact Oracle customer support for more details.
Fri Dec 3 17:10:02 2010
Setting recovery target incarnation to 2
Fri Dec 3 17:10:02 2010
Hex dump of (file 201, block 1) in trace file /oracle/admin/PRMDB1/bdump/prmdb11_dbw0_618984.trc
Corrupt block relative dba: 0x00400001 (file 201, block 1)
Bad header found during data file header read
Data in bad block:
type: 1 format: 2 rdba: 0x000a9a18
last change scn: 0x8010.00005d87 seq: 0x73 flg: 0x4c
spare1: 0x0 spare2: 0x0 spare3: 0x8c
consistency value in tail: 0x374a4519
check value in block header: 0x0
computed block checksum: 0x0
Reread of rdba: 0x00400001 (file 201, block 1) found same corrupted data
Fri Dec 3 17:10:02 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_dbw0_618984.trc:
ORA-01186: file 201 failed verification tests
ORA-01122: database file 201 failed verification check
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
ORA-01210: data file header is media corrupt
File 201 not verified due to error ORA-01122
Fri Dec 3 17:10:02 2010
Assigning activation ID 575491153 (0x224d4c51)
LGWR: STARTING ARCH PROCESSES
ARC0 started with pid=32, OS id=160314
ARC1 started with pid=33, OS id=696818
Fri Dec 3 17:10:02 2010
ARC0: Archival started
ARC1: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
Thread 1 opened at log sequence 1
Current log# 1 seq# 1 mem# 0: /dev/rprm1dbg1_redo1
Current log# 1 seq# 1 mem# 1: /dev/rprm1dbg2_redo1
Successful open of redo thread 1
Fri Dec 3 17:10:03 2010
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Fri Dec 3 17:10:03 2010
ARC0: Becoming the 'no FAL' ARCH
ARC0: Becoming the 'no SRL' ARCH
Fri Dec 3 17:10:03 2010
ARC1: Becoming the heartbeat ARCH
Fri Dec 3 17:10:03 2010
SMON: enabling cache recovery
Fri Dec 3 17:10:04 2010
Successfully onlined Undo Tablespace 1.
Dictionary check beginning
Fri Dec 3 17:10:05 2010
Hex dump of (file 201, block 1) in trace file /oracle/admin/PRMDB1/bdump/prmdb11_dbw0_618984.trc
Corrupt block relative dba: 0x00400001 (file 201, block 1)
Bad header found during data file header read
Data in bad block:
type: 1 format: 2 rdba: 0x000a9a18
last change scn: 0x8010.00005d87 seq: 0x73 flg: 0x4c
spare1: 0x0 spare2: 0x0 spare3: 0x8c
consistency value in tail: 0x374a4519
check value in block header: 0x0
computed block checksum: 0x0
Reread of rdba: 0x00400001 (file 201, block 1) found same corrupted data
Fri Dec 3 17:10:05 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_dbw0_618984.trc:
ORA-01186: file 201 failed verification tests
ORA-01122: database file 201 failed verification check
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
ORA-01210: data file header is media corrupt
File 201 not verified due to error ORA-01122
Fri Dec 3 17:10:05 2010
Dictionary check complete
Fri Dec 3 17:10:05 2010
SMON: enabling tx recovery
Fri Dec 3 17:10:05 2010
Cannot re-create tempfile /dev/rprm1dbg1_tmp1, the same name file exists
Database Characterset is ZHS16GBK
Opening with internal Resource Manager plan
where NUMA PG = 1, CPUs = 16
replication_dependency_tracking turned off (no async multimaster replication found)
Starting background process QMNC
QMNC started with pid=35, OS id=623504
Fri Dec 3 17:10:07 2010
LOGSTDBY: Validating controlfile with logical metadata
Fri Dec 3 17:10:07 2010
LOGSTDBY: Validation complete
Completed: alter database open resetlogs
Fri Dec 3 17:10:16 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_j001_315982.trc:
ORA-01187: cannot read from file 201 because it failed verification tests
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
Fri Dec 3 17:10:16 2010
GATHER_STATS_JOB encountered errors. Check the trace file.
Fri Dec 3 17:10:16 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_j001_315982.trc:
ORA-01187: cannot read from file 201 because it failed verification tests
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
Fri Dec 3 17:10:16 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_j001_315982.trc:
ORA-01187: cannot read from file 201 because it failed verification tests
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
Fri Dec 3 17:10:19 2010
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_j001_315982.trc:
ORA-01187: cannot read from file 201 because it failed verification tests
ORA-01110: data file 201: '/dev/rprm1dbg1_tmp1'
以上因为是异机的不完全恢复，故原日志文件所在裸设备内没有任何信息，因此出现了
ORA-00367: checksum error in log file header 错误，可以忽略
之后Oracle将重用这些裸设备为日志文件
WARNING: You are creating/reusing datafile /dev/rprm1dbg4_redo3.
同样因为是异机恢复，临时文件所在裸设备内没有信息，会出现类似以下错误
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_dbw0_618984.trc:
ORA-01186: file 201 failed verification tests
ORA-01122: database file 201 failed verification check
ORA-01110: data file 201: ‘/dev/rprm1dbg1_tmp1’
ORA-01210: data file header is media corrupt
File 201 not verified due to error ORA-01122
….
Errors in file /oracle/admin/PRMDB1/bdump/prmdb11_j001_315982.trc:
ORA-01187: cannot read from file 201 because it failed verification tests
ORA-01110: data file 201: ‘/dev/rprm1dbg1_tmp1’
建议将原临时表空间删除，然后重建一个新的。
Comment