log file switch(checkpoint incomplete)导致OGG同步延迟38个小时

项目背景

基于TB级生产库搭建一套OGG备库，每天的日志量在200G左右，最近发现经常出现同步延迟几十个小时，搞得有点烦，特此记录一下处理过程。

系统环境

oracle 11.2.0.4+ogg12.2.0.1.0

延迟现象

GGSCI (cluster-10-176-50-29 as ogg@yjgk2) 169> info all

Program     Status      Group       Lag at Chkpt  Time Since Chkpt

MANAGER     RUNNING                                           
REPLICAT    RUNNING     REP_PS1     38:27:09      00:00:57    
REPLICAT    RUNNING     REP_PS2     00:00:02      00:00:10    
REPLICAT    RUNNING     REP_PS3     00:00:03      00:00:10    
REPLICAT    RUNNING     REP_PS4     00:00:03      00:00:03    
REPLICAT    RUNNING     REP_PS5     00:00:05      00:00:01    
REPLICAT    RUNNING     REP_PS6     00:00:05      00:00:01    

通过send rep_ps1,status查看事务提交的记录非常慢

问题分析与定位

1、在操作系统层面找到rep_ps1复制进程对应的操作系统PID
2、根据进程ID找到相应的会话

select a.spid process_id,b.SID,b.SERIAL#,b.PROGRAM,b.SQL_ADDRESS from v$process a,v$session b where a.ADDR=b.PADDR and a.SPID='77295'

3、查看该会话所执行的SQL_ID和等待事件

select  m.SQL_ID,m.EVENT,m.BLOCKING_SESSION_STATUS,m.CURRENT_OBJ#,count(*)  from v$active_session_history m where m.SESSION_ID='1351'
group by m.SQL_ID,m.EVENT,m.BLOCKING_SESSION_STATUS,m.CURRENT_OBJ# 
order by 5,4

说明：这里出现了大量的log file switch(checkpoint incomplete)等待事件
到这里发现可能是redo日志组过少或日志组过小导致的,查询v$log,v$logfile发现单个日志大小为1G，一共6组，但除了当前日志组状态为current，其他日志组都为active，经过分析有以下原因：1、日志组不足；2、DBWN写脏数据过慢
手动添加了4个日志组，每组大小为1G
alter database add logfile group 7 (‘redo7a.log’,‘redo7b.log’) size 1g;
alter database add logfile group 8 (‘redo8a.log’,‘redo8b.log’) size 1g;
alter database add logfile group 9 (‘redo9a.log’,‘redo9b.log’) size 1g;
alter database add logfile group 10 (‘redo10a.log’,‘redo10b.log’) size 1g;
观察了几分钟发现同步速度依然没有明显提升，那就是DBWN进程写入脏数据过慢，接着查看AWR报告。
4、生成AWR报告，截图如下。

system i/o事件产生的等待时间最长

这是可以看到后台进程db file async i/0 submit排在第一位

按I/O等待时间查看看最耗I/O的SQL语句

到这里基本能确认是I/O提交问题，导致数据同步延迟的。

解决方法

1、搜索相应的等件事件
查看mos文档 ID 1274737.1 部分如下：

The tests show the following behavior:
disk_asynch_io filesystemio_options strace DBWR AIO DBWR waits
FALSE NONE pwrite64 NO db file parallel write
FALSE ASYNCH pwrite64 NO db file parallel write
TRUE ASYNCH io_submit/ YES db file parallel write
io_getevents
TRUE NONE pwrite64 NO db file async I/O submit

说明：disk_asynch_io为TRUE，filesystemio_options为NONE的情况下 出现db file async I/O submit等待，可以设置filesystemio_options参数为ASYNCH或者SETALL，使得db file parallel write等待代替db file async I/O submit等待。
SQL> alter system set filesystemio_options=‘setall’ both=spfile
上述操作需要重启数据库实例，重启后查看参数是否生效
SQL> show parameter filesystem;
NAME TYPE VALUE

---

filesystemio_options string setall
disk_asynch_io boolean TRUE

select f.NAME,i.filetype_name,i.ASYNCH_IO,i.ACCESS_METHOD from v$datafile f ,v$iostat_file i 
where f.FILE#=i.FILE_NO

调整完成后，通过send rep_ps1,status查询同步的速度，有明显的提升，先下班了，但事情还没有完（还有SQL没有优化）第二天上班发现同步延迟只有10个小时，很明显同步速度追上来了，接着优化SQL语句。
SQL语句优化就比较简单了，从AWR报告找到最耗I/O的SQL语句进行优化，大部分都是对单表进行DELETE操作，而单表无索引导致走全表扫描引起的同步效率低，对相应的表加上索引后，上午整个同步完全追上来了，到此整个同步延迟问题已圆满解决。

总结

1、log file switch(checkpoint incomplete)不一定是完全是redo日志组过少或过小导致的。
2、需要理解oracle的内部原理，LGWR进行在切换日志组时，如果下一组日志组的状态为ACTIVE，会触发checkpoint操作，进一步会让DBWN将db buffer里的脏数据刷回磁盘，对于磁盘的操作可以是同步写操作也可以是异步写操作，当前异步写操作效率更高，需要看看oracle是否开启的异步提交。
3、业务有设计不规划的地方，如处理的表业务表中，好多都没有主键，导致删除操作都走全表扫描，同步效率低，出现延迟也就说得通了。