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

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/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 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/mysql-server/commit/14cc6bab13ba24c75654e87df4b3c66e55277fcb）

从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 <[e-mail]>
Thanks to Iwo and Percona for this patch.

Change-Id: I5f8e6dce28608f432fbb4b77220e1a21049f510f

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

Enjoy GreatSQL :)

---

《深入浅出MGR》视频课程

戳此小程序即可直达B站

https://www.bilibili.com/medialist/play/1363850082?business=space_collection&business_id=343928&desc=0

---

文章推荐：

想看更多技术好文，点个“在看”吧！