今天又分析了一个数据库延迟跳转的问题，比较典型。在这个过程中也有一些分析问题的方法和技术参考。首先，在高可用检测中，对一组环境的检测是断断续续的。经过排查，发现是数据库延迟了。登录从库的showslavestatus后，会发现Seconds_behind_master的值一直在跳动，也就是从0到39~0~39的频率不停跳动，让人很气愤。查看数据库的相关日志，发现没有可以参考的日志记录。如何分析这个问题？先复现一下，所以我按照节奏抓了3次问题的日志，也就是通过showslavestatus不断监控，抓取showslavestatus的输出并保存，这样我们就可以得到offset在问题发生的过程中发生变化，这个变化就是SQLThread在回放过程中产生的问题。比下面的一段输出，我截取的是Slave端的relaylog进行分析，相应的字节为Relay_Log_PosSlave_IO_State:WaitingformastertosendeventMaster_Host:xxxxMaster_User:dba_Portrepl3:40Master60Master_Log_File:mysqlbin.000044Read_Master_Log_Pos:386125369Relay_Log_File:slave-relay-bin.000066Relay_Log_Pos:386125580Relay_Master_Log_File:mysqlbin.000044SoIquicklygotthechangeoftheoffset:385983806,386062813,386125580ThenIusedmysqlbinlogtostartanalyzingthedetailsintheprocessofthese日志。根据下面的命令，我可以快速的获取dump日志中的相关表。有3个开。#grepINSERTrelaylog_xxxx.dump|awk'{print$3""$4}'|sed's/INTO//g'|sort|uniqact_action_exec_infoact_join_descdic_subsidy_marketing_querylog_202008逐渐分析了各个表的数据运行情况，得到的信息还是比较有限，所以我继续更进一步比如我们分析整个日志中的事务量：#mysqlbinlogslave-relay-bin.000066|grep"GTID$(printf'\t')last_committed"-B1\>|grep-E'^#at'|awk'{print$3}'\>|awk'NR==1{tmp=$1}NR>1{print($1-tmp);tmp=$1}'\>|sort-n-r|head-n100mysqlbinlog:[Warning]unknownvariable'loose-default-character-set=utf8'527852685268526852535253525352535253可以看到大概5K左右，比较大，请问这个额外的信息是从哪里得到的呢？我在主库中打开了general_log，这样我就可以得到更细粒度的操作日志了。进一步分析发现，整个业务使用了显示事务的方式：SETautocommit=0，整个事务包含了若干条大型SQL，其中存储了大量的操作日志明细，在事务运行过程中基于Mybatis框架调用了多次。selectcount(1)fromxxx的操作。与业务沟通后，基本弄清了以上问题。
