在某些时候执行 show engine innodb status 会触发此 bug,目前只在 5.6 版本下发生,在 5.7 版本下还未出现过

# 收集信息

一般来讲,不太可能是第一个吃螃蟹的,果然这个 bug 已经有人报过

  • https://bugs.mysql.com/bug.php?id=90988 被认为是旧版本,没人处理
  • https://bugs.mysql.com/bug.php?id=38883 旧问题复发,没人处理,旧问题是 thd->proc_info 和 thd->query 在多线程环境中变化导致字符串处理时溢出

通过 Yandex 搜索可以得到新的信息

https://forum.pjrc.com/threads/35688-Something-wrong-with-Adding-a-String-to-itself!

似乎递归添加信息可能引发 crack,但是代码逻辑不太可能有重合地方啊

https://forums.mysql.com/read.php?22,293875,295012

太久远了,也没什么结果

https://mariadb.atlassian.net/browse/MDEV-6348?attachmentOrder=desc

说是内存或磁盘上的数据损坏,可能使用压缩表会导致问题

https://jira.mariadb.org/browse/MDEV-16514

描述相似,不能复现

https://jira.percona.com/browse/PS-4491

一个 rocksdb 相关的 bug

https://bugs.mysql.com/bug.php?id=90911

这个最近的相似的问题,slave 下触发,多线程可能有问题,同时里面指出了可能是指针有问题

# 分析 1

还是得自力更生

看下堆栈信息,#38883 的堆栈信息如下

0x8e6145 my_print_stacktrace + 53
0x652c4b handle_fatal_signal + 1051
0x7fa329f73710 _end + 683665960
0x7fa328c75742 _end + 663751258
0x71f04e _ZN6String6appendEPKcj + 222
0x6a193c thd_security_context + 380

0x98cd75 _Z24innobase_mysql_print_thdP8_IO_FILEP3THDj + 37
0x9bb6a7 _Z32lock_print_info_all_transactionsP8_IO_FILE + 887
0xa3b204 _Z25srv_printf_innodb_monitorP8_IO_FILEmPmS1_ + 612
0x999316 _ZL20innobase_show_statusP10handlertonP3THDPFbS2_PKcjS4_jS4_jE12ha_stat_type + 454

0x59518e _Z14ha_show_statusP3THDP10handlerton12ha_stat_type + 974
0x6daa3d _Z21mysql_execute_commandP3THD + 10925
0x6dcf47 _Z11mysql_parseP3THDPcjP12Parser_state + 1223
0x6de8fc _Z16dispatch_command19enum_server_commandP3THDPcj + 6300
0x6a655d _Z24do_handle_one_connectionP3THD + 269
0x6a6692 handle_one_connection + 66
0x96af77 pfs_spawn_thread + 295
0x7fa329f6b9d1 _end + 683633897
0x7fa328cd48fd _end + 664140821
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

# backtrace

堆栈信息是通过 backtrace 函数输出的

对于 _Z24innobase_mysql_print_thdP8_IO_FILEP3THDj + 37

  • _Z 是函数名开始标识符
  • 后面的 24 标识函数名长度,函数名也就是 innobase_mysql_print_thd
  • 接下来的 P8_IO_FILE 和 P3THD 分别表示 _IO_FILE 类型和 THD 类型的指针作为参数
  • j 应该是 uint
  • + 37 是偏移地址

使用 addr2line 工具可以定位到代码行

$ addr2line -fie <path-to-binary-file> 0x6a700e
_ZN9SQL_CRYPT4initEPm
/tmp/884/mysql-5.6.23/sql/sql_crypt.cc:30
1
2
3

参考文档

# 源码阅读

下载 mysql-5.6.44 源码,定位下 thd_security_context 中的问题

$ addr2line -fie bin/mysqld 0x6a700e
inline_mysql_mutex_unlock
/export/servers/download/mysql-5.6.44/include/mysql/psi/mysql_thread.h:753
thd_security_context
/export/servers/download/mysql-5.6.44/sql/sql_class.cc:812
1
2
3
4
5
static inline int inline_mysql_mutex_unlock(
  mysql_mutex_t *that
#ifdef SAFE_MUTEX
  , const char *src_file, uint src_line
#endif
  )
{
  int result;

#ifdef HAVE_PSI_MUTEX_INTERFACE
  if (that->m_psi != NULL)
    PSI_MUTEX_CALL(unlock_mutex)(that->m_psi);
#endif

#ifdef SAFE_MUTEX
  result= safe_mutex_unlock(&that->m_mutex, src_file, src_line);
#elif defined(MY_PTHREAD_FASTMUTEX)
  result= pthread_mutex_unlock(&that->m_mutex.mutex);
#else
  result= pthread_mutex_unlock(&that->m_mutex);
#endif

  return result;
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

问题出在 753 行,也就是

  if (that->m_psi != NULL)
1

宏展开,inline 展开是

  if (&thd->LOCK_thd_data->m_psi != NULL)
1

再看下 append 那行

$ addr2line -fie bin/mysqld 0x725e7e
_ZN6String6appendEPKcj
/export/servers/download/mysql-5.6.44/sql/sql_string.cc:480
1
2
3

出错的地方竟然是,为什么我觉得应该是 memcpy?

str_length+=arg_length;
1

大致可以猜测和 38883 的问题类似

可能出现问题的有:

  • sctx->get_host() 变化
  • sctx->get_ip() 变化
  • sctx->user 变化
  • 或者 THD 被强制销毁了,感觉这个太常见了,不太可能遗留到现在

沟通后发现遗漏了一个很重要的信息,只有从库会出这问题,很可能是内部 slave 线程的变化导致的!

# slave

Master-Slave 是异步复制

sql/rpl_slave.cc 中实现

都没有直接操作 thd.main_security_ctx 或 thd.security_ctx

可疑操作:

  • init_slave_thread 中的 thd->security_ctx->skip_grants(); 会把 ip 置空
  • try_to_reconnect
  • reset_slave
  • change_master
  • 可能是 thread 被销毁了?

可以看到 slave 线程初始化时 ip 和 host 都是置空的,不存在问题,只能是 user 变化导致的

找到一个可能相关的 bug: https://bugs.mysql.com/bug.php?id=82980

说是已经在 8.0.3, 5.7.20, and 5.6.38 版本修复了