数据库内核月报 - 2015 / 10-MySQL · 捉虫动态 · start slave crash 诊断分析

本文涉及的产品
RDS MySQL DuckDB 分析主实例,集群系列 4核8GB
RDS AI 助手,专业版
RDS MySQL DuckDB 分析主实例,基础系列 4核8GB
简介:

问题现象

研发同学执行下列语句序列

stop slave; set global slave_parallel_workers=0; start slave;

后程序 hang 住,不一会返回了2013 错误,即服务器连接异常中断,检查 mysqld error log, 发现在mysqld在将并行复制转化为串行复制的过程中异常 crash,其中错误信息为:

[ERROR] Error reading slave worker configuration
[ERROR] Error creating relay log info: Failed to initialize the worker info structure.

crash 堆栈为:

#0  0x000000395fc0c69c in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000006b2425 in handle_fatal_signal (sig=11)
#2  <signal handler called>
#3  remove_info (this=0x2b19b775b000)
#4  Relay_log_info::mts_finalize_recovery
#5  0x0000000000920ec3 in slave_start_workers
#6  0x0000000000921c03 in handle_slave_sql
#7  0x000000395fc07851 in start_thread () from /lib64/libpthread.so.0
#8  0x000000395f4e767d in clone () from /lib64/libc.so.6

结合源码仔细分析上面的错误信息不难发现,在启动 SQL 线程初始化 worker 信息的过程中失败,从而引起了空指针异常。

问题复现

一个简单的 start slave 就能够导致 mysqld crash?应该不会那么简单,编写 testcase,试图在本地重现以上问题,测例如下:

--source include/master-slave.inc
--source include/not_embedded.inc
--source include/not_windows.inc
--connection slave
stop slave;
set global slave_parallel_workers= 1;
start slave;

stop slave;
set global slave_parallel_workers= 0;
start slave;

--source include/rpl_end.inc

运行后果然没有能够重现问题,根据研发的同学反映在中断之前有一段时间命令是 hang 住的,于是断定 hang 问题与 crash 应该存在着联系,以上测例并不能将问题重现,于是与求助研发同学进行联调,在 hang 住的时候采集到了以下关键 pt-pmp 信息:

pthread_cond_wait,os_cond_wait(os0sync.cc:214),os_event_wait_low(os0sync.cc:610),lock_wait_suspend_thread(lock0wait.cc:323),row_mysql_handle_errors(row0mysql.cc:1040),row_search_for_mysql(row0sel.cc:5064),ha_innobase::index_read(ha_innodb.cc:7668),ha_innobase::index_first(ha_innodb.cc:8041),ha_innobase::rnd_next(ha_innodb.cc:8138),handler::ha_rnd_next(handler.cc:2812),Rpl_info_table_access::scan_info(rpl_info_table_access.cc:287),Rpl_info_table::do_check_info(rpl_info_table.cc:444),Rpl_info_factory::decide_repository(rpl_info_factory.cc:567),Rpl_info_factory::create_worker(rpl_info_factory.cc:419),Relay_log_info::mts_finalize_recovery(rpl_rli.cc:328),slave_start_workers(rpl_slave.cc:6294),handle_slave_sql(rpl_slave.cc:6523),pfs_spawn_thread(pfs.cc:1858),start_thread(libpthread.so.0),clone(libc.so.6)

pthread_cond_wait,safe_cond_wait(thr_mutex.c:240),inline_mysql_cond_wait(mysql_thread.h:1151),start_slave_thread(rpl_slave.cc:1502),start_slave_threads(rpl_slave.cc:1587),start_slave(rpl_slave.cc:9485),start_slave(rpl_slave.cc:548),start_slave_cmd(rpl_slave.cc:690),mysql_execute_command(sql_parse.cc:3576),mysql_parse(sql_parse.cc:6958),dispatch_command(sql_parse.cc:1583),do_command(sql_parse.cc:1102),do_handle_one_connection(sql_connect.cc:1006),handle_one_connection(sql_connect.cc:922),pfs_spawn_thread(pfs.cc:1858),start_thread(libpthread.so.0),clone(libc.so.6)

可以看到在 start slave 后,sql thread 读取 slave_worker_info 初始化 worker 的过程中遇到了锁等待问题,于是断定 relay_log_info_repository=’table’,并且有其它的线程对 slave_worker_info中的记录上了X锁,但是是哪个线程确不是很清楚,因为只看到了一个线程在访问 slave_worker_info 表,然后再一次在hang的时候执行了下列操作:

mysql> SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, left(r.trx_query,20) waiting_query, concat(concat(lw.lock_type, ' '), lw.lock_mode) waiting_for_lock, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, left(b.trx_query,20) blocking_query, concat(concat(lb.lock_type, ' '), lb.lock_mode) blocking_lock FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id   INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id INNER JOIN information_schema.innodb_locks lw ON lw.lock_trx_id = r.trx_id INNER JOIN information_schema.innodb_locks lb ON lb.lock_trx_id = b.trx_id\G
*************************** 1. row ***************************
  waiting_trx_id: 1313
  waiting_thread: 12
   waiting_query: NULL
waiting_for_lock: RECORD S
 blocking_trx_id: 1312
 blocking_thread: 6
  blocking_query: start slave
   blocking_lock: RECORD X
1 row in set (0.00 sec)

mysql> show processlist;
+----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+
| Id | User        | Host            | db    | Command | Time | State                                   | Info             |
+----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+
|  2 | root        | localhost:57292 | test  | Sleep   |   16 |                                         |             |
|  3 | root        | localhost:57293 | test  | Sleep   |   16 |                                         |             |
|  6 | root        | localhost:57299 | test  | Query   |   15 | Waiting for slave thread to start       | start slave      |
|  7 | root        | localhost:57300 | test  | Sleep   |   16 |                                         |             |
| 11 | system user |                 | NULL  | Connect |   15 | Connecting to master                    |             |
| 12 | system user |                 | mysql | Connect |   15 | Waiting for the next event in relay log |             |
| 13 | root        | localhost       | test  | Query   |    0 | init                                    | show processlist |
+----+-------------+-----------------+-------+---------+------+-----------------------------------------+------------------+
7 rows in set (0.00 sec)

其中 information_schema.innodb_lock_waits,information_schema.innodb_locks,information_schema.innodb_trx 的信息可参考官方文档

从以上信息可以清楚地看到 start slave(blocking_thread: 6)获取了 slave_worker_info 中行记录的X锁,而 sql thread 线程 (waiting_thread: 12) 在获取 S 锁失败引起锁等待,进而获取信息失败返回NULL, 进而造成了空指针引用,mysqld crash,此时 start slave 与 sql thread 的资源竟争如下:

  • start slave thread 获取 slave_work_info 记录的 X 锁,等待 sql thread 已启动的信号量,然后继续运行;
  • sql thread 被启动后,需要根据 slave_worker_info 为进行初始化,因此等待获取相关行的S锁;

因此,start slave thread 与 sql thread 形成了死锁,分析到了现在还有两个疑问没有解释:

  • start slave 为什么会访问 slave_worker_info 且一直持有锁资源?
  • 为什么本地在测试的时候加上 relay_log_info_repository 的设置还是不能重现呢?

继续研究,打开general log 后,发现有许多的 set autocommit=0 的语句,于是感觉可能是 autocommit 的问题,修改后测例如下:

--source include/master-slave.inc
--source include/not_embedded.inc
--source include/not_windows.inc
--connection slave
stop slave;
set global relay_log_info_repository='table';
set global master_info_repository='table';
set global slave_parallel_workers= 1;
start slave;
--sleep 1

stop slave;
set autocommit=0;
set global slave_parallel_workers= 0;
start slave;

--source include/rpl_end.inc

运行后问题终于重现。。。

问题原因

有了以上的分析过程,不难看出,在 1) autocommit=0 && 2) relay_log_info_repository=’table’ && 3) 并行复制切换到串行复制时,就会触发此 bug, 原因有以下两个:

  • start slave thread 在等待 sql thread 的过程中没有释放其占用的锁资源;
  • sql thread 在初始化 worker 信息时没有处理获取信息失败的情况。

回到上面的问题:

  • start slave 为什么会访问 slave_worker_info 且一直持有锁资源?

    答:start slave 的过程中需要初始化 worker信息,执行 crash recovery 等一系列操作,对于已经执行的不再执行,对于没有执行的继续执行,详情见global_init_infomts_recovery_groups 等函数,在autocommit=0 的情况下,start slave thread 没有commit 或者执行完之前是不会释放锁资源的。

  • 为什么本地在测试的时候加上 relay_log_info_repository 的设置还是不能重现呢?

    答:本地在测试的时候,autocommit 默认值为1,因此不会重现。
    在上锁方面为什么会上写锁,可以参考:Rpl_info_table::do_init_info 函数;

  • 影响范围
    经官方验证,5.6, 5.6.26, 5.6.28, 5.7.10 均存在此 bug。

问题扩展

在排查问题的过程中发现 start slave 时会自动提交当前 session 之前已经操作的数据,然后开启一个新的事务,所以在使用 start slave 时要注意这个问题!

相关实践学习
每个IT人都想学的“Web应用上云经典架构”实战
本实验从Web应用上云这个最基本的、最普遍的需求出发,帮助IT从业者们通过“阿里云Web应用上云解决方案”,了解一个企业级Web应用上云的常见架构,了解如何构建一个高可用、可扩展的企业级应用架构。
MySQL数据库入门学习
本课程通过最流行的开源数据库MySQL带你了解数据库的世界。 &nbsp; 相关的阿里云产品:云数据库RDS MySQL 版 阿里云关系型数据库RDS(Relational Database Service)是一种稳定可靠、可弹性伸缩的在线数据库服务,提供容灾、备份、恢复、迁移等方面的全套解决方案,彻底解决数据库运维的烦恼。 了解产品详情:&nbsp;https://www.aliyun.com/product/rds/mysql&nbsp;
目录
相关文章
|
存储 消息中间件 人工智能
AI大模型独角兽 MiniMax 基于阿里云数据库 SelectDB 版内核 Apache Doris 升级日志系统,PB 数据秒级查询响应
早期 MiniMax 基于 Grafana Loki 构建了日志系统,在资源消耗、写入性能及系统稳定性上都面临巨大的挑战。为此 MiniMax 开始寻找全新的日志系统方案,并基于阿里云数据库 SelectDB 版内核 Apache Doris 升级了日志系统,新系统已接入 MiniMax 内部所有业务线日志数据,数据规模为 PB 级, 整体可用性达到 99.9% 以上,10 亿级日志数据的检索速度可实现秒级响应。
956 14
AI大模型独角兽 MiniMax 基于阿里云数据库 SelectDB 版内核 Apache Doris 升级日志系统,PB 数据秒级查询响应
|
监控 关系型数据库 MySQL
如何监控和诊断 MySQL 数据库的性能问题?
【10月更文挑战第28天】监控和诊断MySQL数据库的性能问题是确保数据库高效稳定运行的关键
1386 1
|
存储 SQL 关系型数据库
|
DataWorks 监控 关系型数据库
利用 DataWorks 数据推送定期推播 MySQL 或 StarRocks Query 诊断信息
DataWorks 近期上线了数据推送功能,能够将数据库查询的数据组织后推送到各渠道 (如钉钉、飞书、企业微信及 Teams),除了能将业务数据组织后推送,也能将数据库自身提供的监控数据组织后推送,这边我们就以 MySQL (也适用于StarRocks) 为例,定期推播 MySQL 的数据量变化等信息,帮助用户掌握 MySQL 状态。
386 1
|
网络协议 关系型数据库 MySQL
启动mysql时的异常为:[ERROR] Can‘t start server: Bind on TCP/IP port. Got error: 98: Address already in used
启动mysql时的异常为:[ERROR] Can‘t start server: Bind on TCP/IP port. Got error: 98: Address already in used
|
SQL 存储 运维
网易游戏如何基于阿里云瑶池数据库 SelectDB 内核 Apache Doris 构建全新湖仓一体架构
随着网易游戏品类及产品的快速发展,游戏数据分析场景面临着越来越多的挑战,为了保证系统性能和 SLA,要求引入新的组件来解决特定业务场景问题。为此,网易游戏引入 Apache Doris 构建了全新的湖仓一体架构。经过不断地扩张,目前已发展至十余集群、为内部上百个项目提供了稳定可靠的数据服务、日均查询量数百万次,整体查询性能得到 10-20 倍提升。
708 0
网易游戏如何基于阿里云瑶池数据库 SelectDB 内核 Apache Doris 构建全新湖仓一体架构
|
存储 大数据 关系型数据库
从 ClickHouse 到阿里云数据库 SelectDB 内核 Apache Doris:快成物流的数智化货运应用实践
目前已经部署在 2 套生产集群,存储数据总量达百亿规模,覆盖实时数仓、BI 多维分析、用户画像、货运轨迹信息系统等业务场景。
694 0
|
SQL Java Apache
阿里云数据库 SelectDB 版内核 Apache Doris 2.1.4 版本正式发布
亲爱的社区小伙伴们,Apache Doris 2.1.4 版本已于 2024 年 6 月 26 日正式发布。在 2.1.4 版本中,我们对数据湖分析场景进行了多项功能体验优化,重点修复了旧版本中异常内存占用的问题,同时提交了若干改进项以及问题修复,进一步提升了系统的性能、稳定性及易用性,欢迎大家下载使用。
411 0
|
SQL Java 数据库连接
【MyBatis】MyBatis操作数据库(二):动态SQL、#{}与${}的区别
【MyBatis】MyBatis操作数据库(二):动态SQL、#{}与${}的区别
403 0
|
存储 SQL 数据管理
基于阿里云数据库 SelectDB 版内核 Apache Doris 全新分区策略 Auto Partition 应用场景与功能详解
自动分区的出现进一步简化了复杂场景下的 DDL 和分区表的维护工作,许多用户已经使用该功能简化了工作流程,并且极大的便利了从其他数据库系统迁移到 Doris 的工作,自动分区已成为处理大规模数据和应对高并发场景的理想选择。
621 0

相关产品

  • 云数据库 RDS MySQL 版
  • 推荐镜像

    更多