本文主要分析 sql thread中system lock出现的原因，但是笔者并明没有系统的学习过master-slave的代码，这也是2018年的一个目标，2018年我都排满了，悲剧。所以如果有错误请指出，也作为一个笔记用于后期学习。同时也给出笔者现在知道的几种造成延迟的可能和延迟计算的方式。
其实每次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);
稍微解释一下：
这里我们也看到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; else print NULL;
} else compute Seconds_Behind_Master;
} else print NULL;
*/
其实他也来自函数 show_slave_status_send_data，有兴趣的自己在看看。我就不过多解释了。
这部分还可以参考一下淘宝内核月报
我发现有朋友这方面有疑问就做个简单的解释
当然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
这部分是我总结现有的我知道的原因：
这些原因都是我遇到过的。接下来我想分析一下从库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调试做了如下分析，希望对大家有用，也作为后期我学习的一个笔记。
这里直接给出原因供大家直接参考:
必要条件：
由于大量的小事物如UPDATE/DELETE table where一行数据，这种只包含一行DML event的语句，table是一张大表。
如果是大量的表没有主键或者唯一键可以考虑修改参数slave_rows_search_algorithms 试试。但是innodb中不用主键或者主键不选择好就等于自杀。
下面的分析是我通过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
->进入reading event from the relay log状态
->读取一条event(参考next_event函数)
->进入system lock状态
->innodb层进行查找和修改数据
->进入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并且应用
gdb 打印:ev->get_type_code()
#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
#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
作者微信：
免责声明：本站发布的内容（图片、视频和文字）以原创、转载和分享为主，文章观点不代表本网站立场，如果涉及侵权请联系站长邮箱：is@yisu.com进行举报，并提供相关证据，一经查实，将立刻删除涉嫌侵权内容。
