作者：李锡超
一个爱笑的江苏苏宁银行数据库工程师，主要负责数据库日常运维、自动化建设、DMP 平台运维。擅长 MySQL、Python、Oracle，爱好骑行、研究技术。
本文来源：原创投稿
* 爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
一、问题现象
研发同学反馈某测试应用系统存在异常，分析应用的错误日志、CPU、内存和磁盘 IO 等指标后，未发现相关异常。请求配合确认数据库运行情况。
关键配置
| 配置项 | 值 |
|---|---|
| 数据库版本 | MySQL 8.0 |
| 数据库架构 | 单机 |
| CPU 个数 | 8C |
| 内存 | 16G |
| 参数 innodb_thread_concurrency | 16 |
| 参数 innodb_concurrency_tickets | 5000 |
二、初步分析
此类问题，一般是由于 SQL 的效率低下，导致服务器的 CPU、IO 等资源耗尽，然后应用发起新的 SQL 请求，会由于无法获取系统资源，导致 SQL 请求被堵塞。
为此，检查 CPU、IO 等资源，发现 CPU 使用率约 5%，IO 几乎没有压力。登录数据库检查连接状态，发现很多连接的状态都在 executing。部分结果如下：
根据上述结果分析：
有 28 个会话状态为 executing，1 个会话状态为 updating。如果这些会话都真正在 executing，CPU 压力应该会很高，但实际情况仅占用很少的 CPU。
1 系统有报错或者某其它异常？
随后，对 MySQL 错误日志、磁盘使用率、磁盘 Inode 使用率、系统 messages 等信息进行确认，都未发现有相关异常！
2 SQL 语句存在特殊性？
对连接中的 SQL 进行了初步分析，发现除了表 t01 所在的 SQL 较为复杂，其它 SQL 都非常简单，且访问的都是数据表（不是视图）。表 t02、t03 的数据仅 1 行，应该瞬间执行完成！
由于是测试环境，且问题导致测试阻断，于是执行如下命令收集了诊断数据：
| 诊断项 | 执行 SQL |
|---|---|
| 连接状态 | show processlist; |
| 线程状态 | select * from performance_schema.threads where processlist_infoG |
| 事务信息 | select * from information_schema.innodb_trxG |
| InnoDB status | show engine innodb statusG |
| 堆栈信息 | pstack <mysqld-pid> |
随后对数据库执行了重启，重启完成后，应用系统恢复正常。
三、堆栈与源码分析
综合收集的信息，对连接状态、线程状态和堆栈信息进行关联分析，发现被堵塞的 29 个连接中，有 13 个都被卡在函数 nanosleep 中，比较奇怪。其堆栈关键信息如下：
#0 in nanosleep from /lib64/libpthread.so.0
#1 in srv_conc_enter_innodb
#2 in ha_innobase::index_read
#3 in ha_innobase::index_first
#4 in handler::ha_index_first
#5 in IndexScanIterator<false>::Read
#6 in Query_expression::ExecuteIteratorQuery
#7 in Query_expression::execute
#8 in Sql_cmd_dml::execute
#9 in mysql_execute_command
#10 in dispatch_sql_command
#11 in dispatch_command
#12 in do_command
#13 in handle_connection
其中 index_read ⼀般是⾸次访问 index，去找 WHERE ⾥的记录。更关键的，看到了 srv_conc_enter_innodb 函数，并由他调用了 nanosleep，执行了类似“睡眠” 的操作。为此，结合对应版本的源码进行分析。总结如下：
|-index_read(buf, nullptr, 0, HA_READ_AFTER_KEY) // 入口函数
|-ret = innobase_srv_conc_enter_innodb(m_prebuilt)
|-err = DB_SUCCESS
// STEP-1: 判断 innodb_thread_concurrency 是否为0, 不为0则进一步判断。否则直接返回（即不限制进入innodb的线程数）
|-if (srv_thread_concurrency):
// STEP-2: 判断事务拥有的 ticket(该值初始为:0) 个数是否大于0，如成立则 --ticket，然后返回 DB_SUCCESS 至上层函数；否则继续判断
|-if (trx->n_tickets_to_enter_innodb > 0): --trx->n_tickets_to_enter_innodb
|-else: err = srv_conc_enter_innodb(prebuilt)
|-return srv_conc_enter_innodb_with_atomics(trx)
|-for (;;):
|-ulint sleep_in_us
|-if (srv_thread_concurrency == 0): return DB_SUCCESS // 再次判断 innodb_thread_concurrency 是否为0, 满足则直接返回 DB_SUCCESS
/* STEP-3: 判断进入 innodb 的事务是否小于 innodb_thread_concurrency 。
如小于(进入innodb)：则调整innodb中活动线程个数、标记事务进入了innodb、设置事务的ticket个数，然后返回 DB_SUCCESS 至上层函数；
*/
|-if (srv_conc.n_active.load(std::memory_order_relaxed) < srv_thread_concurrency):
|-n_active = srv_conc.n_active.fetch_add(1, std::memory_order_acquire) + 1
|-if (n_active <= srv_thread_concurrency):
|-srv_enter_innodb_with_tickets(trx): // Note that a user thread is entering InnoDB.
|-trx->declared_to_be_inside_innodb = TRUE
|-trx->n_tickets_to_enter_innodb = srv_n_free_tickets_to_enter
|- // 调整 srv_thread_sleep_delay/
|-return DB_SUCCESS
|-srv_conc.n_active.fetch_sub(1, std::memory_order_release)
/* STEP-4: 否则(未进入innodb)，执行:
a. 设置事务的状态(information_schema.innodb_trx.trx_operation_state)为"sleeping before entering InnoDB"
b. 根据 innodb_thread_sleep_delay 设置sleep时间
c. 判断 sleep 时间是否超过上限 innodb_adaptive_max_sleep_delay, 如超过则设置睡眠时间为 innodb_adaptive_max_sleep_delay(1.5s)
d. 调用 nanosleep 进行指定时间的 sleep
e. 设置事务状态为 “”
f. 自增 sleep 此时
h. 自增睡眠时间
i. 进行下一次for 循环 ------------------ > for
*/
|-trx->op_info = "sleeping before entering InnoDB"
|-sleep_in_us = srv_thread_sleep_delay
|-if (srv_adaptive_max_sleep_delay > 0 && sleep_in_us > srv_adaptive_max_sleep_delay):
|-sleep_in_us = srv_adaptive_max_sleep_delay
|-srv_thread_sleep_delay = sleep_in_us
|-std::this_thread::sleep_for(std::chrono::microseconds(sleep_in_us))
|-nanosleep
|-trx->op_info = ""
|-++n_sleeps
|-if (srv_adaptive_max_sleep_delay > 0 && n_sleeps > 1):
|-++srv_thread_sleep_delay
|-if (trx_is_interrupted(trx)):
|-return DB_INTERRUPTED
|-return err
|-ret = row_search_mvcc(buf, mode, m_prebuilt, match_mode, 0) // 执行查询操作
|-innobase_srv_conc_exit_innodb(m_prebuilt);
// STEP-5: 判断是否进入了innodb，且ticket为0(ticket 被耗尽)
|-if (trx->declared_to_be_inside_innodb && trx->n_tickets_to_enter_innodb == 0):
|-srv_conc_force_exit_innodb(trx)
// STEP-6: 标记事务为未进入innodb状态。以避免不必要的函数调用
|-srv_conc_exit_innodb_with_atomics(trx)
|-trx->n_tickets_to_enter_innodb = 0
|-trx->declared_to_be_inside_innodb = FALSE
|-srv_conc.n_active.fetch_sub(1, std::memory_order_release)
为便于理解，将以上源码逻辑总结为 4 个场景：
场景 1：innodb_thread_concurrency == 0, 执行逻辑：
场景 2：innodb_thread_concurrency != 0、事务拥有 ticket, 执行逻辑：
场景 3：innodb_thread_concurrency != 0、事务没有 ticket、进入 innodb 的事务小于 innodb_thread_concurrency , 执行逻辑：
场景 4：innodb_thread_concurrency != 0、事务没有 ticket、进入 innodb 的事务大于 innodb_thread_concurrency , 执行逻辑：
根据堆栈信息，受影响的会话都被堵塞在 nanosleep 函数；同时，通过事务信息，看到对应的会话的 ticket 为 0、事务状态为 sleeping before entering InnoDB，与上述场景 4 基本相符。
小结
故障数据库配置 innodb_thread_concurrency=16，问题时刻，由于数据库中慢 SQL 持有并发资源，且并发较高（超过 innodb_thread_concurrency），导致其它事务需要进行 nanosleep 以等待 InnoDB 并发资源。
同时，结合源码不难看出，对于慢 SQL，其自身也需要频繁从 innodb 中进出，而当其拥有的 ticket（5000）用完之后，也需要重新进入排队及等待并发资源，导致执行 SQL 性能进一步降低，形成劣性循环。
四、问题解决
问题发生后，已通过重启的方式临时解决。但通过与研发同学的沟通，还存在如下问题：
1 如何根本解决问题？
综合以上分析过程，我们可以看到导致此次故障的根本原因就是问题时刻数据库存在慢 SQL，耗尽了 InnoDB 的并发资源，因此需要对问题 SQL 进行优化（由于篇幅有限，不在此讨论）。
此外，测试数据库设置了 innodb_thread_concurrency=16 是导致发生该现象的直接原因。对于该参数设置建议，简要总结如下（完整说明参考 MySQL 官方文档）：
-
如果数据库的活动并发用户线程数小于 64，则设置
innodb_thread_concurrency=0； -
如果压力一直很重或偶尔出现峰值，首先设置
innodb_thread_concurrency=128，然后将该值降低到 96、80、64，以此类推，直到找到提供最佳性能的线程数； -
Innodb_thread_concurrency值过高会导致性能下降，因为这会增加系统内部和资源的争用。
因此，建议将 innodb_thread_concurrency=0 从数据库层面解决。该参数为动态参数，发生问题后可立即修改，并会立即生效，以避免不必要的重启操作。同时，需要尽快对慢 SQL 进行优化，以从根本解决该问题。
2 如何影响到那些本身执行会很快的其它 SQL？
根据源码分析结果：由于耗尽的是 InnoDB 全局并发线程资源，类似于进入 InnoDB “连接” 被耗尽了一样。因此会影响所有的其它线程。
3 影响的会话到底会被堵塞多久？
对于线上系统，当 InnoDB 并发资源被耗尽后，新发起的 SQL 会进入 nanosleep，直至已进入 InnoDB 事务的 ticket 被耗尽后，才有可能进入 InnoDB（而且好像是最后新发起的 SQL 请求，由于 sleep 时间越短，越容易进入）。除非源头的慢 SQL 快速执行完成，但由于慢 SQL 在此状态下，当 ticket 用完后也需要参与排队，因此其执行时间会进一步加长，导致源头 SQL 无法快速完成。因此对于大多数 SQL 请求，都需要参与堵塞，且堵塞的时间会越来越长。问题发生后，建议尽快处理。
4 再次发生后，如何快速确认是该问题？
-
对于该数据库版本，检查是否大量的数据库会话处于
executing, 且部分会话执行的 SQL 可能非常简单； -
检查数据库事务的状态，判断是否有处于
sleeping before entering InnoDB的事务，且基本满足：
sleeping before entering InnoDB的事务个数 = 总的事务个数 -
innodb_thread_concurrency -
检查
innodb输出，示例输出结果如下：
--------------
ROW OPERATIONS
--------------
16 queries inside InnoDB, 22 queries in queue
....
----------------------------
-
根据前面提供的信息采集步骤，保存相关信息，并结合堆栈和源码进行确认。
本文关键字：#MySQL# #源码#
文章推荐：
故障分析 | MySQL 升级到 8.0 变慢问题分析
技术分享 | 一招解决 MySQL 中 DDL 被阻塞的问题
故障分析 | 一条本该记录到慢日志的 SQL 是如何被漏掉的
技术分享 | OceanBase写入限速源码解读
关于 SQLE
爱可生开源社区的 SQLE 是一款面向数据库使用者和管理者，支持多场景审核，支持标准化上线流程，原生支持 MySQL 审核且数据库类型可扩展的 SQL 审核工具。
SQLE 获取
| 类型 | 地址 |
|---|---|
| 版本库 | https://github.com/actiontech/sqle |
| 文档 | https://actiontech.github.io/sqle-docs-cn/ |
| 发布信息 | https://github.com/actiontech/sqle/releases |
| 数据审核插件开发文档 | https://actiontech.github.io/sqle-docs-cn/3.modules/3.7_auditplugin/auditplugin_development.html |
提交有效 pr，高质量 issue，将获赠面值 200-500 元（具体面额依据质量而定）京东卡以及爱可生开源社区精美周边！
更多关于 SQLE 的信息和交流，请加入官方QQ交流群：637150065
本文分享自微信公众号 - 爱可生开源社区（ActiontechOSS）。
如有侵权，请联系 support@oschina.cn 删除。
本文参与“OSC源创计划”，欢迎正在阅读的你也加入，一起分享。
