主从延迟案例分析一
-
问题背景：
在我们实际工作过程中，会遇到形形色色的数据库问题，有些问题可以迎刃而解，而有的问题处理起来却比较让人揪心，比如说“延迟问题”。你是否也在工作中遇到过类似的问题呢？它到底是怎么造成的呢？我们该如何处理呢？
首先，我们先来看一个用户主从延迟的案例：
【下面展示步骤为测试环境复现用户主从延迟场景】 -
排查步骤：
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 ”。
存储过程比较长，这里简单梳理调用过程：
用户调用存储过程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分区表数据导致的主从延迟案例】
