玉面飞龙的BLOG

这个问题是在作Online redef测试的时候碰见的，如果在primary执行START_REDEF_TABLE的时候，写错了目标表的名字，可能导致在logical standby上报这个错误然后导致apply停掉。并且该错误无法被skip。貌似bug.

SQL> create table large(id number primary key,text varchar(32) ) tablespace users;
Table created.

SQL> insert into large select object_id,object_name from dba_objects where object_id is not null;
72631 rows created.

SQL> create table TEST_NEW(id number primary key,text varchar(32) ) tablespace users2;
Table created.

SQL> exec dbms_redefinition.can_redef_table ( USER,’TEST’, DBMS_REDEFINITION.CONS_USE_PK) ;
PL/SQL procedure successfully completed.

然后执行START_REDEF_TABLE;如下敲错成“-”，自然会在primary上提示表large-new不存在。

exec dbms_redefinition.START_REDEF_TABLE ( USER, ‘LARGE’, ‘LARGE-NEW’, NULL, DBMS_REDEFINITION.CONS_USE_PK);

然后会在logical standby上碰见ORA-26808错误。

ORA-26808: Apply process AS00 died unexpectedly.
ORA-23481: unexpected name string “LARGE-NEW”

下面是logical standby上的日志，

Then on logical standby, when it parse “LARGE-NEW”, apply process died and report ORA-23481: unexpected name string “LARGE-NEW”.

————–alter.log on logical standby ———————

ALTER DATABASE START LOGICAL STANDBY APPLY IMMEDIATE
ALTER DATABASE START LOGICAL STANDBY APPLY (oradb)
with optional part
IMMEDIATE
Attempt to start background Logical Standby process
LOGSTDBY parameters set by user:
LOGSTDBY MAX_EVENTS_RECORDED = 2000000000
LOGSTDBY RECORD_UNSUPPORTED_OPERATIONS = TRUE
LOGSTDBY LOG_AUTO_DELETE = FALSE
LOGSTDBY PRESERVE_COMMIT_ORDER = FALSE
Thu Jun 03 08:26:11 2010
LSP0 started with pid=30, OS id=9363
Completed: ALTER DATABASE START LOGICAL STANDBY APPLY IMMEDIATE
LOGMINER: Parameters summary for session# = 5
LOGMINER: Number of processes = 3, Transaction Chunk Size = 201
LOGMINER: Memory Size = 30M, Checkpoint interval = 150M
LOGMINER: SpillScn 7930843, ResetLogScn 754488
LOGMINER: summary for session# = 5
LOGMINER: StartScn: 0 (0×0000.00000000)
LOGMINER: EndScn: 0 (0×0000.00000000)
LOGMINER: HighConsumedScn: 7930824 (0×0000.007903c8)
LOGMINER: session_flag 0×1
Thu Jun 03 08:26:12 2010
LOGMINER: session#=5, builder MS01 pid=32 OS id=9367 sid=34 started
Thu Jun 03 08:26:13 2010
LOGMINER: session#=5, reader MS00 pid=31 OS id=9365 sid=38 started
LOGMINER: Begin mining logfile for session 5 thread 1 sequence 321, /home/oracle/app/oradb/oradata/oradb/arch2/1_321_696990990.dbf
Thu Jun 03 08:26:13 2010
LSP2 started with pid=36, OS id=9371
Thu Jun 03 08:26:14 2010
LOGMINER: session#=5, preparer MS02 pid=35 OS id=9369 sid=51 started
Thu Jun 03 08:26:15 2010
LOGSTDBY Analyzer process AS00 started with server id=0 pid=37 OS id=9373
Thu Jun 03 08:26:15 2010
LOGSTDBY Apply process AS01 started with server id=1 pid=38 OS id=9375
Thu Jun 03 08:26:15 2010
LOGSTDBY Apply process AS03 started with server id=3 pid=36 OS id=9379
Thu Jun 03 08:26:15 2010
LOGSTDBY Apply process AS02 started with server id=2 pid=39 OS id=9377
Thu Jun 03 08:26:15 2010
LOGSTDBY Apply process AS04 started with server id=4 pid=42 OS id=9381
Thu Jun 03 08:26:16 2010
LOGSTDBY Apply process AS05 started with server id=5 pid=44 OS id=9383
LOGSTDBY Analyzer process AS00 server id=0 pid=37 OS id=9373 stopped
Errors in file /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_lsp0_9363.trc:
ORA-26808: Apply process AS00 died unexpectedly.
ORA-23481: unexpected name string “LARGE-NEW”
LOGSTDBY Apply process AS01 server id=1 pid=38 OS id=9375 stopped
LOGSTDBY Apply process AS02 server id=2 pid=39 OS id=9377 stopped
LOGSTDBY Apply process AS03 server id=3 pid=36 OS id=9379 stopped
LOGSTDBY Apply process AS04 server id=4 pid=42 OS id=9381 stopped
LOGSTDBY Apply process AS05 server id=5 pid=44 OS id=9383 stopped
Errors in file /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_as00_9373.trc:
ORA-23481: unexpected name string “LARGE-NEW”
LOGMINER: session#=5, reader MS00 pid=31 OS id=9365 sid=38 stopped
LOGMINER: session#=5, builder MS01 pid=32 OS id=9367 sid=34 stopped
LOGMINER: session#=5, preparer MS02 pid=35 OS id=9369 sid=51 stopped
LOGSTDBY status: ORA-16222: automatic Logical Standby retry of last action
LOGMINER: Parameters summary for session# = 5
LOGMINER: Number of processes = 3, Transaction Chunk Size = 201
LOGMINER: Memory Size = 30M, Checkpoint interval = 150M
LOGMINER: SpillScn 7930843, ResetLogScn 754488
LOGMINER: summary for session# = 5
LOGMINER: StartScn: 0 (0×0000.00000000)
LOGMINER: EndScn: 0 (0×0000.00000000)
LOGMINER: HighConsumedScn: 7930824 (0×0000.007903c8)
LOGMINER: session_flag 0×1
Thu Jun 03 08:26:18 2010
LOGMINER: session#=5, reader MS00 pid=31 OS id=9385 sid=38 started
Thu Jun 03 08:26:19 2010
LOGMINER: session#=5, builder MS01 pid=32 OS id=9387 sid=51 started
Thu Jun 03 08:26:19 2010
LOGMINER: session#=5, preparer MS02 pid=35 OS id=9389 sid=43 started
LOGMINER: Begin mining logfile for session 5 thread 1 sequence 321, /home/oracle/app/oradb/oradata/oradb/arch2/1_321_696990990.dbf
Thu Jun 03 08:26:20 2010
LOGSTDBY Apply process AS01 started with server id=1 pid=37 OS id=9393
Thu Jun 03 08:26:20 2010
LOGSTDBY Apply process AS02 started with server id=2 pid=38 OS id=9395
Thu Jun 03 08:26:20 2010
LOGSTDBY Apply process AS03 started with server id=3 pid=39 OS id=9397
Thu Jun 03 08:26:20 2010
LOGSTDBY Analyzer process AS00 started with server id=0 pid=36 OS id=9391
Thu Jun 03 08:26:20 2010
LOGSTDBY Apply process AS04 started with server id=4 pid=42 OS id=9399
Thu Jun 03 08:26:20 2010
LOGSTDBY Apply process AS05 started with server id=5 pid=44 OS id=9401
LOGSTDBY Analyzer process AS00 server id=0 pid=36 OS id=9391 stopped
Thu Jun 03 08:26:21 2010
Errors in file /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_lsp0_9363.trc:
ORA-26808: Apply process AS00 died unexpectedly.
ORA-23481: unexpected name string “LARGE-NEW”
LOGSTDBY Apply process AS01 server id=1 pid=37 OS id=9393 stopped
LOGSTDBY Apply process AS02 server id=2 pid=38 OS id=9395 stopped
LOGSTDBY Apply process AS03 server id=3 pid=39 OS id=9397 stopped
LOGSTDBY Apply process AS04 server id=4 pid=42 OS id=9399 stopped
LOGSTDBY Apply process AS05 server id=5 pid=44 OS id=9401 stopped
Errors in file /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_as00_9391.trc:
ORA-23481: unexpected name string “LARGE-NEW”
LOGMINER: session#=5, reader MS00 pid=31 OS id=9385 sid=38 stopped
LOGMINER: session#=5, builder MS01 pid=32 OS id=9387 sid=51 stopped
LOGMINER: session#=5, preparer MS02 pid=35 OS id=9389 sid=43 stopped
———————————————————————————————–

cat /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_as00_9391.trc

*** 2010-06-03 08:26:22.065
ORA-23481: unexpected name string “LARGE-NEW”
OPIRIP: Uncaught error 447. Error stack:
ORA-00447: fatal error in background process
ORA-23481: unexpected name string “LARGE-NEW”

—————————————————————————————————

cat /home/oracle/app/oradb/diag/rdbms/standby/oradb/trace/oradb_lsp0_9363.trc

*** 2010-06-03 08:26:21.980
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0×0, level=0, mask=0×0)
—– Error Stack Dump —–
ORA-26808: Apply process AS00 died unexpectedly.
ORA-23481: unexpected name string “LARGE-NEW”
KNACDMP: *******************************************************
KNACDMP: Dumping apply coordinator’s context at bfc99c94
KNACDMP: Apply Engine # 0
KNACDMP: Apply Engine name
KNACDMP: Coordinator’s Watermarks ——————————
KNACDMP: Apply High Watermark = 0000007903c8 (SCN=0×0000.007903c8)
KNACDMP: Apply Low Watermark = 0000007903c8 (SCN=0×0000.007903c8)
KNACDMP: Recovery Low Watermark = 0000007903c8 (SCN=0×0000.007903c8)
KNACDMP: Fetch Low Watermark = (SCN=0×0000.00000000)
KNACDMP: Fetch Low Watermark Time = 0
KNACDMP: Oldest SCN = (SCN=0×0000.00000000)
KNACDMP: Oldest XID =
KNACDMP: Oldest Create Time = 0
KNACDMP: Last replicant syncpoint SCN = 0×0000.00000000
KNACDMP: Last syncpoint at primary SCN = 0×0000.00000000
KNACDMP: First partition max pos = 000000799b61 (SCN=0×0000.00799b61)
KNACDMP: Last partition max pos = 000000799b61 (SCN=0×0000.00799b61)
KNACDMP: Last processed = 0000007903d7 (SCN=0×0000.007903d7)
KNACDMP: Conservative pos = 0000007903d7 (SCN=0×0000.007903d7)
KNACDMP: Recovery start pos = (SCN=0×0000.00000000)
KNACDMP: Recovery high watermark = 0000007903c8 (SCN=0×0000.007903c8)
KNACDMP: Spill LWM = (SCN=0×0000.00000000)
KNACDMP: Spill LWM Create Time = 0
KNACDMP: Coordinator’s constants ——————————-
KNACDMP: number of apply slaves = 5
KNACDMP: safety level (K) = 1
KNACDMP: max txns in memory = 1200
KNACDMP: max constraints per table = 653
KNACDMP: hash table size (in entries) = 1000000
KNACDMP: Coordinator’s intervals ——————————-
KNACDMP: syncpoint interval (ms) = 4294967295
KNACDMP: write low watermark interval(ms)= 1
KNACDMP: Coordinator’s timers/counters ————————-
KNACDMP: current time = 1275524781
KNACDMP: low watermark timer = 0
KNACDMP: syncpoint timer = 1275524780
KNACDMP: txnbufsize timer = 1275524780
KNACDMP: Coordinator’s txn counts ————————-
KNACDMP: total txns applied = 0
KNACDMP: number of unassigned txns = 0
KNACDMP: avg number of unassigned txns = 0.00
KNACDMP: total applied at last plwm write= 0
KNACDMP: apply prog. entries below plwm = 0
KNACDMP: total unassigned lcrs = 0
KNACDMP: Coordinator’s State/Flags —————————–
KNACDMP: Coordinator’s State = KNACST_APPLY_UNTIL_END
KNACDMP: Coordinator’s Flags = 0×8200
KNACDMP: Slave counts ——————————————
KNACDMP: number of reserved slaves = 1
KNACDMP: number of admin slaves = 0
KNACDMP: number of slaves in wait cmt = 0
KNACDMP: number of slaves suspended = 0
KNACDMP: number of safe slaves = 0
KNACDMP: avg number of idle slaves = 0.00
KNACDMP: number of slaves initializing = 0
KNACDMP: number of slaves terminating = 0
KNACDMP: Slave Lists ——————————————-
KNACDMP: Dumping All Slaves :-
Slave id = 0, State = 8, Flags = 0, Not Assigned
Slave id = 1, State = 0, Flags = 0, Not Assigned
Slave id = 2, State = 0, Flags = 0, Not Assigned
Slave id = 3, State = 0, Flags = 0, Not Assigned
Slave id = 4, State = 0, Flags = 0, Not Assigned
Slave id = 5, State = 0, Flags = 0, Not Assigned
KNACDMP: End dumping all slaves
KNACDMP: syncdep slaves = { }
KNACDMP: cont chunk slaves = { }
KNACDMP: cont slaves = { }
KNACDMP: exec txn slaves = { }
KNACDMP: Active slaves (0) = { }
KNACDMP: Idle slaves (5) = { 1 2 3 4 5 }
KNACDMP: Txn Lists ———————————————
KNACDMP: Dumping all txns :-
KNACDMP: End dumping all txns.
KNACDMP: Complete txns = { ** NO UNASS ** }
KNACDMP: Unassigned txns = { }
KNACDMP: *******************************************************

*** 2010-06-03 08:26:25.156
Warning: Apply error received: ORA-26714: User error encountered while applying. Clearing.
=====================

事件视图DBA_LOGSTDBY_EVENTS中没有记录任何有用的信息。
如下等各种方法都无法skip该错误, SQL apply进程无法启动。

exec dbms_logstdby.SKIP_ERROR(’TABLE’,'BINZHANG’,'%’,null);
exec dbms_logstdby.SKIP_ERROR(’NON_SCHEMA_DDL’,'BINZHANG’,'LARGE_NEW’,null);
exec dbms_logstdby.SKIP_ERROR(’SCHEMA_DLL’,'BINZHANG’,'LARGE_NEW’,null);
EXECUTE DBMS_LOGSTDBY.SKIP (stmt => ‘DML’, schema_name => ‘BINZHANG’, object_name => ‘%’, proc_name => null);
EXECUTE DBMS_LOGSTDBY.SKIP (stmt => ‘SCHEMA_DLL’, schema_name => ‘BINZHANG’, object_name => ‘%’, proc_name => null);
EXECUTE DBMS_LOGSTDBY.SKIP (stmt => ‘NON_SCHEMA_DDL’, schema_name => ‘BINZHANG’, object_name => ‘%’, proc_name => null);

测试环境:oracle11gR2 redhat5.