首页 » ORACLE 9i-23c » Oracle 11g Active DataGuard(ADG) 优化及 duplicate hang 诊断案例

Oracle 11g Active DataGuard(ADG) 优化及 duplicate hang 诊断案例

前段时间因为硬件原因,standby DB crash,主库删除了日志且无备份,后期需要重建,该环境是主备两套11.2.0.3 2-NODES RAC ON EXADATA Machine ,存储在ASM, 数据库70TB 大小, 闲时每天1T归档日志, 忙时每天可达4T+归档, 之前朋友重建DG一直使用主机上一个shell 放后台,我查看了该shell 确实不算复杂,但是duplicate 一直hang在开始。下面我只是简单记录一下这个过程,及后期的DATAGUARD 相关的一些优化细节。因为数据库太大,这里使用了duplicate for standby from active DATAbase, 另个每天日志产生量大,所以在空间有限的情况下要格外注意速度。

附一下shell的调用

1,create pfile (not using spfile)
DB_NAME=orarpt
DB_UNIQUE_NAME=rptstby
DB_BLOCK_SIZE=16384

2, shell adg_setup.sh

export ORACLE_SID=orarpt2
rman msglog /home/oracle/work/adg_setup.log << EOF
connect target sys/xxxxxx@rptpri2
connect auxiliary sys/xxxxx@rptstby

run {
allocate channel ch001 type disk;
allocate channel ch002 type disk;
allocate channel ch003 type disk;
allocate channel ch004 type disk;
allocate channel ch006 type disk;
allocate channel ch007 type disk;
allocate channel ch008 type disk;
allocate auxiliary channel ch005 type disk;

duplicate target DATAbase for standby from active database NOFILENAMECHECK
spfile
  set db_unique_name 'rptstby'
  set db_create_file_dest '+DATA'
  set standby_file_management 'AUTO'
  set remote_listener 'anbob-scan:1521'
  set log_archive_dest_2 ''
  set log_archive_dest_state_2 'DEFER'
  set fal_server 'rptpri1','rptpri2'
  set fal_client 'rptstby'
  set control_files='+DATA/RPTSTBY/CONTROLFILE/ctrl1','+DATA/RPTSTBY/CONTROLFILE/ctrl2'
  set audit_file_dest '/oracle/app/oracle/admin/rptstby/adump'
;
release channel ch001;
release channel ch002;
release channel ch003;
release channel ch004;
release channel ch005;
release channel ch006;
release channel ch007;
release channel ch008;
}

EOF

Tip:

调用很简单nohup 放到后台,但是查看日志, 它睡的好沉…

...
allocated channel: c8
channel c8: SID=834 device type=DISK

Starting Duplicate Db at 04-FEB-16

contents of Memory Script:
{
backup as copy reuse
targetfile '/oracle/app/oracle/product/11.2.0.3/dbhome_1/dbs/orapworarpt2' auxiliary format
'/oracle/app/oracle/product/11.2.0.3/dbhome_1/dbs/orapworarpt2' targetfile
'+DATA/orarpt/spfileorarpt.ora' auxiliary format
'+DATA/rptstby/parameterfile/spfile.1123.886959551' ;
sql clone "alter system set spfile= ''+DATA/rptstby/parameterfile/spfile.1123.886959551''";
}
executing Memory Script

Starting backup at 04-FEB-16  --hang here

note:
正常情况下早应该set newname, copy datafile了, 咨询了下其他DBA说真有几个小时不动的, 下班回家,第二天发现日志还在那里等着我,那就有点不正常了。

[oracle@anbob02 (orarpt2)work]$ ps -ef|grep adg
oracle   20574 16423  0 Feb03 pts/0    00:00:00 sh adg_setup.sh
oracle   20578 20574  0 Feb03 pts/0    00:00:02 rman msglog /home/oracle/work/adg_setup.log

 
[oracle@anbob02 (orarpt2)work]$ strace -fp 20578 -o rman.trc -ttt
Process 20578 attached - interrupt to quit

[oracle@anbob02 (orarpt2)work]$ tail -f rman.trc
20578 1454551745.092009 nanosleep({10, 0}, NULL) = 0
20578 1454551755.092238 write(12, "\0)\0\0\6\0\0\0\0\0\3N\221\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551755.092309 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551755.093573 nanosleep({10, 0}, NULL) = 0
20578 1454551765.093786 write(12, "\0)\0\0\6\0\0\0\0\0\3N\222\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551765.093858 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551765.094551 nanosleep({10, 0}, NULL) = 0
20578 1454551775.094778 write(12, "\0)\0\0\6\0\0\0\0\0\3N\223\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551775.094842 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551775.095816 nanosleep({10, 0}, NULL) = 0
20578 1454551785.096035 write(12, "\0)\0\0\6\0\0\0\0\0\3N\224\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551785.096106 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551785.096849 nanosleep({10, 0}, NULL) = 0
20578 1454551795.097062 write(12, "\0)\0\0\6\0\0\0\0\0\3N\225\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551795.097139 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551795.097882 nanosleep({10, 0}, NULL) = 0
20578 1454551805.098073 write(12, "\0)\0\0\6\0\0\0\0\0\3N\226\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551805.098141 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551805.098974 nanosleep({10, 0}, NULL) = 0
20578 1454551815.099187 write(12, "\0)\0\0\6\0\0\0\0\0\3N\227\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551815.099260 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551815.100527 nanosleep({10, 0}, NULL) = 0
20578 1454551825.100707 write(12, "\0)\0\0\6\0\0\0\0\0\3N\230\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551825.100783 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551825.101540 nanosleep({10, 0}, NULL) = 0
20578 1454551835.101744 write(12, "\0)\0\0\6\0\0\0\0\0\3N\231\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551835.101813 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551835.102565 nanosleep({10, 0}, NULL) = 0
20578 1454551845.102764 write(12, "\0\35\0\0\6\0\0\0\0\0\3\2\232\376\377\377\377\377\377\377\377\0\0\0\0\0\0\0\0", 29) = 29
20578 1454551845.102836 read(12, "\0\26\0\0\6\0\0\0\0\0\10\6\0\0\0\t\1\0\0\0\230!", 8208) = 22
20578 1454551845.103462 write(12, "\1B\0\0\6\0\0\0\0\0\3\3\233\6\0\0\0\0\0\0\0\376\377\377\377\377\377\377\377\26\1\0"..., 322) = 322
20578 1454551845.103521 read(12, "\0\222\0\0\6\0\0\0\0\0\4\1\0\0\0\231!\1\1\0\0\0\0\0\0\0\0\0\6\0\0\0"..., 8208) = 146
20578 1454551845.104163 write(12, "\1\305\0\0\6\0\0\0\0\0\3G\234\370\200\0\0\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 453) = 453
20578 1454551845.104215 read(12, "\0\254\0\0\6\0\0\0\0\0\4\1\0\0\0\232!\1\0\0\0\0{\5\0\0\0\0\6\0\0\0"..., 8208) = 172
20578 1454551845.108028 write(12, "\0*\0\0\6\0\0\0\0\0\3N\235\6\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\375\1"..., 42) = 42
20578 1454551845.108079 read(12, "\0\254\0\0\6\0\0\0\0\0\4\1\0\0\0\233!\1\0\0\0\0{\5\0\0\0\0\6\0\0\0"..., 8208) = 172
20578 1454551845.111745 write(12, "\0\21\0\0\6\0\0\0\0\0\3\10\236\6\0\0\0", 17) = 17
20578 1454551845.111793 read(12, "\0\21\0\0\6\0\0\0\0\0\t\1\0\0\0\234!", 8208) = 17
20578 1454551845.112397 write(12, "\0)\0\0\6\0\0\0\0\0\3N\237\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551845.112475 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551845.113188 nanosleep({10, 0}, NULL) = 0
20578 1454551855.113399 write(12, "\0)\0\0\6\0\0\0\0\0\3N\240\2\0\0\0\1\0\0\0\340\0\0\0\0\0\0\0\7\2\301"..., 41) = 41
20578 1454551855.113477 read(12, "\0\334\0\0\6\0\0\0\0\0\6\1\2\0\1\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 8208) = 220
20578 1454551855.114217 nanosleep({10, 0}, NULL) = 0
...

note:
strace 看进程好像在一直循环nanosleep, 查看了句柄41 是socket. 下面查看rman 是否有堵塞和等待。

SQL> select S.SID, S.SERIAL#, S.INST_ID , P.SPID SPID, S.USERNAME, S.STATUS, S.OSUSER || '@' || S.MACHINE OSINFO, SUBSTR(S.PROGRAM,0,20) PROGRAM, S.EVENT, S.SECONDS_IN_WAIT SIW
 from gv$session s, gv$process p
   where s.type <> 'BACKGROUND'
   and s.inst_id = p.inst_id
   and s.paddr = p.addr  and s.program like 'rman%'

 SID    SERIAL#    INST_ID SPID        USERNAME      STATUS   OSINFO          PROGRAM         EVENT                                 SIW
---- ---------- ---------- -------- -- ----------- - -------- --------------  --------------- ------------------------------ ----------
 147      61685          2 16192       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4930
1014      26077          2 13700       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4909
1833      40727          2 12810       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4910
 299      60835          2 15130       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4933
2653       1403          2 13628       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client             5
 196      61379          2 16980       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4928
 576      45345          2 14183       SYS           ACTIVE   oracle@anbob02   rman@anbob02   remote db operation                  4910
1016      27113          2 14593       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4935
  55      21301          2 17624       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4927
2021      49333          2 15689       SYS           INACTIVE oracle@anbob02   rman@anbob02   SQL*Net message from client          4932

Note:
以DG 和wait event 为关键字在MOS中发现RMAN “duplicate From Active Database” Hangs Between 2 Datacenters using Cisco Firewall ( Doc ID 2007835.1 ) ,但是网络确认近期无网络变动,且不存在firewall。 开了个SR也倾向于网络原因, 启用一些EVNET 排查,因使用duplicateauxiliary instance 要以pfile启动, pfile 中增加下面event:

*.event='10294 trace name context forever, level 1: 10298 trace name context forever,level 3:logon trace name krb_trace level 15'

同时启用rman 启用debug

rman debug trace=/tmp/rman_debug msglog=/home/oracle/work/adg_setup_weejar.log << EOF
 ...
EOF

并且查看了duplicate 进程的 call stack

SQL> oradebug short_stack
ksedsts()+461<-ksdxfstk()+32<-ksdxen_int()+4179<-ksdxen()+14<-opiodr()+916<-ttcpip()+2210<-opitsk()+1717<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36 -- wait 10s , repeat 3 times , output same as above SQL> select * from v$iostat_network ; 

select * from v$iostat_network ; 
--无网络IO

# 从上面的event 和debug 中trace 发现了一些,其它没找到有价值的信息 

ksfdwtio:count=4294967295 aioflags=0x20 timeout=2147483647
ksfd_osmwat:count=4294967295 intr=0 posted=(nil) tout=2147483647
ksfdwat_internal:count=4294967295 timeout=32 aioflags=2147483647
ksfdwtio:count=4294967295 aioflags=0x20 timeout=2147483647
ksfd_osmwat:count=4294967295 intr=0 posted=(nil) tout=2147483647
ksfdwat_internal:count=4294967295 timeout=32 aioflags=2147483647
ksfdwtio:count=4294967295 aioflags=0x20 timeout=2147483647
ksfd_osmwat:count=4294967295 intr=0 posted=(nil) tout=2147483647
ksfdwat_internal:count=4294967295 timeout=32 aioflags=2147483647
ksfdwtio:count=4294967295 aioflags=0x20 timeout=2147483647


Number of resource hash buckets is 15115
Large Pages allocation failed (free: 22981 required: 192)
2016-02-19 13:30:28.626: [ default]failed to initialize skgp context
2016-02-19 13:30:28.626: [ default]slos op : sslssreghdlr
2016-02-19 13:30:28.626: [ default]slos dep : Error 0 (0)
2016-02-19 13:30:28.626: [ default]slos loc : sskgpinit1
2016-02-19 13:30:28.626: [ default]slos info:
[ CLWAL]clsw_Initialize: OLR initlevel [30000]
2016-02-19 13:30:28.627: [ default]a_init: Unable to get log name. Retval:[-4] 

后来尝试在pfile逐渐增加了些参数,还有些是因为错误加了其它项 最终

*.audit_file_dest='/oracle/app/oracle/admin/rptstby/adump'
*.compatible='11.2.0.3.0'
*.control_files='+DATA/rptstby/controlfile/control01.ctl','+DATA/rptstby/controlfile/control02.ctl'
*.db_block_size=16384
*.db_create_file_dest='+DATA'
*.db_domain=''
*.db_file_multiblock_read_count=32
*.db_file_name_convert='+data/orarpt/datafile/','+data/rptstby/datafile/','+data/ORARPT/tempfile/','+data/rptstby/tempfile/','+flashts/ORARPT/datafile/','+data/rptstby/datafile/','+reco/ORARPT/datafile/','+reco/rptstby/datafile/','+DBFS_DG/orarpt/datafile/','+DBFS_DG/rptstby/datafile/'
*.db_lost_write_protect='TYPICAL'
*.db_name='orarpt'
*.db_unique_name='rptstby'
*.diagnostic_dest='/oracle/app/oracle'
*.log_archive_dest_1='location=+reco'
*.log_archive_dest_2=''
*.log_archive_dest_state_2='DEFER'
*.log_archive_format='arch_%t_%s_%r.arc'
*.log_file_name_convert='+data/orarpt/onlinelog/','+data/rptstby/onlinelog/'
*.standby_file_management='AUTO'

*.utl_file_dir='*'

*.cluster_database=false
orarpt2.thread=2
orarpt1.thread=1
orarpt1.instance_number=1
orarpt2.instance_number=2

*.sga_max_size=40G
*.sga_target=0
*.shared_pool_size=6G      
*.db_files=2000
*.pga_aggregate_target=10120855552
*.processes=2000

再启动rman duplicate 错误变成了

RMAN-03009: failure of backup command on d1 channel at 03/14/2016 13:50:07
ORA-00245: control file backup failed; target is likely on a local file system

这个问题的解决方法

RMAN> show all;  

..
CONFIGURE SNAPSHOT CONTROLFILE NAME TO '/oracle/app/oracle/product/11.2.0.3/dbhome_1/dbs/snapcf_orarpt1.f'; # default

修改到共享磁盘中
RMAN> CONFIGURE SNAPSHOT CONTROLFILE NAME TO '+data/snapcf_orarpt1.f';          

经过上面修改了pfile和修改自动备份controlfile 目录到ASM,  rman终于顺利开始copy datafile了,因网络限制用了4天3夜把终于把数据copy完了, 剩下工作不在详细描述的如

create spfile in ASM from pfile,
modify clustr_database=true,
create pfile on other nodes with spfile in ASM.
$GIRD_HOME/bin/srvctl add database -d rptstby -o $ORACLE_HOME  -p "+DATA/rptstby/parameterfile/spfileorarpt2.ora" -n orarpt -r physical_standby -s mount
srvctl add instance -d rptstby -i orarpt1 -n qdexa1db01
srvctl add instance -d rptstby -i orarpt2 -n qdexa1db02

srvctl modify database -d rptstby -a 
srvctl start database -d rptstby 

–start real-time redo apply
alter database recover managed standby database using current logfile disconnect from session;

--stop redo apply
alter database recover managed standby database cancel;

NOTE:
刚开始日志相差太多,如果启用ADG, open standby read-only时可能不会成功。

错误ORA-17628: Oracle error 19505 returned by remote Oracle server

有时在安装完补丁后,duplicat database报错

release channel:c2
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 08/23/2022 17:35:43
RMAN-05501: aborting duplication of target database
RMAN-03015: error occurred in stored script Memory Script
RMAN-03009: failure of backup command on ORA_DISK_1 channel at 08/23/2022 17:35:43
ORA-17628: Oracle error 19505 returned by remote Oracle server

分析
检查 目标库的db alert log日志内容
检查 ASM DEVICE设备所有者
检查 Oracle 执行文件属主

$ ls -l  `which  oracle`

解决
修改$ORACLE_HOME/bin/oracle的权限:

重启备库至nomount状态,重新进行rman active duplicate

下面这个有些优化技术可以加速日志传速及日志应用。
1, 日志启用压缩传输 — on primary DB 如 LOG_ARCHIVE_DEST_2=’SERVICE=xxxx COMPRESSION=ENABLE ….’
2, 增加归档进程 增加 log_archive_max_processes — on primary
DB 增加 log_archive_max_processes = log_archive_max_processes on primary* number of threads — on Standby DB
3, 调整内存参数 增加 standby DB 的 buffer cache 值,要大于primary DB
4, 启用并行日志恢复, 并行度 #CPUs * 2
如: alter database recover managed standby database PARALLEL 48 using current logfile disconnect from session;

# 查询

— 查看primary 库上的日志进度

select thread#,max(sequence#) from v$archived_log group by thread#;
select * from v$log;

— 查看standby 库,日志传速进程,应用进程

select t.*,arched-applied gap from (select thread#,max(sequence#) arched, max(decode(applied,'YES',sequence#,1)) applied 
from v$archived_log group by thread#) t;

select to_char(START_TIME,'dd.mm.yyyy hh24:mi:ss') "Recover_start",to_char(item)||' = '||to_char(sofar)||' '||to_char(units)||' '|| to_char(TIMESTAMP,'dd.mm.yyyy hh24:mi') "Values" 
from v$recovery_progress 
where start_time=(select max(start_time) from v$recovery_progress);
打赏

对不起,这篇文章暂时关闭评论。