MySQL数据延迟跳动的问题解决

今天分析了另外一个关于数据库延迟跳动的问题，也算是比较典型，这个过程中也有一些分析问题的方法和技巧工参考。

首先在高可用检测中，有一套环境的检测时断时续，经过排查发现是数据库产生了延迟，在登录到从库show slave status查看，会发现seconds_behind_master的值是不断跳动的，即从0~39~0~39这样的频率不断跳动，让人很搓火。

查看数据库的相关日志发现竟然没有任何可以参考的日志记录，怎么分析这个问题呢，我们先来复现，于是我按照节奏抓取了3次问题出现的日志，即通过show slave status连续监测，抓取show slave status输出的结果保存下来，这样我们就得到了一个问题发生过程中的偏移量变化，而这个变化则是在sqlthread在回放过程中产生的问题。

比如下面的一段输出，我截取的是slave端的relay log进行分析，相应的字段为relay_log_pos

slave_io_state: waiting for master to send event
         master_host: xxxx
         master_user: dba_repl
         master_port: 4306
        connect_retry: 60
       master_log_file: mysqlbin.000044
     read_master_log_pos: 386125369
        relay_log_file: slave-relay-bin.000066
        relay_log_pos: 386125580
    relay_master_log_file: mysqlbin.000044

所以很快得到了偏移量的变化情况：385983806 ，386062813 ，386125580

接着我使用mysqlbinlog开始分析这些日志过程中的明细，根据如下的命令可以很快得到转储的日志中相关的表有3张。

# grep insert relaylog_xxxx.dump |awk '{print $3 " " $4}'|sed 's/into//g'|sort|uniq
 act_action_exec_info
 act_join_desc
 dic_subsidy_marketing_querylog_202008

 

我逐步分析了每张表的数据操作情况，得到的信息还是比较有限，继续做更进一步的分析，比如我们分析一下整个日志中的事务量大小：

# mysqlbinlog slave-relay-bin.000066 | grep "gtid$(printf '\t')last_committed" -b 1 \
>                   | grep -e '^# at' | awk '{print $3}' \
>                   | awk 'nr==1 {tmp=$1} nr>1 {print ($1-tmp);tmp=$1}' \
>                   | sort -n -r | head -n 100
mysqlbinlog: [warning] unknown variable 'loose-default-character-set=utf8'
5278
5268
5268
5268
5253
5253
5253
5253
5253

可以看到是5k左右，算是比较大了，而这些额外的信息从哪里获得呢，我在主库开启了general_log，这样就能够得到更细粒度的操作日志了。

进一步分析发现，整个业务使用了显示事务的方式：set autocommit=0，整个事务中包含了几个大sql,里面存储了很多操作日志明细，而且在事务操作过程中还基于mybatis框架调用了多次select count(1) from xxx的操作。

经过和业务沟通也基本明确了以上问题。

以上就是mysql数据延迟跳动的问题解决的详细内容，更多关于mysql数据延迟跳动的资料请关注其它相关文章！