- 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/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？
4. 水落石出
写了个简略脚本，循环向数据库实例发送指定文件中的 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 没有触发。
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/perc…）
但 release notes list 中看到多了一个 8.0.30-update：其中有一个 bugfix 波及到 ”show engine innodb status”
（https://docs.percona.com/perc…）
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 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 语句的结尾。
7. 总结
- 排查问题时尽量躲避外界的影响。
- 如果生产零碎应用了 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
GreatSQL 社区：
社区博客有奖征稿详情：https://greatsql.cn/thread-10…
技术交换群：
微信：扫码增加
GreatSQL 社区助手微信好友，发送验证信息加群。