这是学习笔记的第2263篇文章 读完需要 9hr分钟 速读仅需7分钟 今天分析了另外一个关于数据库延迟跳动的问题,也算是比较典型,这个过程中也有一些分析问题的方法和技巧工参考。 首先在高可用检测中,有一套环境的检测时断时续,经过排查发现是数据库产生了延迟,在登录到从库showslavestatus查看,会发现Secondsbehindmaster的值是不断跳动的,即从039039这样的频率不断跳动,让人很搓火。 查看数据库的相关日志发现竟然没有任何可以参考的日志记录,怎么分析这个问题呢,我们先来复现,于是我按照节奏抓取了3次问题出现的日志,即通过showslavestatus连续监测,抓取showslavestatus输出的结果保存下来,这样我们就得到了一个问题发生过程中的偏移量变化,而这个变化则是在SQLThread在回放过程中产生的问题。 比如下面的一段输出,我截取的是Slave端的relaylog进行分析,相应的字段为RelayLogPosSlaveIOState:WaitingformastertosendeventMasterHost:xxxxMasterUser:dbareplMasterPort:4306ConnectRetry:60MasterLogFile:mysqlbin。000044ReadMasterLogPos:386125369RelayLogFile:slaverelaybin。000066RelayLogPos:386125580RelayMasterLogFile:mysqlbin。000044 所以很快得到了偏移量的变化情况:385983806,386062813,386125580 接着我使用mysqlbinlog开始分析这些日志过程中的明细,根据如下的命令可以很快得到转储的日志中相关的表有3张。grepINSERTrelaylogxxxx。dumpawk{print}sedsINTOgsortuniqactactionexecinfoactjoindescdicsubsidymarketingquerylog202008 我逐步分析了每张表的数据操作情况,得到的信息还是比较有限,继续做更进一步的分析,比如我们分析一下整个日志中的事务量大小:mysqlbinlogslaverelaybin。000066grepGTID(printf)lastcommittedB1grepEatawk{print3}awkNR1{tmp1}NR1{print(1tmp);tmp1}sortnrheadn100mysqlbinlog:〔Warning〕unknownvariableloosedefaultcharactersetutf8527852685268526852535253525352535253 可以看到是5K左右,算是比较大了,而这些额外的信息从哪里获得呢,我在主库开启了generallog,这样就能够得到更细粒度的操作日志了。 进一步分析发现,整个业务使用了显示事务的方式:SETautocommit0,整个事务中包含了几个大SQL,里面存储了很多操作日志明细,而且在事务操作过程中还基于Mybatis框架调用了多次selectcount(1)fromxxx的操作。 经过和业务沟通也基本明确了以上问题。