又遇到一次logic standby的问题

By banping On 2009/09/28 · 3 Comments · In Oracle

主库传到备库的日志发生了滞留，在DBA_LOGSTDBY_LOG视图发现大量的日志没有应用，而正在APPLY的只有几条，这说明不是大事务导致的延迟。以前经常是特殊的DDL语句导致的阻塞，而这次在DBA_LOGSTDBY_EVENTS视图并没有发现可疑的DDL操作。

尝试停止APPLY，可是却迟迟没有响应：

SQL> alter database stop logical standby apply;
^Calter database stop logical standby apply
*
ERROR at line 1:
ORA-01013: user requested cancel of current operation

这时备库的日志记录了如下的信息：

Sun Sep 27 17:30:04 2009
alter database stop logical standby apply
Sun Sep 27 17:30:04 2009
ALTER DATABASE STOP LOGICAL STANDBY APPLY
Sun Sep 27 17:30:05 2009
LOGSTDBY: Shutdown acknowledged

Sun Sep 27 17:36:12 2009
ORA-1013 signalled during: alter database stop logical standby apply...

此时并没有停掉应用，尝试ABORT停止：

SQL> alter database abort logical standby apply;

Database altered.

日志记录了如下的信息：

Sun Sep 27 20:02:43 2009
ALTER DATABASE ABORT LOGICAL STANDBY APPLY
Sun Sep 27 20:02:44 2009
LOGSTDBY: Shutdown acknowledged
LOGSTDBY Analyzer process P006 pid=39 OS id=479250 stopped
LOGSTDBY Apply process P008 pid=43 OS id=381224 stopped
LOGSTDBY Apply process P011 pid=46 OS id=270744 stopped
LOGSTDBY Apply process P018 pid=53 OS id=315748 stopped
LOGSTDBY Apply process P009 pid=44 OS id=373196 stopped
LOGSTDBY Apply process P022 pid=89 OS id=409732 stopped
LOGSTDBY Apply process P025 pid=92 OS id=467268 stopped
LOGSTDBY Apply process P023 pid=90 OS id=278898 stopped
LOGSTDBY Apply process P012 pid=47 OS id=438534 stopped
LOGSTDBY Apply process P010 pid=45 OS id=299266 stopped
LOGSTDBY Apply process P021 pid=88 OS id=176472 stopped
LOGSTDBY Apply process P019 pid=72 OS id=421888 stopped
LOGSTDBY Apply process P007 pid=41 OS id=458914 stopped
LOGSTDBY Apply process P026 pid=93 OS id=410074 stopped
LOGSTDBY Apply process P020 pid=87 OS id=291214 stopped
LOGSTDBY Apply process P024 pid=91 OS id=397640 stopped
LOGSTDBY Apply process P013 pid=48 OS id=487712 stopped
LOGSTDBY Apply process P017 pid=52 OS id=401700 stopped
LOGSTDBY Apply process P014 pid=49 OS id=405806 stopped
LOGSTDBY Apply process P015 pid=50 OS id=586094 stopped
Sun Sep 27 20:03:43 2009
LOGSTDBY status: ORA-16128: User initiated stop apply successfully completed
Sun Sep 27 20:04:49 2009
Completed: alter database abort logical standby apply

再尝试开启应用，仍然没有反应：

SQL> alter database start logical standby apply;
^Calter database start logical standby apply
*
ERROR at line 1:
ORA-01013: user requested cancel of current operation

日志显示apply engine已经在运行，看来没有办法停掉它：

Sun Sep 27 20:06:56 2009
ALTER DATABASE START LOGICAL STANDBY APPLY (banpingbkdb)
Sun Sep 27 20:06:56 2009
No optional part
Attempt to start background Logical Standby process
LSP0 started with pid=21, OS id=655544
LOGSTDBY status: ORA-16084: an apply engine is already running
Sun Sep 27 20:06:57 2009
Errors in file /u01/admin/banpingbkdb/bdump/banpingbkdb_lsp0_655544.trc:
ORA-16084: an apply engine is already running
LOGSTDBY status: ORA-16222: automatic Logical Standby retry of last action
LOGSTDBY status: ORA-16084: an apply engine is already running
Sun Sep 27 20:06:57 2009
Errors in file /u01/admin/banpingbkdb/bdump/banpingbkdb_lsp0_655544.trc:
ORA-16084: an apply engine is already running

现在stop可以了：

SQL>
SQL> alter database stop logical standby apply;

Database altered.

但是再开启仍然不行，apply engine一直在运行。没有什么好办法，重启备库的instance吧：

SQL> alter database stop logical standby apply;

Database altered.

SQL> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.

在重启的过程中也等待了很久，日志如下：

Sun Sep 27 20:24:04 2009
Starting background process EMN0
EMN0 started with pid=21, OS id=536826
Sun Sep 27 20:24:04 2009
Shutting down instance: further logons disabled
Sun Sep 27 20:24:04 2009
Stopping background process CJQ0
Sun Sep 27 20:24:04 2009
Stopping background process MMNL
Sun Sep 27 20:24:05 2009
Stopping background process MMON
Sun Sep 27 20:24:06 2009
Shutting down instance (immediate)
License high water mark = 98
Sun Sep 27 20:24:06 2009
Stopping Job queue slave processes
Sun Sep 27 20:24:06 2009
Job queue slave processes stopped
Sun Sep 27 20:29:05 2009
Active call for process 557346 user 'oracle' program 'oracle@p55a (P016)'
SHUTDOWN: waiting for active calls to complete.

似乎一直在等待这个process 557346，于是直接kill之：

# ps -ef | grep 557346
root 606208 528518 0 20:46:00 pts/3 0:00 grep 557346
oracle 557346 1 93 Aug 27 - 1018:44 ora_p016_banpingbkdb
# kill -9 557346

然后就顺利的关掉了：

Sun Sep 27 20:43:57 2009
MMNL absent for 1203 secs; Foregrounds taking over
Sun Sep 27 20:46:20 2009
All dispatchers and shared servers shutdown
Sun Sep 27 20:46:20 2009
Process OS id : 643398 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:21 2009
Process OS id : 696622 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:22 2009
Process OS id : 606694 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:23 2009
Process OS id : 647260 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:23 2009
Process OS id : 536932 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:24 2009
Process OS id : 372796 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:24 2009
Process OS id : 348212 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:25 2009
Process OS id : 430426 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:26 2009
Process OS id : 634944 alive after kill
Errors in file /u01/admin/banpingbkdb/udump/banpingbkdb_ora_610574.trc
Sun Sep 27 20:46:27 2009
ALTER DATABASE CLOSE NORMAL
Sun Sep 27 20:46:41 2009
SMON: disabling tx recovery
SMON: disabling cache recovery
Sun Sep 27 20:46:48 2009
Shutting down archive processes
Archiving is disabled
Sun Sep 27 20:46:53 2009
ARCH shutting down
ARC1: Archival stopped
Sun Sep 27 20:46:58 2009
ARCH shutting down
ARC0: Archival stopped
Sun Sep 27 20:46:59 2009
Thread 1 closed at log sequence 43105
Successful close of redo thread 1
Sun Sep 27 20:47:02 2009
Completed: ALTER DATABASE CLOSE NORMAL
Sun Sep 27 20:47:02 2009
ALTER DATABASE DISMOUNT
Sun Sep 27 20:47:02 2009
SUCCESS: diskgroup DATA was dismounted
Sun Sep 27 20:47:02 2009
Completed: ALTER DATABASE DISMOUNT
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active

然后再启动实例：

SQL> startup
ORACLE instance started.

Total System Global Area 1.0737E+10 bytes
Fixed Size                  2090664 bytes
Variable Size            3707767128 bytes
Database Buffers         7012876288 bytes
Redo Buffers               14684160 bytes
Database mounted.
Database opened.
SQL> alter database start logical standby apply;

Database altered.

再查看日志，logic standby终于恢复了正常。

启动的日志也记录一下吧：

Sun Sep 27 20:48:13 2009
Starting ORACLE instance (normal)
Sun Sep 27 20:48:29 2009
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on.
IMODE=BR
ILAT =121
LICENSE_MAX_USERS = 0
SYS auditing is disabled
ksdpec: called for event 13740 prior to event group initialization
Starting up ORACLE RDBMS Version: 10.2.0.3.0.
System parameters with non-default values:
processes                = 1000
lock_sga                 = TRUE
__shared_pool_size       = 3623878656
__large_pool_size        = 16777216
__java_pool_size         = 16777216
__streams_pool_size      = 50331648
streams_pool_size        = 50331648
nls_language             = AMERICAN
nls_territory            = CHINA
nls_length_semantics     = BYTE
resource_manager_plan    =
sga_target               = 10737418240
control_files            = +DATA/banpingbkdb/controlfile/db_control1, +DATA/banpingbkdb/controlfile/db_control2, +DATA/banpingbkdb/controlfile/db_control3
db_file_name_convert     = /dev, +DATA/banpingbkdb/datafile
log_file_name_convert    = /dev, +DATA/banpingbkdb/onlinelog
db_block_size            = 8192
__db_cache_size          = 7012876288
compatible               = 10.2.0.1.0
log_archive_config       = DG_CONFIG=(cnderpdb, banpingbkdb)
log_archive_dest_1       = LOCATION=/ora_arch/ VALID_FOR=(ONLINE_LOGFILE,ALL_ROLES) DB_UNIQUE_NAME=banpingbkdb
log_archive_dest_2       = SERVICE=cnderpdb1 VALID_FOR=(ONLINE_LOGFILES,PRIMARY_ROLE) DB_UNIQUE_NAME=cnderpdb
log_archive_dest_3       = LOCATION=/stb_arch/ VALID_FOR=(STANDBY_LOGFILE,STANDBY_ROLE) DB_UNIQUE_NAME=banpingbkdb
log_archive_format       = %t_%s_%r.dbf
fal_client               = banpingbkdb
fal_server               = CNDERPDB1, CNDERPDB2
db_file_multiblock_read_count= 16
standby_file_management = MANUAL
undo_management          = AUTO
undo_tablespace          = UNDOTBS1
undo_retention           = 900
remote_login_passwordfile= EXCLUSIVE
db_domain                = chinacdc.com
dispatchers              = (PROTOCOL=TCP) (SERVICE=banpingbkdbXDB)
job_queue_processes      = 10
background_dump_dest     = /u01/admin/banpingbkdb/bdump
user_dump_dest           = /u01/admin/banpingbkdb/udump
core_dump_dest           = /u01/admin/banpingbkdb/cdump
audit_file_dest          = /u01/admin/banpingbkdb/adump
session_max_open_files   = 20
db_name                  = banpingbkdb
db_unique_name           = banpingbkdb
open_cursors             = 300
pga_aggregate_target     = 2147483648
aq_tm_processes          = 0
PMON started with pid=2, OS id=639102
PSP0 started with pid=3, OS id=672098
MMAN started with pid=4, OS id=545050
DBW0 started with pid=5, OS id=655710
DBW1 started with pid=6, OS id=635230
LGWR started with pid=7, OS id=627006
CKPT started with pid=8, OS id=643408
SMON started with pid=9, OS id=610492
RECO started with pid=10, OS id=614748
CJQ0 started with pid=11, OS id=274744
MMON started with pid=12, OS id=589914
Sun Sep 27 20:48:29 2009
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
MMNL started with pid=13, OS id=696642
Sun Sep 27 20:48:29 2009
starting up 1 shared server(s) ...
Sun Sep 27 20:48:30 2009
ALTER DATABASE   MOUNT
Sun Sep 27 20:48:30 2009
Starting background process ASMB
ASMB started with pid=17, OS id=524414
Starting background process RBAL
RBAL started with pid=18, OS id=299234
Sun Sep 27 20:48:34 2009
SUCCESS: diskgroup DATA was mounted
Sun Sep 27 20:48:38 2009
Setting recovery target incarnation to 2
Using STANDBY_ARCHIVE_DEST parameter default value as /stb_arch/
Sun Sep 27 20:48:38 2009
Successful mount of redo thread 1, with mount id 1040980254
Sun Sep 27 20:48:38 2009
Database mounted in Exclusive Mode
Completed: ALTER DATABASE   MOUNT
Sun Sep 27 20:48:38 2009
ALTER DATABASE OPEN
Sun Sep 27 20:48:39 2009
LGWR: STARTING ARCH PROCESSES
ARC0 started with pid=20, OS id=467272
Sun Sep 27 20:48:39 2009
ARC0: Archival started
ARC1: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC1 started with pid=21, OS id=418070
Sun Sep 27 20:48:39 2009
ARC0: Becoming the 'no FAL' ARCH
Sun Sep 27 20:48:39 2009
ARC0: Becoming the 'no SRL' ARCH
Sun Sep 27 20:48:39 2009
ARC1: Becoming the heartbeat ARCH
Sun Sep 27 20:48:39 2009
Thread 1 opened at log sequence 43105
Current log# 4 seq# 43105 mem# 0: +DATA/banpingbkdb/onlinelog/rdb_redo1_4
Successful open of redo thread 1
Sun Sep 27 20:48:39 2009
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Sun Sep 27 20:48:39 2009
SMON: enabling cache recovery
Sun Sep 27 20:48:40 2009
Successfully onlined Undo Tablespace 1.
Sun Sep 27 20:48:40 2009
SMON: enabling tx recovery
Sun Sep 27 20:48:40 2009
Database Characterset is ZHS16GBK
replication_dependency_tracking turned off (no async multimaster replication found)
WARNING: AQ_TM_PROCESSES is set to 0. System operation might be adversely affected.
Completed: ALTER DATABASE OPEN
Sun Sep 27 20:50:41 2009
alter database start logical standby apply
Sun Sep 27 20:50:42 2009
ALTER DATABASE START LOGICAL STANDBY APPLY (banpingbkdb)
Sun Sep 27 20:50:42 2009
No optional part
Attempt to start background Logical Standby process
LSP0 started with pid=24, OS id=561496
Sun Sep 27 20:50:42 2009
LOGSTDBY Parameter:                        MAX_SGA = 1000
LOGSTDBY Parameter:                    MAX_SERVERS = 27
Completed: alter database start logical standby apply