前几天碰到一个看起来有些奇怪的例子,今天抽空把分析过程整理了一下。
有一主一备的一套测试环境,之前环境在我手里,交给另外一个同事之后,重新搭建了dataguard,我检查了一圈,发现都没有问题,然后过了一个星期的样子,无意中再次查看的时候,发现这个备库竟然在dg broker中的状态是disable,当然我也不能看到这个现象就反问同事,说当时dataguard怎么有这种低级操作问题。我想了想,根据我的印象,当时也确实是搭建成功了。这些天这个主库也从来没有任何的操作,zabbix也一直没有相关的报警,这个问题引起了我的兴趣,我们来查一查。
大体的架构环境是这样的,有两台独立的测试环境,目前因为schema有一些重合,没有整合到一起,因为平时的负载极小,而且存在单点故障,就把原来的逻辑备份方式改成了dataguard。这样我们基本就从这些逻辑备份校验中解放出来了。因为平时负载小,使用率不高,所以就把备库都搭建到了同一个台服务器上。
这次dg broker校验出问题的是test1的主库
现象就是:
DGMGRL> show configuration;
Configuration - testdb_dg
Protection Mode: MaxPerformance
Databases:
sactvdb - Primary database
s2actvdb - Physical standby database (disabled)
Fast-Start Failover: DISABLED
Configuration Status:
SUCCESS
当时的处理思路是尝试enable,结果抛错了。
DGMGRL> enable database s2actvdb;
Error: ORA-16631: operation requires shutdown of database or instance ""
Failed.
DGMGRL> show database verbose s2actvdb;
Database - s2actvdb
Role: PHYSICAL STANDBY
Intended State: OFFLINE
Transport Lag: (unknown)
Apply Lag: (unknown)
Real Time Query: OFF
Instance(s):
actvdb
Properties:
DGConnectIdentifier = 's2actvdb'
ObserverConnectIdentifier = ''
LogXptMode = 'ASYNC'
DelayMins = '0'
Binding = 'optional'
MaxFailure = '0'
MaxConnections = '1'
...
InconsistentProperties = '(monitor)'
InconsistentLogXptProps = '(monitor)'
SendQEntries = '(monitor)'
LogXptStatus = '(monitor)'
RecvQEntries = '(monitor)'
SidName = 'actvdb'
StaticConnectIdentifier = '(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=xxxx)(PORT=1528))(CONNECT_DATA=(SERVICE_NAME=s2actvdb_DGMGRL)(INSTANCE_NAME=actvdb)(SERVER=DEDICATED)))'
StandbyArchiveLocation = 'USE_DB_RECOVERY_FILE_DEST'
AlternateLocation = ''
LogArchiveTrace = '0'
LogArchiveFormat = '%t_%s_%r.dbf'
TopWaitEvents = '(monitor)'
Database Status:
SHUTDOWN
然后尝试设置备库为online
DGMGRL> edit database s2actvdb set state='ONLINE';
Error: ORA-16525: the Data Guard broker is not yet available
Failed.
这个时候虽然抛错,dg broker的校验结果却发生了变化。
DGMGRL> show configuration;
Configuration - testdb_dg
Protection Mode: MaxPerformance
Databases:
sactvdb - Primary database
s2actvdb - Physical standby database
Error: ORA-16525: the Data Guard broker is not yet available
Fast-Start Failover: DISABLED
Configuration Status:
ERROR
然后折腾了一番,发现原因是log_archive_dest_state_2的值为RESET,重新置为ENABLE之后就没有问题了。
那么问题就来了,为什么这个地方的值变为了reset。
经过一番排查,发现这台服务器中的备库1在本周重启了,而且还是在nomount阶段。
当然这个问题还是很好定位,最后发现是同事搭建test2的备库的时候,无意中碰到了test1的备库,做了重启的操作。
那么就问题而言,就更奇怪了,先不说重启备库的操作失误,就技术角度而言,重启备库会直接导致log_archive_dest_state_2为reset,到底是什么原因导致这种情况发生。
于是开始翻找日志的一些痕迹。
RESET相关的日志为:
TNS-12564: TNS:connection refused
ns secondary err code: 0
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
Tue Mar 22 17:53:59 2016
ALTER SYSTEM SET log_archive_dest_state_2='RESET' SCOPE=BOTH;
在置为RESET之前出现了网络连接问题,时间点就是备库重启的时间,看起来确实是备库重启导致的,为什么会有这个特殊的内部操作呢。
准备再次复现这个问题,但是重启之后再就没有出现这个问题。
问题虽然解决了,但是这个问题就一直在脑海中萦绕,因为我还没有找到问题的根本原因。为了进一步验证,我开始准备急需查看更多的日志,尝试复现这个问题。