DG日志应用延时严重故障处理及优化（数据延迟6天将近3T归档日志文件）

【说明】：操作部分若没有特别说明，都是在目标端

本文包含故障的处理过程，DG目标端应用速度优化，DG监控思路

摘要：11G DG（Data Gurad）单实例目标端应用延迟6天，将近3T的归档日志为应用，故障处理及数据积压后怎么快速追平数据

1）第一时间查看了数据库的打开状态为“ READ ONLY ”，而非正常的状态 “ READ ONLY WITH APPLY ”

SQL> select open_mode from v$database; OPEN_MODE READ ONLY

2）日志怎么会挂了呢？查看告警日志，其中一段显示，磁盘空间不足，造成后台进程MRP0 shutdown掉

09812 ARC3: Closing local archive destination LOG_ARCHIVE_DEST_1: '/mnt/vdd1/archivelog/ARC0000202222_1013199719.0001.arc' (error 19502) (orcl) 309813 ARCH: Archival stopped, error occurred. Will continue retrying 309814 ORACLE Instance orcl - Archival Error 309815 ORA-16038: log 4 sequence# 202222 cannot be archived 309816 ORA-19502: write error on file "", block number (block size=) 309817 ORA-00312: online log 4 thread 1: '/mnt/oracle/oradata/orcl/redo04.log' 309818 Sat Jul 02 14:14:06 2022 309819 Media Recovery Log /mnt/vdd1/archivelog/ARC0000201136_1013199719.0001.arc 309820 Sat Jul 02 14:14:08 2022 309821 ARCH: Archival stopped, error occurred. Will continue retrying 309822 ORACLE Instance orcl - Archival Error 309823 ORA-16014: log 4 sequence# 202222 not archived, no available destinations 309824 ORA-00312: online log 4 thread 1: '/mnt/oracle/oradata/orcl/redo04.log' 309825 Errors with log /mnt/vdd1/archivelog/ARC0000201136_1013199719.0001.arc 309826 MRP0: Background Media Recovery terminated with error 1237 309827 Errors in file /mnt/oracle/diag/rdbms/orcl_st/orcl/trace/orcl_pr00_29562.trc: 309828 ORA-01237: cannot extend datafile 91 309829 ORA-01110: data file 91: '/mnt/vdd1/oradata/TS_PART4_01' 309830 ORA-19502: write error on file "/mnt/vdd1/oradata/TS_PART4_01", block number 4130560 (block size=8192) 309831 ORA-27072: File I/O error 309832 Linux-x86_64 Error: 28: No space left on device 309833 Additional information: 4 309834 Additional information: 4130560 309835 Additional information: -1 309836 Managed Standby Recovery not using Real Time Apply 309837 Sat Jul 02 14:15:29 2022 309838 Recovery interrupted! 309839 Recovered data files to a consistent state at change 17592401117937 309840 Sat Jul 02 14:15:31 2022 309841 MRP0: Background Media Recovery process shutdown (orcl)

3）14点多发生磁盘空间不足，删除目标端日志的计划任务是在18点，那18点后，DG检测又空间了，继续将归档日志重传到目标端，但是由于日志应用的进程MRP0挂掉，导致数据同步失败

4）大坑：未及时发现，需设置监控告警DG情况

1）考虑归档日志已经被计划任务删除，需要先进行归档日志恢复，目标端最新应用到201136，而主库还存在归档是207163，限于磁盘空间，分多次进行恢复，先进行恢复202315到203000直接的归档日志文件 ，并后台执行

建立shell脚本：
cat arch_restore.sh

#!/bin/bash . $HOME/.bash_profile rman target / nocatalog msglog /mnt/script/logs/rman-arch.log <<EOF run { set archivelog destination to '/mnt/vdd1/archivelog'; allocate channel ch1 type disk; allocate channel ch2 type disk; allocate channel ch3 type disk; allocate channel ch4 type disk; allocate channel ch5 type disk; allocate channel ch6 type disk; allocate channel ch7 type disk; allocate channel ch8 type disk; restore archivelog from logseq 202315 until logseq 203000; release channel ch1; release channel ch2; release channel ch3; release channel ch4; release channel ch5; release channel ch6; release channel ch7; release channel ch8; } exit EOF

后台执行脚本 :

nohup sh arch_restore.sh >alog07070813.log &

2）重启MRP0，恢复日志应用 (### 然后忙去了，几个小时候去检查，发现才应用了三百个多文件… ###)

alter database recover managed standby database cancel; alter database recover managed standby database using current logfile disconnect;

3）再查日志，发现需要一个，到源端去拿一个，最后还直接挂了 (### 哭晕在厕所o(╥﹏╥)o… ###)

日志显示：

Wed Jul 06 18:59:07 2022 Archived Log entry 206097 added for thread 1 sequence 206015 ID 0xe08f092f dest 1: Wed Jul 06 18:59:41 2022 Media Recovery Log /mnt/vdd1/archivelog/ARC0000201380_1013199719.0001.arc Error opening /mnt/vdd1/archivelog/ARC0000201380_1013199719.0001.arc Attempting refetch Media Recovery Waiting for thread 1 sequence 201380 Fetching gap sequence in thread 1, gap sequence 201380-201380 Wed Jul 06 18:59:42 2022 RFS\[7513\]: Allowing overwrite of partial archivelog for thread 1 sequence 201380 RFS\[7513\]: Opened log for thread 1 sequence 201380 dbid 1116521861 branch 1013199719 Archived Log entry 206098 added for thread 1 sequence 201380 rlc 1013199719 ID 0x0 dest 2: Media Recovery Log /mnt/vdd1/archivelog/ARC0000201380_1013199719.0001.arc Wed Jul 06 19:00:09 2022 Archived Log entry 206099 added for thread 1 sequence 206016 ID 0xe08f092f dest 1: Wed Jul 06 19:01:35 2022 Media Recovery Log /mnt/vdd1/archivelog/ARC0000201381_1013199719.0001.arc Error opening /mnt/vdd1/archivelog/ARC0000201381_1013199719.0001.arc Attempting refetch Media Recovery Waiting for thread 1 sequence 201381 Fetching gap sequence in thread 1, gap sequence 201381-201381 Media Recovery Waiting for thread 1 sequence 201381 Fetching gap sequence in thread 1, gap sequence 201381-201381 Wed Jul 06 19:05:07 2022 FAL\[client\]: Failed to request gap sequence GAP - thread 1 sequence 201381-201381 DBID 1116521861 branch 1013199719 FAL\[client\]: All defined FAL servers have been attempted. Check that the CONTROL_FILE_RECORD_KEEP_TIME initialization parameter is defined to a value that's sufficiently large enough to maintain adequate log switch information to resolve archivelog gaps.

4）将日志批量复制到备库，并解决GAP

– 【目标端】GAP查询语句

select count(*) from v$archive_gap;

–【目标端】有时候该视图查询超级慢，也可以考虑用下面语句代替：

select USERENV('Instance'), high.thread#, low.lsq, high.hsq from (select a.thread#, rcvsq, min(a.sequence#)-1 hsq from v$archived_log a, (select lh.thread#, lh.resetlogs_change#, max(lh.sequence#) rcvsq from v$log_history lh, v$database_incarnation di where lh.resetlogs_time = di.resetlogs_time and lh.resetlogs_change# = di.resetlogs_change# and di.status = 'CURRENT' and lh.thread# is not null and lh.resetlogs_change# is not null and lh.resetlogs_time is not null group by lh.thread#, lh.resetlogs_change# ) b where a.thread# = b.thread# and a.resetlogs_change# = b.resetlogs_change# and a.sequence# > rcvsq group by a.thread#, rcvsq) high, (select srl_lsq.thread#, nvl(lh_lsq.lsq, srl_lsq.lsq) lsq from (select thread#, min(sequence#)+1 lsq from v$log_history lh, x$kccfe fe, v$database_incarnation di where to_number(fe.fecps) <= lh.next_change# and to_number(fe.fecps) >= lh.first_change# and fe.fedup!=0 and bitand(fe.festa, 12) = 12 and di.resetlogs_time = lh.resetlogs_time and lh.resetlogs_change# = di.resetlogs_change# and di.status = 'CURRENT' group by thread#) lh_lsq, (select thread#, max(sequence#)+1 lsq from v$log_history where (select min( to_number(fe.fecps)) from x$kccfe fe where fe.fedup!=0 and bitand(fe.festa, 12) = 12) >= next_change# group by thread#) srl_lsq where srl_lsq.thread# = lh_lsq.thread#(+) ) low where low.thread# = high.thread# and lsq < = hsq and hsq > rcvsq;

–【源端】复制归档日志目标端

scp -P port username@IP:目标端目录

–【目标端】手动注册归档日志(注册断掉的第一个就好，后续再注册会提示已注册)

alter database register logfile '/${归档目录绝对路径}/ARC0000201381_1013199719.0001.arc';

(### 你以为这就完了么？？？ ###)

1）开启并行（视负载情况及CPU核数，最大设置cpu*2）

– 取消日志应用

alter database recover managed standby database cancel;

– 默认8通道，更改为12通道

alter database recover managed standby database parallel 16 using current logfile disconnect;

2）主库到备库的日志传输，考虑积压量大，可以传输一段时间关闭一段时间的方式（源端主库操作）

– 停止主库归档日志传输到备库

ALTER system SET log_archive_dest_state_2 = 'defer';

– 恢复归档日志传输

ALTER system SET log_archive_dest_state_2 = enable;

3）优化参数并重启数据库（目标端执行）

– 查看参数设置

show parameter parallel_execution_message_size --值为16384 show parameter filesystemio_options --默认none

– linux操作系统层面可查看

grep kio /proc/slabinfo

– 更改设置为异步IO（单机实例，11.2.0.4）

alter system set filesystemio_options=setall scope=spfile;

–指定并行执行中meassage的大小，11G取值2148~32768

alter system set parallel_execution_message_size=32768 scope=spfile;

通过上述1 2 点优化设置后，速度有点提升，但是速度不稳定（感谢lgs提供的思路）；

停掉日志传输，并行度从4、6、8、12、16、 20都尝试过，但资源监控：CPU、IO都闲的发慌，占比20%以下，这让我再想加资源都没有理由。

最后发现第3点的参数调优，可以一试，趁着中午业务低峰期，调整参数后，导出pfile，比对之前的初始化参数文件，确定没问题后，重启目标端端数据库【慎之又慎】。

通过以上三点，优化完成后效果显著，结果是可喜的：
速度提升10-20倍，由原来的2分钟1-3个，提升到2分钟30-50个文件

1）设定日志监控：通过监控alert日志的关键字（在使用中逐步优化）进行告警

2）通过视图v$dataguard_stats进行监控（单位分钟）：

select to_number(substr(s.value,2,2))2460+to_number(substr(s.value,5,2))*60+to_number(substr(s.value,8,2)) as nums from v$dataguard_stats s where name='apply lag';

– 查询归档还原情况，若是正常在同步中，YES后是IN-MEMORY状态，表示正在应用的日志文件,或通过文件号定位最新的应用到的归档，YES为已应用，NO为未应用

select g.recid,g.sequence#,g.applied,status,archived,g.first_time from v$archived_log g where 1=1-- g.sequence#> 201134 and applied='IN-MEMORY' order by g.sequence#

– 查看备库DG状态

SELECT PROCESS,CLIENT_PROCESS,PROCESS,STATUS,THREAD#,SEQUENCE#,BLOCK#,BLOCKS FROM V$MANAGED_STANDBY;

– 查询在线日志情况

select thread#, group#, sequence#, bytes, archived, s.status , blocksize, member FROM v$standby_log s join v$logfile using (GROUP#) order by thread#, group#;

– 查询进程状态 dg库日志应用性能监控

select to_char(sysdate,'DD-MON-YYYY HH24:MI:SS') "Current time" ,s.process , p.spid , substr(s.program, -6) PROC , s.event , s.p1 , s.p2 , s.p3 , s.seconds_in_wait SIW , s.seq# from v$session s, v$process p where p.addr = s.paddr and (s.program like '%MRP%' or s.program like '%PR0%' or s.program like '%DBW%' or s.program like '%CKPT%') order by s.process;