问题背景:
用户通过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的事务