写点什么

Percona 8.0.30 中 show engine innodb status 导致 coredump 排查及分析

作者:GreatSQL
  • 2023-02-20
    福建
  • 本文字数:7050 字

    阅读完需:约 23 分钟

  • GreatSQL 社区原创内容未经授权不得随意使用,转载请联系小编并注明来源。

  • GreatSQL 是 MySQL 的国产分支版本,使用上与 MySQL 一致。

  • 作者:lh

  • 文章来源:GreatSQL 社区原创



1. 异常崩溃

GreatSQL 合并 Percona-Server 8.0.30 的 Beta 版测试中,QA 报了一个 crash 的 bug:


###########  bug list ##########benchmarksql加载1000仓数据时,数据库实例发生coredump。core堆栈信息如下:#0  0x00007f51315a39d1 in pthread_kill () from /lib64/libpthread.so.0#1  0x00000000013258cd in handle_fatal_signal () at /src/sql/signal_handler.cc:228#2  <signal handler called>#3  0x0000000001339244 in mem_root_deque<Item*>::push_back () at /src/include/mem_root_deque.h:182#4  0x0000000001364a16 in push_back () at /src/sql/parse_tree_helpers.h:126#5  MYSQLparse(THD*, Parse_tree_root**) () at /src/sql/sql_yacc.yy:13506#6  0x000000000103a595 in THD::sql_parser () at /src/sql/sql_class.cc:3287#7  0x00000000010d0e37 in parse_sql () at /src/sql/sql_parse.cc:7353#8  0x00000000010d61bd in dispatch_sql_command () at /src/sql/sql_parse.cc:5399#9  0x00000000010d78d0 in dispatch_command () at /src/sql/sql_parse.cc:2052#10 0x00000000010d9a12 in do_command () at /src/sql/sql_parse.cc:1424#11 0x00000000013159f8 in handle_connection () at /src/sql/conn_handler/connection_handler_per_thread.cc:308#12 0x00000000027db225 in pfs_spawn_thread () at /src/storage/perfschema/pfs.cc:2943#13 0x00007f513159edd5 in start_thread () from /lib64/libpthread.so.0#14 0x00007f512ffa9ead in clone () from /lib64/libc.so.6
core文件在测试服务器xxx.xxx.xxx.xxx的xxx目录,能够稳定复现crash。
复制代码

2. 捕风捉影

2.1 信息缺失

通常有 core 文件的话定位 bug 不算太难。


第一时间使用 GDB 打开 core 文件,切到相应函数调用栈尝试打印关键变量的信息:


但无论尝试任何变量,使用 gdb 打印时均会报:“gdb: No symbol "xxx" in current context”。


最初怀疑是 GDB 版本过低,安装 devtoolset-11 并使用高版本 GDB 后问题依旧。检查出包时的编译记录,发现 cmake 后,"CMAKE_CXX_FLAGS_RELWITHDEBINFO"后的编译选项多了"-g1"。


CMAKE_CXX_FLAGS_RELWITHDEBINFO: -DNDEBUG -D_FORTIFY_SOURCE=2 -ffunction-sections -fdata-sections -O2 -g -DNDEBUG -g1
复制代码


原因是新版本多了编译选项“MINIMAL_RELWITHDEBINFO”,该选项在打包时自动开启。


向打包脚本添加"-DMINIMAL_RELWITHDEBINFO=OFF"后重新打包。经验证,此时 GDB 能够 attach 到新部署的数据库实例并打印变量。

2.2 问题复现过程

  • 本地编译安装。本地操作系统为 ubuntu20.04,使用源码编译安装数据库实例后导入数据,未能复现 crash。

  • 使用新打的包在另一台物理机部署实例并导入数据测试,未复现 crash。新部署的数据库实例在一台配置较高的物理机上,而出现问题的机器是一台 8 core,16G ram 的虚拟机。

  • 重新在发生 crash 的虚拟机上部署实例并导入数据测试,依旧未复现 crash。

  • 为排除参数差异的影响:经比对修改后虚拟机上两实例的配置除 basedir、datadir、log 文件位置、端口号等无法改为一致的外,其余参数均相等。依旧未能复现 crash。

  • 在发生 crash 的数据库实例上,使用新包替换可执行程序,执行导入测试,能够复现 crash。

2.3 问题分析

经上述尝试后,开始基于原始环境复现问题并分析 core 文件中的异常内存数据。


  • 经多次复现,每次 crash 的位置并不完全一致。

  • 为缩小问题范围,将 benchmarksql 导入数据的 woker 改为 1,验证是否和多 session 并发写入有关。并发度改为 1 后,经 7-10 分钟,crash 再次发生。说明问题和多线程并发导入无关。


由于 crash 时的位置不同,选择较早 crash 时的 core 文件进行分析,堆栈如下(发生在 parser 阶段):


#0  0x00007f51315a39d1 in pthread_kill () from /lib64/libpthread.so.0#1  0x00000000013258cd in handle_fatal_signal () at /src/sql/signal_handler.cc:228#2  <signal handler called>#3  0x0000000001339244 in mem_root_deque<Item*>::push_back () at /src/include/mem_root_deque.h:182#4  0x0000000001364a16 in push_back () at /src/sql/parse_tree_helpers.h:126#5  MYSQLparse(THD*, Parse_tree_root**) () at /src/sql/sql_yacc.yy:13506#6  0x000000000103a595 in THD::sql_parser () at /src/sql/sql_class.cc:3287#7  0x00000000010d0e37 in parse_sql () at /src/sql/sql_parse.cc:7353#8  0x00000000010d61bd in dispatch_sql_command () at /src/sql/sql_parse.cc:5399#9  0x00000000010d78d0 in dispatch_command () at /src/sql/sql_parse.cc:2052#10 0x00000000010d9a12 in do_command () at /src/sql/sql_parse.cc:1424#11 0x00000000013159f8 in handle_connection () at /src/sql/conn_handler/connection_handler_per_thread.cc:308#12 0x00000000027db225 in pfs_spawn_thread () at /src/storage/perfschema/pfs.cc:2943#13 0x00007f513159edd5 in start_thread () from /lib64/libpthread.so.0#14 0x00007f512ffa9ead in clone () from /lib64/libc.so.6
复制代码


切到"#3",打印mem_root_deque<Item*>对象的内容:


  • 发现其头部内容存在非法地址。

  • 按字符串格式输出内存内容时,发现其尾部内容被填充了一小段"INSERT INTO bmsql_xxxx ..."


切到"#7",“p parser_state->m_lip->m_buf_length”输出原始 sql 语句的长度,将 gdb 定向到 log 文件,调整 print element 足够大后执行“p parser_state->m_lip->m_buf”,导出原始 sql 语句到 log 文件。 此时可发现异常内存的内容为当前语句的头部。


由于“mem_root_deque”使用的内存是从当前 THD->mem_root 分配的,基本可判断是当前 session 的"thd->mem_root"分配异常。即已分配出去的内存被重新分配给其它对象,最终造成 coredump。

3. 误打误撞

以上信息还不够准确定位问题。为进一步缩小排查范围,尝试将 benchmarksql 在 load 数据期间发送的语句记录到 general_log,将 general_log 中的语句导出到文本,使用文本中固定的语句尝试触发 crash 并验证 crash 时间点是否一致。


重启数据库实例、清理并重建 database、开启 general_log、启动 benchmarksql 导入。一段时间后数据库 crash,一切按预期进行。


打开 general_log,找 benchmarksql 对应的 session 时发现 general_log 多了部分内容,每隔几秒执行一次。


2023-02-12T09:08:43.665421+08:00          243 Connect   greatsql@***.**.***.*** on  using TCP/IP2023-02-12T09:08:43.666014+08:00          243 Query     SET AUTOCOMMIT = 02023-02-12T09:08:43.666791+08:00          243 Query     SHOW GLOBAL STATUS2023-02-12T09:08:43.698693+08:00          243 Query     show variables2023-02-12T09:08:43.739684+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>102023-02-12T09:08:43.740640+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>602023-02-12T09:08:43.741376+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>1802023-02-12T09:08:43.742095+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>6002023-02-12T09:08:43.742751+08:00          243 Query     show engine innodb status2023-02-12T09:08:43.744324+08:00          243 Query     select round(innodb_buffer_pool_read_requests / (innodb_buffer_pool_read_requests + innodb_buffer_pool_reads) * 100,2) FROM   (SELECT max(CASE VARIABLE_NAME WHEN 'innodb_buffer_pool_read_requests' THEN VARIABLE_VALUE ELSE 0 END) AS innodb_buffer_pool_read_requests,           max(CASE VARIABLE_NAME WHEN 'innodb_buffer_pool_reads' THEN VARIABLE_VALUE ELSE 0 END) AS innodb_buffer_pool_reads    FROM performance_schema.global_status) t2023-02-12T09:08:43.747029+08:00          243 Query     SHOW SLAVE STATUS2023-02-12T09:08:43.758254+08:00          243 Query     SHOW WARNINGS2023-02-12T09:08:43.759621+08:00          243 Query     show binary logs2023-02-12T09:08:43.760013+08:00          243 Query     select count(1) from information_schema.INNODB_TRX2023-02-12T09:08:43.760676+08:00          243 Query     select count(1) from performance_schema.DATA_LOCK_WAITS2023-02-12T09:08:43.761246+08:00          243 Query     select count(1) from performance_schema.DATA_LOCKS2023-02-12T09:08:43.761829+08:00          243 Query     select count(1) from information_schema.tables where engine='MEMORY'2023-02-12T09:08:43.765503+08:00          243 Query     select count(1) from information_schema.tables where engine='InnoDB'2023-02-12T09:08:43.770064+08:00          243 Query     select count(1) from information_schema.tables where engine='MyISAM'2023-02-12T09:08:43.770126+08:00          244 Quit2023-02-12T09:08:43.772994+08:00          243 Query     select count(1) from information_schema.tables where engine='CSV'2023-02-12T09:08:43.775934+08:00          243 Query     select count(1) from information_schema.tables where engine='PERFORMANCE_SCHEMA'2023-02-12T09:08:43.783303+08:00          243 Query     show variables like '%semi%'2023-02-12T09:08:43.787773+08:00          243 Query     show status like '%semi%'2023-02-12T09:08:43.790204+08:00          243 Query     select rgms.COUNT_TRANSACTIONS_IN_QUEUE  from performance_schema.replication_group_members rgm ,performance_schema.replication_group_member_stats rgms where rgm.CHANNEL_NAME=rgms.CHANNEL_NAME and rgm.MEMBER_ID=rgms.MEMBER_ID and rgm.MEMBER_HOST='***.**.***.***' and rgm.MEMBER_PORT='1957'2023-02-12T09:08:43.790947+08:00          243 Query     select MEMBER_STATE,MEMBER_ROLE from performance_schema.replication_group_members where MEMBER_HOST='***.**.***.***' and MEMBER_PORT='1957'2023-02-12T09:08:43.794132+08:00          243 Query     select max( if(LAST_APPLIED_TRANSACTION <>'', timestampdiff(MICROSECOND,LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP,LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP) div 1000,0)) 'max_worker_latency' from performance_schema.replication_applier_status_by_worker where SERVICE_STATE='ON' and CHANNEL_NAME='group_replication_applier'2023-02-12T09:08:43.794800+08:00          243 Query     select max(count_transactions_remote_in_applier_queue) from performance_schema.replication_group_member_stats2023-02-12T09:08:43.795266+08:00          243 Quit
复制代码


看到多的这部分内容,心里一震,原来 QA 部署的数据库实例会被平台纳管。 莫非是这些语句导致 benchmarksql 导入数据时 crash?

4. 真相大白

写了个简单脚本,循环向数据库实例发送指定文件中的 sql 语句


file repeat_sql_file.sh:


#!/bin/bashfor ((i=1;i<=1000000000;i++)) ;do  usleep 100  greatsql -h***.**.***.*** -ugreatsql -p123456 -P1957 < $1done
复制代码


再将 general log 中的语句取出到文件 monit.sql,执行命令"file repeat_sql_file.sh monit.sql"。然后启动 benchmarksql 导入数据。


仅仅过了 15 秒,数据库实例 crash。


接下来要找到肇事 sql。采用二分查找法先注释一半内容逐步验证,重复几次后将肇事语句锁定到了 DBA 最常用的一条语句:


show engine innodb status;
复制代码


下载 Percona-8.0.30 官方源码并按上述步骤编译安装部署后,重现了 crash!


继续验证 MySQL 官方的 8.0.30,发现该 crash 没有触发。

5. Release notes review

既然已明确是 Percona-Server 的 bug,那就先到 MySQL 和 Percona 官网看新版本 release note 有没有和"show engine innodb status"相关的 bugfix。


首先是 Percona-8.0.31,未看到相关 bugfix 说明,只看到一个从库 crash 的 bugfix。


https://docs.percona.com/percona-server/8.0/release-notes/8.0.31-23.html#bug-fixes



但 release notes list 中看到多了一个 8.0.30-update:其中有一个 bugfix 涉及到"show engine innodb status"


https://docs.percona.com/percona-server/8.0/release-notes/8.0.30-22.upd.html#bug-fixes


6. 源码分析

定位 Percona 8.0.30 PS-8351 相关 patch,可看到 Percona 修改了一些代码,而这部分代码在 MySQL 8.0.30 上是未被修改的:


430 char *thd_security_context(MYSQL_THD thd, char *buffer, size_t length,431                            size_t max_query_len) {

487 LEX_STRING truncated_query = {nullptr, 0}; // 这里是Percona引入的488 if (len < thd->query().length &&489 !thd->convert_string(&truncated_query, thd->charset(), thd->query().str,490 len, thd->charset())) {491 str.append(truncated_query.str, truncated_query.length);492 } else {493 // In case of error or not trimming, fall back to the original behavior494 str.append(thd->query().str, len);
........
复制代码


其调用逻辑为:


| > innodb_show_status| | > srv_printf_innodb_monitor| | | > srv_printf_locks_and_transactions| | | | > lock_print_info_all_transactions| | | | | > lock_trx_print_wait_and_mvcc_state| | | | | | > trx_print_latched| | | | | | | > trx_print_low| | | | | | | | > innobase_mysql_print_thd| | | | | | | | | > thd_security_context  // MySQL原始代码不会调用convert_string| | | | | | | | | | > THD::convert_string
复制代码


而在 trx_print_low 中:很明显作为参数传递下去的"trx->mysql_thd"归属于实例中其它活跃的 session,而不是归属于当前执行"show engine innodb status"的 session


void trx_print_low() {  .....  if (trx_state != TRX_STATE_NOT_STARTED && trx->mysql_thd != nullptr) {    innobase_mysql_print_thd(f, trx->mysql_thd,                             static_cast<uint>(max_query_len));  }}
复制代码


继续看 convert_string:执行"show engine innodb status"的 session 使用了其它 session 的 mem_root 开辟了内存空间。


bool THD::convert_string(){  size_t new_length = to_cs->mbmaxlen * from_length;  if (!(to->str = (char *)alloc(new_length + 1))) {    to->length = 0;  // Safety fix    return true;     // EOM  }  ......}
// alloc实际调用的是THD的父类成员函数Query_arena::alloc(),代码为class Query_arena { .... void *alloc(size_t size) { return mem_root->Alloc(size); } ....};
复制代码


因此,一旦“thd->convert_string()”使用 thd->memroot 申请内存,就会出现两个线程并发操作 thd->memroot。由于对同一 mem_root 的操作不是线程安全的,两个线程分配的内存空间可能存在重叠。


随着"show engine innodb status"线程的运行,重叠内存区域的内容可能会被填上部分原始 sql 语句。回顾上文中打印mem_root_deque<Item*>对象的内存内容,其尾部也确实包含了原始 sql 语句的开头。

7. 总结

  • 排查问题时尽量规避外界的影响。

  • 如果生产系统使用了 Percona-8.0.30,请慎用"show engine innodb status"。


目前 MySQL-8.0.32 版本的 release note 中已有相关的 patch:



https://github.com/mysql/mysql-server/commit/14cc6bab13ba24c75654e87df4b3c66e55277fcb


从 commit 信息看,该 commit 来自 Percona。


Truncating a message at a fixed length might leavea partial UTF-8 character at the end of a truncated message.This patch makes sure, that a truncation doesn't resultin such a "garbled" character.
Patch is based on contribution from Iwo Panowicz <iwo.panowicz@percona.com>Thanks to Iwo and Percona for this patch.
Change-Id: I5f8e6dce28608f432fbb4b77220e1a21049f510f
复制代码


解决了 show engine innodb status 乱码问题的同时,不再使用“convert_string()”。





Enjoy GreatSQL :)

关于 GreatSQL

GreatSQL 是由万里数据库维护的 MySQL 分支,专注于提升 MGR 可靠性及性能,支持 InnoDB 并行查询特性,是适用于金融级应用的 MySQL 分支版本。


相关链接: GreatSQL社区 Gitee GitHub Bilibili

GreatSQL 社区:


社区有奖建议反馈: https://greatsql.cn/thread-54-1-1.html


社区博客有奖征稿详情: https://greatsql.cn/thread-100-1-1.html


社区 2022 年度勋章获奖名单: https://greatsql.cn/thread-184-1-1.html


(对文章有疑问或者有独到见解都可以去社区官网提出或分享哦~)

技术交流群:

微信 &QQ 群:


QQ 群:533341697


微信群:添加 GreatSQL 社区助手(微信号:wanlidbc )好友,待社区助手拉您进群。

发布于: 刚刚阅读数: 4
用户头像

GreatSQL

关注

GreatSQL社区 2023-01-31 加入

GreatSQL是由万里数据库维护的MySQL分支,专注于提升MGR可靠性及性能,支持InnoDB并行查询特性,是适用于金融级应用的MySQL分支版本。 社区:https://greatsql.cn/ Gitee: https://gitee.com/GreatSQL/GreatSQL

评论

发布
暂无评论
Percona 8.0.30中show engine innodb status导致coredump排查及分析_MySQL_GreatSQL_InfoQ写作社区