主从延迟案例二
一、问题背景：
用户反馈主从延迟很大，经过排查分析得知：用户每天凌晨00:05分开始调用存储过程SP_DELETE_HIS ，删除表t_today 前一天的历史数据以及t_hist 表除了’00’,’10’...’50’整点的全部数据；同时用户还时时在往存储过程中涉及的表插入数据。了解用户背景后我们进一步分析延迟问题。
【下面截图为测试环境复现场景】
二、演示步骤：
1、查询存储过程SP_DELETE_HIS：
SET SESSION TRANSACTION ISOLATION LEVEL read committed;
IF a_id = -1
THEN
delete from t_hist
where update_datetime < DATE_ADD(B_DATE,INTERVAL -1 day)
and DATE_FORMAT(update_datetime,'%i') not in ('00','10','20','30','40','50');
delete from t_today
where update_datetime < B_DATE;
COMMIT;
ELSE
delete from t_hist
WHERE farm_id = a_id AND update_datetime BETWEEN B_DATE AND E_DATE;
COMMIT;
end if;
INSERT INTO t_log(SP_NAME, BEGIN_TIME, END_TIME, RESULT,CREATE_TIME)
SELECT V_SP_NAME, V_BEGIN_TIME, V_END_TIME, 'SUCCESSED',SYSDATE();
COMMIT;
SET SESSION TRANSACTION ISOLATION LEVEL repeatable read;
2、业务场景：
（1）、数据库版本：
5.7.18
（2）、测试数据准备：
主库调用存储过程：
从库延迟状态：
从库执行多次show slave status，Relay_Log_File和Relay_Log_Pos一直卡着不变，Seconds_Behind_Master值也持续增大未有变小的迹象。
分析Relay_Log_File和Relay_Log_Pos查询卡着的点：
执行：show create table ss_db.t_hist;查询表结构得知t_hist为分区表，这里查询分区表t_hist分区个数可知该表有7200个分区：
（3）和用户确认用户每天凌晨00:05分调用存储过程SP_DELETE_HIS删除分区表数据：
delete from t_hist
where update_datetime < DATE_ADD(B_DATE,INTERVAL -1 day)
and DATE_FORMAT(update_datetime,'%i') not in ('00','10','20','30','40','50');
为什么调用存储过程删除分区表数据会导致主从延迟呢？
解决这个问题需要了解一些mysql基础知识：
mysql存储过程中的本地变量会被一个内部函数name_const转化。参考https:/dev.mysql.com/doc/refman/5.7/en/stored-programs-logging.html
mysql 5.7.20前调用存储过程delete 分区表会转成row格式。
深入分析下为什么这么耗时？
我们使用gdb工具对mysql线程进行分析：
[root@TENCENT64 ~]# gdb -p 40385
切换到第56个线程, 可以看到线程id 为 0x7f8381966700，用bt 可以打印函数堆栈信息：
下面对堆栈信息进一步分析：
ha_innopart.cc
partition_info.h
my_bitmap.c
perf top -p 40385
bitmap_get_next_set函数调用占到 73.65%，非常的高，其次是build_template_field占到10.85%，第三是try_semi_consistent_read占到6.17%
从这个数据可以看出，mysql一直在调用bitmap_get_next_set函数
综合上面堆栈信息：调用函数try_semi_consistent_read[从第一个分区到最后一个分区，即扫描7200个分区]——>调用函数get_next_used_partition[传入分区号调用函数bitmap_get_next_set]
假设delete删除的是100w行数据，数据库要调用1000000*7200=7200000000=72亿
所以看到的“同步卡着不动并非真的不动，而是因为跑的次数太多，花费时间很长”。
补充测试一下delete 336 条数据同步耗费的时间大概12分钟左右，再次证明延迟时间和数据量也是有关系的。
注意：这里抓的是自己的测试实例可以使用gdb【这里暂时不做分析，以后再补上】，线上建议使用pstack抓。
三、建议：
1、和内核兄弟评估后建议将官方代码合并过来修复该bug，预计5月下旬上线。
2、上面bug在存储过程中才出现，使用脚本执行删除语句且binlog_format=mixed格式会将删除语句转为sql执行，这样从库延迟也就等价在从库执行delete sql的时间，并不会造成长时间的延迟。
【由于用户人力有限等原因，并不愿意改写脚本跑存储过程的逻辑】
2、修改存储过程将隔离级别改为默认的RR隔离级别，执行set session binlog_format = statement让产生的binlog为具体sql，这里改写后的新存储过程SP_DELETE_HIS_1，下面展示新存储过程核心代码：
set session binlog_format = statement;
show variables like 'binlog_format';
IF fa_id = -1 and hs_id = -1 and ba_no = -1
THEN
delete from t_hist
where update_datetime < B_DATE_UP
and DATE_FORMAT(update_datetime,'%i') not in ('00','10','20','30','40','50');
delete from t_today
where update_datetime < B_DATE;
COMMIT;
ELSE
delete from t_hist
WHERE farm_id = fa_id AND house_id = hs_id AND batch_no = ba_no AND update_datetime BETWEEN B_DATE AND E_DATE;
COMMIT;
end if;
INSERT INTO t_log(SP_NAME, BEGIN_TIME, END_TIME, RESULT,CREATE_TIME)
SELECT V_SP_NAME, V_BEGIN_TIME, V_END_TIME, 'SUCCESSED',NOW();
COMMIT;
SET SESSION TRANSACTION ISOLATION LEVEL repeatable read;
风险点：存储过程修改为RR隔离级别delete t_hist表数据，且delete分区表数据执行时间比较长，很容易与用户时时向该表插入数据产生锁冲突。
这点我们在用户测试环境也复现了。
解析binlog可确认存储过程调用执行delete落地到binlog为sql语句：
3、因为从库延迟很大，现在从库备份是失效的，所以在用户修改存储过程期间我们每天在主库上进行全备份，并将备份拷贝到从库，时时拉取主库binlog保存在从库，运维层面保留备份数据。
4、用户使用DTS任务每天执行完存储过程后发起DTS任务将数据同步到新实例，且保证时时同步。
四、小结&思考
1、MDL锁问题：
分区表在server层是1个表，在引擎层，认为这是不同的表，因此MDL锁之后的执行过程，会根据分区表规则，只访问必要的分区。
分区表只有一个MDL锁，在做DDL操作时，分区表相对于普通分表而言影响会更大。
现在很多中间件都支持打造分表，程序也可以通过比较小的改造实现分表。
2、分区表是不是越细越好呢？
不是，建议一个分区表不要创建过多分区，因为“mysql在第一次打开分区表的时候，需要访问所有分区，对于MyISAM表，会受参数open_files_limit限制 ，由于分区表文件过多会导致打开表文件个数超过上限而报错；对于InnoDB表，如果需要打开的文件数大于innodb_open_files，会导致InnoDB管理文件句柄代价增加，影响性能”。现在硬件一个表没有特别大的索引的话，单个分区数据在500w行也是没有太大问题的。如：业务每天做一个分区，不建议一次性创建很多年的分区表，建议定时添加和删除分区。
3、分区表使用场景：
（1）、对业务透明。
（2）、没有特别多分区的业务。
（3）、定期删除分区文件：使用alter table xx drop partition定期删除分区文件比做delete删除要快，对系统影响小，还会回收空间。
