OGG-MySQL无法正常同步数据问题分析

问题背景:

        用户通过OGG从源端一个MySQL从库将数据同步到目标端的另一个MySQL数据库里面，后面由于源端的从库出现了长时间的同步延时，由于延时差距过大最后选择通过重建从库方式进行了修复

从库重建之后，源端的OGG出现了报错ERROR   OGG-00146  Call to VAMInitialize returned with error status 600: VAM Client Report <CAUSE OF FAILURE : Failed to find binlog:  inside binlog index，从报错信息看很明显是源端的extract进程找不到读取的binlog文件，这是因为从库进行了重建，导致从库的binlog重新从1开始，知道问题的原因之后，用户对源端的extract抽取进行修复，将抽取进程的读取位置重新指向最新序号1的binlog进行抽取，源端的抽取进程也恢复了正常，通过stats可以看到有在正常的抽取事务，但奇怪的事，目标端的replicat应用进程一直却无法应用数据，进程状态显示为正常

问题分析：

        查看目标端应用进程r_test的状态，可以看到应用进程r_test有在正常的读取队列文件，而且没有存在应用延时的情况

        检查应用进程的日志，发现存在大量的事务被过滤的报错OGG-05664  CSN-based filtering suppressed 2 duplicate transactions, from trail Seqno 3, RBA 14043 to Seqno 3, RBA 14283. 

        最近一次的报错信息可以看到被过滤的

        第一个事务为CSN 000000000000000000001:000000000011177 and transaction ID 000000000000000000001:000000000010963，

        最后一个事务为CSN 000000000000000000001:000000000011511 and 

transaction ID 000000000000000000001:000000000011297

        注:CSN表示事务结束所在的binlog位置:000000000000000000001表示事务在binlog的序号为1，000000000011177表示事务结束的binlog位置pos

        transaction ID表示事务开始所在的binlog位置000000000000000000001表示事务在binlog的序号为1,000000000010963表示事务开始的binlog位置pos

        查看目标端检查表里面应用进程的检查点信息，可以看到当前检查点存储的低位线log_cmplt_csn为000000000000000000004:000000000003836,已经应用执行事务log_cmplt_xids为000000000000000000004:000000000003622，均超过了之前报错被过滤的事务csn以及事务xid，因此事务将被视作已经完成执行从而被跳过，这也为什么应用进程看起来读取队列正常，但一直没有应用事务的原因，因为应用的事务csn，xid都低于检查表里面的检查点csn以及事务XID

        那为什么检查表里面的检查点信息都这么大呢，从000000000000000000004序号我们可以判断，检查点已经读取到了属于binlog为4的事务，很明显这是重搭从库之前应用进程的检查点信息，因为从库的binlog已经重新从1开始，所以检查表的信息应该也需要被重新清理，确保检查点也从binlog 1重新开始

问题解决：

        我们先要清理检查表里面链路的信息，这里直接根据应用的进程名称删除检查表信息，辅助的检查表checkpoint_lox记录为空不需要进行操作，另一种方式直接删除应用进程delete replicat重建也可以清空检查表进程的信息 

mysql> delete from checkpoint where group_name='R_TEST';

        修改进程r_test读取队列文件的位置，指向最近一个的队列文件3，再重新应用一遍队列文件，由于修改的队列文件位置不一定准确，可能出现重复应用数据的情况，可以通过参数HANDLECOLLISIONS去解决冲突数据

GGSCI (rac2) 20> alter replicat r_test,extseqno 3,extrba 0 

        重新开启应用进程，发现依然出现事务被过滤的报错OGG-05664  CSN-based filtering suppressed 15 duplicate transactions

问题二次分析：

        再次查看检查表的信息，发现进程R_TEST的检查点又重新回到了之前的CSN位置000000000000000000004:000000000003836，不是期待的binlog为1的日志

        通过logdump分析队列文件3日志，首先尝试根据filter ggstoken TRANID过滤检查点里面记录的事务ID000000000000000000004:000000000003836，发现队列文件记录了从库重建之前的binlog 4的事务信息

        之后再往下查找又发现了属于从库重建之后binlog日志序列号1的事务信息000000000000000000001:000000000005280

        也就是说队列文件3同时记录了从库重建之前binlog 4的事务以及重建之后binlog 1的事务，这样如果应用进程从队列文件头开始读取的话，会先应用重建之前binlog 4的事务，检查点里面的信息会更新为binlog 4的事务检查点信息，这样后面再读取到重建之后binlog 1的事务信息时，由于binlog 1事务的csn，xid均低于binlog 4事务的csn,xid，就会导致binlog 1事务都被过滤

最终解决：

        知道问题原因是由于队列文件里面同时包含从库重建之前binlog 4的事务以及重建之后binlog 1的事务之后，我们需要获取更为准确的读取rba位置，让应用进程跳过从库重建之前binlog 4的事务应用

        通过logdump确认第一个属于binlog 1的事务的位置rba 4421

        清理检查表里面链路的信息，这里我直接根据应用的进程名称删除检查表信息，辅助的检查表checkpoint_lox记录为空不需要进行操作，另一种方式直接删除应用进程delete replicat重建也可以清空检查表进程的信息 

mysql> delete from checkpoint where group_name='R_TEST';

        修改进程r_test读取队列文件的位置，指向队列文件3，rba 4421

GGSCI (rac2) 20> alter replicat r_test,extseqno 3,extrba 4421 

        注：如果知道重建从库的时间点，也可以通过修改应用进程的开始事务的时间点启动，跳过重建之前的事务，这种方式更加便捷

ALTER REPLICAT xxxx, BEGIN 2017-01-07 08:00:00 

        重新开启应用进程同步终于恢复正常，没有再出现事务被过滤的报错，

        检查表的信息也更新为binlog 1的事务