从Mysql slave system lock延迟说开去

本文主要分析 sql thread中system lock出现的原因，但是笔者并明没有系统的学习过master-slave的代码，这也是2018年的一个目标，2018年我都排满了，悲剧。所以如果有错误请指出，也作为一个笔记用于后期学习。同时也给出笔者现在知道的几种造成延迟的可能和延迟计算的方式。

  • 本文基于5.7.17源码
  • 本文只考虑row 格式binlog
  • 主要考虑DML语句，DDL语句比较简单不做考虑

一、延迟的计算方式

其实每次show slave status命令的时候后台会调用函数show_slave_status_send_data进行及时计算，这个延迟并不是保存在哪里的。栈帧如下：

#0  show_slave_status_send_data (thd=0x7fffd8000cd0, mi=0x38ce2e0, io_gtid_set_buffer=0x7fffd800eda0 "e859a28b-b66d-11e7-8371-000c291f347d:42-100173", sql_gtid_set_buffer=0x7fffd8011ac0 "e859a28b-b66d-11e7-8371-000c291f347d:1-100173") at /mysql/mysql-5.7.17/sql/rpl_slave.cc:3602
#1  0x0000000001867749 in show_slave_status (thd=0x7fffd8000cd0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:3982
#2  0x0000000001867bfa in show_slave_status_cmd (thd=0x7fffd8000cd0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:4102

其计算方式基本就是这段代码

time_diff= ((long)(time(0) - mi->rli->last_master_timestamp) - mi->clock_diff_with_master);

稍微解释一下：

  • time(0) ：取当前slave服务器系统时间。
  • mi->rli->last_master_timestamp：是event common header中timestamp的时间+exetime，其中exetime只有query event才有，其他全部是0,这也导致了binlog row格式下的延迟最大基本是(2 乘以主库的执行的时间)，但是DDL的语句包含在query event中索引延迟最大基本就是(1 乘以 主库执行时间)
  • mi->clock_diff_with_master：这是从库和主库时间的差值。

这里我们也看到event中common header中的timestamp和slave本地时间起了决定因素。因为每次发起命令time(0)都会增加，所以即便event中common header中的timestamp的时间不变延迟也是不断加大的。

另外还有一段有名的伪代码如下：

 /*The pseudo code to compute Seconds_Behind_Master:if (SQL thread is running){if (SQL thread processed all the available relay log){if (IO thread is running)print 0;elseprint NULL;}elsecompute Seconds_Behind_Master;}elseprint NULL;*/

其实他也来自函数 show_slave_status_send_data，有兴趣的自己在看看。我就不过多解释了。

这部分还可以参考一下淘宝内核月报

  • https://www.kancloud.cn/taobaomysql/monthly/140089
    这也是后期我还要学习的文章。

二、Binlog写入Binlog文件时间和event生成的时间

我发现有朋友这方面有疑问就做个简单的解释

  • binlog真正从binglog cache/tmp file写入binlog文件是在commit的flush阶段然后sync阶段才落盘，传输是在order commit的flush后。
  • event生成是在语句执行期间，具体各个event生成时间如下：
  1. 如果没有显示开启事物，Gtid event/query event/map event/dml event/xid event均是命令发起时间
  2. 如果显示开始事物 Gtid event/xid event是commit命令发起时间，其他event是dml语句发起时间

所以binlog写入到binlog文件或者什么时候传输到slave和event的生成没有什么联系。
下面是一个小事物典型的event生命周期

>Gtid Event:Pos:234(0Xea) N_pos:299(0X12b) Time:1513135186 Event_size:65(bytes) 
Gtid:31704d8a-da74-11e7-b6bf-52540a7d243:100009 last_committed=0  sequence_number=1
-->Query Event:Pos:299(0X12b) N_Pos:371(0X173) Time:1513135186 Event_size:72(bytes) 
Exe_time:0  Use_db:test Statment(35b-trun):BEGIN /*!Trx begin!*/ Gno:100009
---->Map Event:Pos371(0X173) N_pos:415(0X19f) Time:1513135186 Event_size:44(bytes) 
TABLE_ID:108 DB_NAME:test TABLE_NAME:a Gno:100009
------>Insert Event:Pos:415(0X19f) N_pos:455(0X1c7) Time:1513135186 Event_size:40(bytes) 
Dml on table: test.a  table_id:108 Gno:100009 
>Xid Event:Pos:455(0X1c7) N_Pos:486(0X1e6) Time:1513135186 Event_size:31(bytes) 
COMMIT; /*!Trx end*/ Gno:100009

三、造成延迟的可能原因

这部分是我总结现有的我知道的原因：

  • 大事物延迟 延迟略为2*执行时间 状态为:reading event from the relay log
  • 大表DDL延迟 延迟略为1*执行时间 状态为:altering table
  • 长期未提交的事物延迟，会造成延迟的瞬时增加
  • 表上没有主键或者唯一键 状态为:system lock 或者 reading event from the relay log
  • innodb层锁造成延迟 状态为:system lock 或者 reading event from the relay log
  • 从库参数设置如sync_binlog，sync_relay_log，innodb_flush_log_at_trx_commit等参数

这些原因都是我遇到过的。接下来我想分析一下从库system lock形成的原因。

四、问题由来

问题主要是出现在我们的线上库的从库上，我们经常发现某些数据量大的数据库，sql thread经常处于system lock状态下，大概表现如下：

mysql> show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+
| Id | User        | Host      | db   | Command | Time | State                            | Info             |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+
|  3 | root        | localhost | test | Sleep   |  426 |                                  | NULL             |
|  4 | system user |           | NULL | Connect | 5492 | Waiting for master to send event | NULL             |
|  5 | system user |           | NULL | Connect |  104 | System lock                      | NULL             |
|  6 | root        | localhost | test | Query   |    0 | starting                         | show processlist |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+

对于这个状态官方有如下描述:

The thread has called mysql_lock_tables() and the thread state has not been updated since.
This is a very general state that can occur for many reasons.
For example, the thread is going to request or is waiting for an internal or external system lock for the
table. This can occur when InnoDB waits for a table-level lock during execution of LOCK TABLES.
If this state is being caused by requests for external locks and you are not using multiple mysqld
servers that are accessing the same MyISAM tables, you can disable external system locks with the
--skip-external-locking option. However, external locking is disabled by default, so it is likely
that this option will have no effect. For SHOW PROFILE, this state means the thread is requesting the
lock (not waiting for it).

显然不能解决我的问题，一时间也是无语。而我今天在测试从库手动加行锁并且sql thread冲突的时候发现了这个状态，因此结合gdb调试做了如下分析，希望对大家有用，也作为后期我学习的一个笔记。

五、system lock 延迟的原因

这里直接给出原因供大家直接参考:
必要条件：
由于大量的小事物如UPDATE/DELETE table where一行数据，这种只包含一行DML event的语句，table是一张大表。

  • 这个表上没有主键或者唯一键。
  • 由于类似innodb lock堵塞，也就是slave从库修改了数据同时和sql_thread也在修改同样的数据。
  • 确实I/O扛不住了，可以尝试修改参数。

如果是大量的表没有主键或者唯一键可以考虑修改参数slave_rows_search_algorithms 试试。但是innodb中不用主键或者主键不选择好就等于自杀。

六、system lock 延迟的问题分析

下面的分析是我通过gdb代码得出的结论可能有误
我们知道所有的state都是mysql上层的一种状态，如果要发生状态的改变必须要调用THD::enter_stage来改变，而system lock则是调用mysql_lock_tables进入的状态，同时从库SQL_THREAD中还有另外一种状态重要的状态reading event from the relay log。

这里是rpl_slave.cc handle_slave_sql函数中的很小的一部分主要用来证明我的分析。

/* Read queries from the IO/THREAD until this thread is killed */while (!sql_slave_killed(thd,rli)) //大循环{THD_STAGE_INFO(thd, stage_reading_event_from_the_relay_log); //这里进入reading event from the relay log状态if (exec_relay_log_event(thd,rli)) //这里会先调入next_event函数读取一条event，然后调用lock_tables但是如果不是第一次调用lock_tables则不需要调用mysql_lock_tables//逻辑在lock_tables调用mysql_lock_tables则会将状态置为system lock，然后进入innodb层进行数据的查找和修改}

这里还特地请教了阿里的印风兄验证了一下mysql_lock_tables是myisam实现表锁的函数innodb会设置为共享锁。

这里我们先抛开query event/map event等。只考虑DML event

  • 如果一个小事物只有一条DML event的场景下逻辑如下：
->进入reading event from the relay log状态 ->读取一条event(参考next_event函数)->进入system lock状态->innodb层进行查找和修改数据
  • 如果是一个大事物则包含了多条DML event的场景逻辑如下:
->进入reading event from the relay log状态 ->读取一条event(参考next_event函数)->进入system lock状态->innodb层进行查找和修改数据
->进入reading event from the relay log状态 ->读取一条event(参考next_event函数)->innodb层进行查找和修改数据
->进入reading event from the relay log状态 ->读取一条event(参考next_event函数)->innodb层进行查找和修改数据
....直到本事物event执行完成

因此我们看到对于一个小事物我们的sql_thread会在加system lock的情况下进行对数据进行查找和修改，因此得出了我的结论，同时如果是innodb 层 锁造成的sql_thread堵塞也会在持有system lock的状态下。但是对于一个大事物则不一样，虽然出现同样的问题的但是其状态是reading event from the relay log。所以如果出现system lock一般就是考虑前文给出的结论，但是前文给出的结论不一定都会引起system lock，这个要看是否是大事物。

以下的部分是我进行gdb的时候用到断点和栈帧是我自己看的

七、分析中用到的断点

  • mysql_lock_tables 本函数更改状态为system lock
    gdb打印:p tables[0]->s->table_name
  • THD::enter_stage 本函数改变状态
    gdb打印:p new_stage->m_name
  • ha_innobase::index_read innodb查找数据接口
    gdb打印:p index->table_name
  • ha_innobase::delete_row innodb删除数据接口
  • exec_relay_log_event 获取event并且应用
  1. 打印:ev->get_type_code()

八、两个栈帧

  • 进入system lock状态
#0  THD::enter_stage (this=0x7fffec000970, new_stage=0x2ccd180, old_stage=0x0, calling_func=0x2216fd0 "mysql_lock_tables", calling_file=0x22167d8 "/mysql/mysql-5.7.17/sql/lock.cc", calling_line=323) at /mysql/mysql-5.7.17/sql/sql_class.cc:731
#1  0x00000000017451a6 in mysql_lock_tables (thd=0x7fffec000970, tables=0x7fffec005e38, count=1, flags=0) at /mysql/mysql-5.7.17/sql/lock.cc:323
#2  0x00000000014fe8da in lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, count=1, flags=0) at /mysql/mysql-5.7.17/sql/sql_base.cc:6630
#3  0x00000000014fe321 in open_and_lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, flags=0, prelocking_strategy=0x7ffff14e2360)at /mysql/mysql-5.7.17/sql/sql_base.cc:6448
#4  0x0000000000eee1d2 in open_and_lock_tables (thd=0x7fffec000970, tables=0x7fffec012b70, flags=0) at /mysql/mysql-5.7.17/sql/sql_base.h:477
#5  0x000000000180e7c5 in Rows_log_event::do_apply_event (this=0x7fffec024790, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10626
#6  0x00000000017f7b7b in Log_event::apply_event (this=0x7fffec024790, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:3324
#7  0x00000000018690ff in apply_event_and_update_pos (ptr_ev=0x7ffff14e2818, thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:4709
#8  0x000000000186a7f2 in exec_relay_log_event (thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:5224//这里可以看到不同event不同的处理
#9  0x0000000001870db6 in handle_slave_sql (arg=0x357fc50) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:7332//这里是整个主逻辑
#10 0x0000000001d5442c in pfs_spawn_thread (arg=0x7fffd88fb870) at /mysql/mysql-5.7.17/storage/perfschema/pfs.cc:2188
#11 0x00007ffff7bc7851 in start_thread () from /lib64/libpthread.so.0
#12 0x00007ffff672890d in clone () from /lib64/libc.so.6
  • 在system lock状态下查找数据
#0  ha_innobase::index_read (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY)at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:8540
#1  0x000000000192126c in ha_innobase::index_first (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y")at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:9051
#2  0x00000000019214ba in ha_innobase::rnd_next (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y") at /mysql/mysql-5.7.17/storage/innobase/handler/ha_innodb.cc:9149
#3  0x0000000000f4972c in handler::ha_rnd_next (this=0x7fffec0294c0, buf=0x7fffec0297b0 "\375\311y") at /mysql/mysql-5.7.17/sql/handler.cc:2947
#4  0x000000000180e1a9 in Rows_log_event::do_table_scan_and_update (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10475
#5  0x000000000180f453 in Rows_log_event::do_apply_event (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:10941
#6  0x00000000017f7b7b in Log_event::apply_event (this=0x7fffec035c20, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/log_event.cc:3324
#7  0x00000000018690ff in apply_event_and_update_pos (ptr_ev=0x7ffff14e2818, thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:4709
#8  0x000000000186a7f2 in exec_relay_log_event (thd=0x7fffec000970, rli=0x393b9c0) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:5224
#9  0x0000000001870db6 in handle_slave_sql (arg=0x357fc50) at /mysql/mysql-5.7.17/sql/rpl_slave.cc:7332
#10 0x0000000001d5442c in pfs_spawn_thread (arg=0x7fffd88fb870) at /mysql/mysql-5.7.17/storage/perfschema/pfs.cc:2188
#11 0x00007ffff7bc7851 in start_thread () from /lib64/libpthread.so.0
#12 0x00007ffff672890d in clone () from /lib64/libc.so.6

作者微信：
微信.jpg

本文来自互联网用户投稿，该文观点仅代表作者本人，不代表本站立场。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如若转载，请注明出处：http://www.mzph.cn/news/391555.shtml

如若内容造成侵权/违法违规/事实不符，请联系多彩编程网进行投诉反馈email:809451989@qq.com，一经查实，立即删除！

相关文章

传智播客全栈_播客：从家庭学生到自学成才的全栈开发人员

传智播客全栈_播客：从家庭学生到自学成才的全栈开发人员

传智播客全栈In this weeks episode of the freeCodeCamp podcast, Abbey chats with Madison Kanna, a full-stack developer who works remotely for Mediavine. Madison describes how homeschooling affected her future learning style, how she tackles imposter syndrom…
阅读更多...
leetcode 82. 删除排序链表中的重复元素 II（map）

leetcode 82. 删除排序链表中的重复元素 II（map）

解题思路 map记录数字出现的次数，出现次数大于1的数字从链表中移除 代码 /*** Definition for singly-linked list.* public class ListNode {* int val;* ListNode next;* ListNode() {}* ListNode(int val) { this.val val; }* ListNode(…
阅读更多...
python 列表、字典多排序问题

python 列表、字典多排序问题

版权声明：本文为博主原创文章，遵循 CC 4.0 by-sa 版权协议，转载请附上原文出处链接和本声明。本文链接：https://blog.csdn.net/justin051/article/details/84289189Python使用sorted函数来排序： l [2,1,3,5,7,3]print…
阅读更多...
接facebook广告_Facebook广告分析

接facebook广告_Facebook广告分析

接facebook广告Is our company’s Facebook advertising even worth the effort?我们公司的Facebook广告是否值得努力？ 题： (QUESTION:) A company would like to know if their advertising is effective. Before you start, yes…. Facebook does ha…
阅读更多...
如何创建自定义进度栏

如何创建自定义进度栏

Originally published on www.florin-pop.com最初发布在www.florin-pop.com The theme for week #14 of the Weekly Coding Challenge is: 每周编码挑战第14周的主题是： 进度条 (Progress Bar) A progress bar is used to show how far a user action is still in…
阅读更多...
基于SpringBoot的CodeGenerator

基于SpringBoot的CodeGenerator

title: 基于SpringBoot的CodeGenerator tags: SpringBootMybatis生成器PageHelper categories: springboot date: 2017-11-21 15:13:33背景 目前组织上对于一个基础的crud的框架需求较多 因此选择了SpringBoot作为基础选型。 Spring Boot是由Pivotal团队提供的全新框架&#xf…
阅读更多...
seaborn线性关系数据可视化：时间线图|热图|结构化图表可视化

seaborn线性关系数据可视化：时间线图|热图|结构化图表可视化

一、线性关系数据可视化lmplot( ) 表示对所统计的数据做散点图，并拟合一个一元线性回归关系。 lmplot(x, y, data, hueNone, colNone, rowNone, paletteNone,col_wrapNone, height5, aspect1,markers"o", sharexTrue,shareyTrue, hue_orderNone, col_orde…
阅读更多...
hdu 1257

hdu 1257

http://acm.hdu.edu.cn/showproblem.php?pid1257 题意：有个拦截系统，这个系统在最开始可以拦截任意高度的导弹，但是之后只能拦截不超过这个导弹高度的导弹，现在有N个导弹需要拦截，问你最少需要多少个拦截系统 思路&am…
阅读更多...
eda可视化_5用于探索性数据分析（EDA）的高级可视化

eda可视化_5用于探索性数据分析（EDA）的高级可视化

eda可视化Early morning, a lady comes to meet Sherlock Holmes and Watson. Even before the lady opens her mouth and starts telling the reason for her visit, Sherlock can tell a lot about a person by his sheer power of observation and deduction. Similarly, we…
阅读更多...
我的AWS开发人员考试未通过。 现在怎么办？

我的AWS开发人员考试未通过。 现在怎么办？

I have just taken the AWS Certified Developer - Associate Exam on July 1st of 2019. The result? I failed.我刚刚在2019年7月1日参加了AWS认证开发人员-联考。结果如何？ 我失败了。 The AWS Certified Developer - Associate (DVA-C01) has a scaled score …
阅读更多...
关系数据可视化gephi

关系数据可视化gephi

表示对象之间的关系，可通过gephi软件实现，软件下载官方地址https://gephi.org/users/download/ 如何来表示两个对象之间的关系？ 把对象变成点，点的大小、颜色可以是它的两个参数，两个点之间的关系可以用连线表示。连线…
阅读更多...
Hyperledger Fabric 1.0 从零开始（十二）——fabric-sdk-java应用

Hyperledger Fabric 1.0 从零开始（十二）——fabric-sdk-java应用

Hyperledger Fabric 1.0 从零开始（十）——智能合约（参阅：Hyperledger Fabric Chaincode for Operators——实操智能合约） Hyperledger Fabric 1.0 从零开始（十一）——CouchDB（参阅&a…
阅读更多...
css跑道_如何不超出跑道：计划种子的简单方法

css跑道_如何不超出跑道：计划种子的简单方法

css跑道There’s lots of startup advice floating around. I’m going to give you a very practical one that’s often missed — how to plan your early growth. The seed round is usually devoted to finding your product-market fit, meaning you start with no or li…
阅读更多...
将json 填入表格_如何将Google表格用作JSON端点

将json 填入表格_如何将Google表格用作JSON端点

将json 填入表格UPDATE: 5/13/2020 - New Share Dialog Box steps available below.更新：5/13/2020-下面提供了 新共享对话框步骤。 Thanks Erica H!谢谢埃里卡H！ Are you building a prototype dynamic web application and need to collaborate with …
阅读更多...
leetcode 173. 二叉搜索树迭代器

leetcode 173. 二叉搜索树迭代器

实现一个二叉搜索树迭代器类BSTIterator ，表示一个按中序遍历二叉搜索树（BST）的迭代器： BSTIterator(TreeNode root) 初始化 BSTIterator 类的一个对象。BST 的根节点 root 会作为构造函数的一部分给出。指针应初始化为一个不存在…
阅读更多...
jyputer notebook 、jypyter、IPython basics

jyputer notebook 、jypyter、IPython basics

1 、修改jupyter默认工作目录：打开cmd，在命令行下指定想要进的工作目录，即键入“cd d/ G:\0工作面试\学习记录”标红部分是想要进入的工作目录。 2、Tab补全 a、在命令行输入表达式时，按下Tab键即可为任意变量（对象、…
阅读更多...
cookie和session（1）

cookie和session（1）

cookie和session 1.cookie产生 识别用户 HTTP是无状态协议，这就回出现这种现象：当你登录一个页面，然后转到登录网站的另一个页面，服务器无法认识到。或者说两次的访问，服务器不能认识到是同一个客户端的访问&#xff0…
阅读更多...
熊猫数据集_为数据科学拆箱熊猫

熊猫数据集_为数据科学拆箱熊猫

熊猫数据集If you are already familiar with NumPy, Pandas is just a package build on top of it. Pandas provide more flexibility than NumPy to work with data. While in NumPy we can only store values of single data type(dtype) Pandas has the flexibility to st…
阅读更多...
2018年，你想从InfoQ获取什么内容？丨Q言Q语

2018年，你想从InfoQ获取什么内容？丨Q言Q语

- Q 言 Q 语 第 三 期 - Q言Q语是 InfoQ 推出的最新板块， 旨在给所有 InfoQer 一个展示观点的平台。 每期一个主题， 不扣帽子，不论对错，不看输赢， 只愿跟有趣的灵魂相遇。 本期话题： 2018年，你想…
阅读更多...
特征阻抗输入阻抗输出阻抗_软件阻抗说明

特征阻抗输入阻抗输出阻抗_软件阻抗说明

特征阻抗输入阻抗输出阻抗by Milan Mimica米兰米米卡(Milan Mimica) 软件阻抗说明 (Software impedance explained) 数据处理组件之间的阻抗不匹配 (The impedance mismatch between data processing components) It all starts with the simplest signal-processing diagram …
阅读更多...
最新文章

Copyright @ 2022~2023