关于数据库:Percona-8030中show-engine-innodb-status导致coredump排查及分析

GreatSQL 社区原创内容未经受权不得随便应用，转载请分割小编并注明起源。
GreatSQL 是 MySQL 的国产分支版本，应用上与 MySQL 统一。
作者：lh
文章起源：GreatSQL 社区原创

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。

通常有 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 到新部署的数据库实例并打印变量。

本地编译装置。本地操作系统为 ubuntu20.04，应用源码编译装置数据库实例后导入数据，未能复现 crash。
应用新打的包在另一台物理机部署实例并导入数据测试，未复现 crash。新部署的数据库实例在一台配置较高的物理机上，而呈现问题的机器是一台 8 core，16G ram 的虚拟机。
从新在产生 crash 的虚拟机上部署实例并导入数据测试，仍旧未复现 crash。
为排除参数差别的影响：经比对批改后虚拟机上两实例的配置除 basedir、datadir、log 文件地位、端口号等无奈改为统一的外，其余参数均相等。仍旧未能复现 crash。
在产生 crash 的数据库实例上，应用新包替换可执行程序，执行导入测试，可能复现 crash。

经上述尝试后，开始基于原始环境复现问题并剖析 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。

以上信息还不够精确定位问题。为进一步放大排查范畴，尝试将 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/IP
2023-02-12T09:08:43.666014+08:00          243 Query     SET AUTOCOMMIT = 0
2023-02-12T09:08:43.666791+08:00          243 Query     SHOW GLOBAL STATUS
2023-02-12T09:08:43.698693+08:00          243 Query     show variables
2023-02-12T09:08:43.739684+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>10
2023-02-12T09:08:43.740640+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>60
2023-02-12T09:08:43.741376+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>180
2023-02-12T09:08:43.742095+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>600
2023-02-12T09:08:43.742751+08:00          243 Query     show engine innodb status
2023-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) t
2023-02-12T09:08:43.747029+08:00          243 Query     SHOW SLAVE STATUS
2023-02-12T09:08:43.758254+08:00          243 Query     SHOW WARNINGS
2023-02-12T09:08:43.759621+08:00          243 Query     show binary logs
2023-02-12T09:08:43.760013+08:00          243 Query     select count(1) from information_schema.INNODB_TRX
2023-02-12T09:08:43.760676+08:00          243 Query     select count(1) from performance_schema.DATA_LOCK_WAITS
2023-02-12T09:08:43.761246+08:00          243 Query     select count(1) from performance_schema.DATA_LOCKS
2023-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 Quit
2023-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_stats
2023-02-12T09:08:43.795266+08:00          243 Quit

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

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

file repeat_sql_file.sh:

#!/bin/bash
for ((i=1;i<=1000000000;i++)) ;
do
  usleep 100
  greatsql -h***.**.***.*** -ugreatsql -p123456 -P1957 < $1
done

再将 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 没有触发。

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

首先是 Percona-8.0.31，未看到相干 bugfix 阐明，只看到一个从库 crash 的 bugfix。

（https://docs.percona.com/perc…）

但 release notes list 中看到多了一个 8.0.30-update：其中有一个 bugfix 波及到 ”show engine innodb status”

（https://docs.percona.com/perc…）

定位 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 behavior
494       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 语句的结尾。

排查问题时尽量躲避外界的影响。
如果生产零碎应用了 Percona-8.0.30，请慎用 ”show engine innodb status”。

目前 MySQL-8.0.32 版本的 release note 中已有相干的 patch：

（https://github.com/mysql/mysq…）

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

Truncating a message at a fixed length might leave
a partial UTF-8 character at the end of a truncated message.
This patch makes sure, that a truncation doesn't result
in 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

社区博客有奖征稿详情：https://greatsql.cn/thread-10…

微信：扫码增加 GreatSQL 社区助手 微信好友，发送验证信息 加群。

关于数据库:Percona-8030中show-engine-innodb-status导致coredump排查及分析

1. 异样解体

2. 捕风捉影

2.1 信息缺失

2.2 问题复现过程

2.3 问题剖析

3. 误打误撞

4. 水落石出

5. Release notes review

6. 源码剖析

7. 总结

GreatSQL 社区：

技术交换群：

Just My Socks（注册教程内含优惠码）

关于数据库:Percona-8030中show-engine-innodb-status导致coredump排查及分析

1. 异样解体

2. 捕风捉影

2.1 信息缺失

2.2 问题复现过程

2.3 问题剖析

3. 误打误撞

4. 水落石出

5. Release notes review

6. 源码剖析

7. 总结

GreatSQL 社区：

技术交换群：

Just My Socks（注册教程 内含优惠码）

Just My Socks（注册教程内含优惠码）