Oracle物理备库RFS进程消失，不能启动--解决

tily

今天在测试Oracle环境上做热备，发现RFS进程不存在，做了如下操作后，还是不行：

1、拷贝主库的密码文件到备库

2、重启备库，也重启了主库，并alter system switch logfile;切换日志

3、未发现主库与备库的gap，监听也正常

备库似乎一切正常，但是就是RFS进程不存在，主库的归档日志没有传输到备库

倒是在备库里有个错误提示：

   
Sun May 25 21:24:09 2014
Errors in file /oracle/admin/dbcc/bdump/dbcc_mrp0_2596.trc:
ORA-16037: user requested cancel of managed recovery operation
Recovery interrupted!

查看跟踪文件

   
[oracle@sdk32 dbs]$ more /oracle/admin/dbcc/bdump/dbcc_mrp0_2596.trc
/oracle/admin/dbcc/bdump/dbcc_mrp0_2596.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /oracle/product/10.2.0/db_1
System name:    Linux
Node name:      sdk32
Release:        2.6.32-279.el6.i686
Version:        #1 SMP Fri Jun 22 10:59:55 UTC 2012
Machine:        i686
Instance name: dbcc
Redo thread mounted by this instance: 1
Oracle process number: 18
Unix process pid: 2596, image: oracle@sdk32 (MRP0)

*** SERVICE NAME:() 2014-05-25 21:13:39.499
*** SESSION ID:(153.1) 2014-05-25 21:13:39.499
ARCH: Connecting to console port...
*** 2014-05-25 21:13:39.500 62692 kcrr.c
MRP0: Background Managed Standby Recovery process started
*** 2014-05-25 21:13:44.500 1118 krsm.c
Managed Recovery: Initialization posted.
*** 2014-05-25 21:13:44.500 62692 kcrr.c
Managed Standby Recovery not using Real Time Apply
Recovery target incarnation = 2, activation ID = -1741977668
Influx buffer limit = 11227 (50% x 22455)
Successfully allocated 2 recovery slaves
Using 543 overflow buffers per recovery slave
Start recovery at thread 1 ckpt scn 15793487 logseq 872 block 2
*** 2014-05-25 21:13:44.579
Media Recovery add redo thread 1
*** 2014-05-25 21:13:44.579 1118 krsm.c
Managed Recovery: Active posted.
*** 2014-05-25 21:13:44.587 62692 kcrr.c
Media Recovery Waiting for thread 1 sequence 872
*** 2014-05-25 21:24:09.713
*** 2014-05-25 21:24:09.713 62692 kcrr.c
MRP0: Background Media Recovery cancelled with status 16037
<span style="color: #ff0000;">ORA-16037: user requested cancel of managed recovery operation</span>
*** 2014-05-25 21:24:09.713
Media Recovery drop redo thread 1
*** 2014-05-25 21:24:11.179 1118 krsm.c
Managed Recovery: Not Active posted.
<span style="color: #ff0000;">ORA-16037: user requested cancel of managed recovery operation</span>
ARCH: Connecting to console port...
*** 2014-05-25 21:24:11.182 62692 kcrr.c
MRP0: Background Media Recovery process shutdown
*** 2014-05-25 21:24:11.182 1118 krsm.c

查了下对应的ORA错误资料，也未见特别的说明。

于是检查下主库参数：

   
SQL> show parameter log_archive_dest_state_2;

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
log_archive_dest_state_2             string      defer

为什么这个参数被设置为了defer，原来是之前做了测试忘改回来了
   
SQL> ALTER system SET log_archive_dest_state_2 = '<span style="color: #ff0000;">enable</span>';

系统已更改。

SQL> show parameter log_archive_dest_state_2;

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
log_archive_dest_state_2             string      enable

改回来后，备库alert日志立马开始响应，RFS进程起来了：

   
Sun May 25 21:54:32 2014
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[1]: Assigned to RFS process 2816
RFS[1]: Identified database type as 'physical standby'
Sun May 25 21:54:32 2014
<span style="color: #ff0000;">RFS LogMiner: Client disabled from further notification
RFS[1]: Archived Log: '/archive/1_876_847917566.dbf'
RFS[1]: Archived Log: '/archive/1_877_847917566.dbf'
RFS[1]: Archived Log: '/archive/1_878_847917566.dbf'</span>
Sun May 25 21:54:35 2014
Fetching gap sequence in thread 1, gap sequence 875-875
Sun May 25 21:54:45 2014
RFS[1]: Archived Log: '/archive/1_879_847917566.dbf'
Sun May 25 21:54:58 2014
RFS[1]: Archived Log: '/archive/1_880_847917566.dbf'
Sun May 25 21:55:11 2014
RFS[1]: Archived Log: '/archive/1_881_847917566.dbf'
Sun May 25 21:55:24 2014
RFS[1]: Archived Log: '/archive/1_882_847917566.dbf'
Sun May 25 21:55:36 2014
RFS[1]: Archived Log: '/archive/1_883_847917566.dbf'
Sun May 25 21:55:49 2014
RFS[1]: Archived Log: '/archive/1_884_847917566.dbf'
Sun May 25 21:56:04 2014
RFS[1]: Archived Log: '/archive/1_885_847917566.dbf'
Sun May 25 21:56:18 2014
RFS[1]: Archived Log: '/archive/1_886_847917566.dbf'
Sun May 25 21:56:31 2014
RFS[1]: Archived Log: '/archive/1_887_847917566.dbf'

最后再次检查主库与备库的同步情况

主库查询归档日志切换情况：

   
SQL> select group#,sequence#,status,first_time,to_char(first_change#) as begin_scn <br>     from v$log order by group# asc;

    GROUP#  SEQUENCE# STATUS           FIRST_TIME     BEGIN_SCN
---------- ---------- ---------------- -------------- ----------------------------------------
         1        898 CURRENT          25-5月 -14     16021321
         2        896 INACTIVE         25-5月 -14     15926616
         3        897 ACTIVE           25-5月 -14     15973241

备库查询归档日志切换情况：

   
SQL> select process,status,thread#,sequence#,block#,blocks from V$managed_standby order by 1,4;

PROCESS   STATUS          THREAD#  SEQUENCE#     BLOCK#     BLOCKS
--------- ------------ ---------- ---------- ---------- ----------
ARCH      CONNECTED             0          0          0          0
ARCH      CONNECTED             0          0          0          0
MRP0      WAIT_FOR_LOG          1        898          0          0
RFS       IDLE                  0          0          0          0

OK，由于部署了一些测试应用，归档日志已经从刚开始时候的878切换到了898

总结：遇到问题要冷静思考可能的原因，Oracle10g的Dataguard还算是比较稳定的，注意检查核心的参数是否有变化。