主从延迟案例分析一

• 问题背景：

  在我们实际工作过程中，会遇到形形色色的数据库问题，有些问题可以迎刃而解，而有的问题处理起来却比较让人揪心，比如说“延迟问题”。你是否也在工作中遇到过类似的问题呢？它到底是怎么造成的呢？我们该如何处理呢？
  首先，我们先来看一个用户主从延迟的案例：
  【下面展示步骤为测试环境复现用户主从延迟场景】

• 排查步骤：

  1、查询同步延迟状态：

  登录RO（只读实例）执行show slave status\G;查询同步状态。执行如下：

  
  

  [ 主从延迟 ]
  
  我们通过重复执行show slave status;查看Seconds_Behind_Master值为1897s肯定是延迟了，多次执行查看Seconds_Behind_Master值仍在不断变大，并且没有自动恢复的迹象。
  接下来，我们在RO上执行show full processlist;查看当前mysql链接线程都在做些什么，执行结果如下：
  | 50 | root | % | rw_upms | Connect | 88 | Sending data | select sum(a.payment)/100 from 【此处省略200行代码:joy:】多次执行show full processlist，我们发现“select sum(a.payment)/100【此处省略】”查询一直在变。
  
  
  
  
  

   

  2、分析延迟的原因：

  a、首先思考什么情况下会导致延迟：
  （1）、主库执行大事务导致从库应用binlog过程慢
  （2）、Row格式下主库更新无主键的表
  （3）、主库高并发写，从库单线程回放
  （4）、数据库参数配置
  （6）、网络延迟导致
  （7）、主和RO硬件配置不同
  …….
  b、首先要看是不是“主库高并发写，从库单线程回放”，为什么先排查这点呢？因为我们在RO上执行几次show slave status;得到Seconds_Behind_Master值在变大，Relay_Log_File: relay-bin.000004值不变，但是Relay_Log_Pos的值在不断的刷新，说明RO是在不断回放Relay_Log只是一直追不上主库而已。
  查询主库监控，主库负载很低，监控信息如下：

  
  
  
  
  
  
  

   

  很奇怪的现象，主库的负载很低但是RO却有延迟。RO暂时分析不出来，那么我们是不是会想：RO有延迟那透明备机有延迟吗？
  登录透明备机执行show slave status;也有延迟，在透明备机上执行show full processlist;查询发现透明备机上居然也有RO上执行的这个SQL：select sum(a.payment)/100【此处省略】查询也一直在变。既然RO和透明备机都有延迟，说明就是由主库的更新引起的。同时注意到，同步线程执行的账号是root，host是%。如果是一个普通的语句，同步线程执行的账号应该是XXXX，host是具体IP，这个root 很可疑。因此需要查明下面两个问题：
  问题1：分析备机有来自root %账号的查询这种情况的原因；
  问题2：主库负载不高，备机和RO均有延迟的原因；

  先说明三个现象：
  1. 普通的客户端查询，host字段是不会显示为%的；
  2. 从系统上排查，这个实例透明从机并没有开过从机只读；
  3. RO和透明从机都有这个语句；

从上面三个现象说明， 这个select… 语句是从主库同步过来的；但是普通的select语句是不会同步到备库的，说明这是一个“特殊”的查询语句。会传到备库的查询语句的一种情况：是这个语句写在存储过程中。
怀疑点：用户调用存储过程
带着疑点去数据库中查询是否有调用存储过程：
（1）、查询 mysql.proc查看到用户有存储过程：

MySQL [(none)]> select name,type,specific_name from mysql.proc;
+-----------------------------+-----------+-----------------------------+
| name                        | type      | specific_name               |
+-----------------------------+-----------+-----------------------------+
| currentLtvFun               | FUNCTION  | currentLtvFun               |
| NewProc                     | FUNCTION  | NewProc | | channel_daily_report | PROCEDURE | channel_daily_report | | channel_daily_report_manual | PROCEDURE | channel_daily_report_manual | | currentLtv | PROCEDURE | currentLtv | | insert_channel_daily_report | PROCEDURE | insert_channel_daily_report | | insetLtvInfo | PROCEDURE | insetLtvInfo | | ltvinfo | PROCEDURE | ltvinfo | | retainLtv | PROCEDURE | retainLtv | +-----------------------------+-----------+-----------------------------+ 9 rows in set (0.00 sec) 

（2）、查询存储过程中是否有执行的该查询的SQL：

MySQL [(none)]> select * from mysql.proc where body like '%select sum(a.payment)/100%'\G;
查询到这两个FUNCTION：
| currentLtvFun               | FUNCTION  | currentLtvFun | | NewProc | FUNCTION | NewProc | MySQL [(none)]> select * from mysql.proc where body like '%NewProc%'\G; Empty set (0.00 sec) mysql.proc 中查询不到NewProc，可以排除NewProc方法 MySQL [(none)]> select * from mysql.proc where body like '%currentLtvFun%'\G; *************************** 1. row *************************** db: rw_upms name: currentLtv type: PROCEDURE specific_name: currentLtv 【此处省略200行代码】 UPDATE rw_upms.statis_current_ltv set recharge_amount = currentLtvFun(reqDate, gameVersion, sdkChannel, advIdentification) where ltv_id = ltvId 

我们可以得出存储过程currentLtv中调用了函数currentLtvFun，函数currentLtvFun
中执行的就是“select sum(a.payment)/100 ”。

存储过程比较长，这里简单梳理调用过程：

[ currentLtv调用过程 ]

 

用户调用存储过程call currentLtv()，存储过程通过逻辑判断，执行update
【UPDATE rw_upms.statis_current_ltv set recharge_amount = currentLtvFun(reqDate, gameVersion, sdkChannel, advIdentification) where ltv_id = ltvId;】调用函数currentLtvFun，该函数我们上面已经截图，是一个很大的select【select sum(a.payment)/100……】返回值。

这就验证了我们前面的猜想，这个select语句来源于主库的存储过程，并且传给备库执行。
再深入看这个存储过程的实现，update语句会调用函数currentLtvFun，函数currentLtvFun是一个非常大的查询，执行也会比较耗时。

• • 解决方案：

    现在知道原因了，备库在执行这个存储过程的时候，也需要调用函数currentLtvFun，很耗时。
    一个比较简单的做法，就是把主库的binlog_format 修改成row。这样从库就只会同步“更新后的结果”，而不需要同步“更新的计算过程”，也就是不用调用这个耗时函数了。
    （1）、当binlog_format=mixed时，binlog结果如下：

    
    
    （2）、binlog_format=row时，binlog结果如下：
    
    
    
    通过修改不binlog_format验证结果。当binlog_format=row时解析binlog记录的是修改后的值，从库回放binlog执行每条update语句不需要再去调用一次函数，再观察备机和RO，也看不到之前的select操作，show slave status查询也观察到没有延迟。

     

  • 小结：

      1. 主从延迟原因。
      2. 通过分析备机有来自root %账号的查询反推调用存储过程。
      3. 存储过程调用会fork一个新线程去执行body的内容。
      4. binlog_format格式不同，记录的binlog日志不一样，mixed格式将update转译为具体的sql语句执行，每条update都会调用一次函数。而设置row格式后，binlog记录的是主库修改后的数据，在从库回放也是单纯执行update跟修改后的值。
      5. 这次是通过改binlog_format=row格式解决主从延迟问题。
      6. 思考：把参数binlog_format设置为row格式就是最佳实践吗？【下次分享一个存储过程中delete分区表数据导致的主从延迟案例】

转载于:https://www.cnblogs.com/sallyluo/p/11307525.html