MySQL线程池卡顿重现

发表于 | 分类于 | 次

MySQL线程池卡顿重现

by @wych42

起因

为了激励大家多动手少空想，我在推特发起了白嫖我的知识星球活动：

白嫖我星球的机会来了，总有人说贵、没有优惠券，这次直接来一个完全100%免费的机会，要求： 在MySQL的基础上重现某个线程池卡的现象，给出可复制的重现过程。就是因为某个线程池满了导致落到这个池里的查询一定都慢，否则都快。 不愿意出钱就动手吧

参考现象：https://plantegg.github.io/2020/11/17/MySQL%E7%BA%BF%E7%A8%8B%E6%B1%A0%E5%AF%BC%E8%87%B4%E7%9A%84%E5%BB%B6%E6%97%B6%E5%8D%A1%E9%A1%BF%E6%8E%92%E6%9F%A5/

感谢推友王鱼翅同学，以下是他的教科书级的细致重现，你复制粘贴就能和他一样重现了

这个案例的重要性

这个现象对应我们年度四大案例之一，如下图左下角

image-20230517082106489

重现后请思考：

  1. MySQL为什么要将多个线程分成小池子，小池子肯定容易局部资源不足
  2. Nginx 一个连接固定在一个worker上，那么同样多个Worker也会有不均衡(有的worker很闲，有的很卡)
  3. 动手实验一下将多个小池子改成一个大线程池会怎么样
  4. Java ConcurrentHashMap为什么能够高性能

由 @wych42 重现

原因分析

根据 USE 分析套路。看到服务端执行快，但是整体RT慢的现象，大概率是中间哪个位置有排队。根据文章里的描述，原因是在thread pool group中出现了排队。

排队的主要原因是服务端拒绝创建新的thread（worker），导致新进来的SQL需要等待前面的执行完成。那么就需要重点分析thread(worker)的创建过程和约束条件。根据文章和文档的说明，重点在thread_pool_size, thread_pool_oversubscribe, thread_pool_max_threads, thread_pool_stall_limit这几个参数上。

跟据文档分析和实际执行结果，这几个参数在MySQL不同的发型版中的行为逻辑是不尽相同的。核心差异在对创建新worker的限制条件上，后面复现也会根据两个发型版的特点分别执行。

mariadb

文档

  • 通常情况下，新worker由listener worker创建
  • 当timer worker检测到thread group 有stall时，可能会选择创建一个新的worker
  • worker的数量上限由thread_pool_max_threads限制
  • thread_pool_oversubscribe约束的是被额外创建出来的worker，在执行完任务后，最多能保留active状态的数量

    To clarify, the thread_pool_oversubscribe system variable does not play any part in the creation of new worker threads. The thread_pool_oversubscribe system variable is only used to determine how many worker threads should remain active in a thread group, once a thread group is already oversubscribed due to stalls.

percona

文档

percona的行为更符合原文章里的说明：

  • 如果线程执行超过时间 thread_pool_stall_limit 的值，会被任务stalled，会创建一个新的线程执行排队的任务
  • thread_pool_oversubscribe 约束了每个thread group的线程数上限。

尝试复现

思路

并发向DB发起请求，观察客户端耗时，这些请求应当符合这些条件：

  • 可控的并发数量：以对比数据库服务端不同参数值的情况
  • 有稳定的、相同的服务端执行耗时：以对比客户端在不同场景下的耗时
  • 对服务端的硬件压力较小：避免因为并发不同时，因IO、CPU资源占用，影响服务端执行耗时

综合考虑使用 select sleep(2); 作为测试SQL。并发控制使用下面的golang代码实现。

再控制数据库服务端参数，运行同一个并发程序进行对比，mariadb和percona分析执行运行过程：

复现执行

mariadb

由上面分析可以，mariadb 中造成排队的约束是thread_pool_max_threads。

执行方案

  • DB配置

    1
    2
    3
    4
    | thread_pool_max_threads                 | 6               |
    | thread_pool_oversubscribe               | 1               |
    | thread_pool_size                        | 1               |
    | thread_pool_stall_limit                 | 500             |

  • 执行SQL select sleep(2)

  • 执行并发：8

预期结果： 6个SQL执行的客户端观察耗时为2s；2个SQL为4s

若调整 thread_pool_max_threads=8，则8个SQL的执行客户端观察耗时都为2s

执行结果

  1. thread_pool_max_threads=6;concurrency=8

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    go run ./main.go
    2023/05/16 13:34:51 starting taskId:task_3
    2023/05/16 13:34:51 starting taskId:task_1
    2023/05/16 13:34:51 starting taskId:task_6
    2023/05/16 13:34:51 starting taskId:task_4
    2023/05/16 13:34:51 starting taskId:task_0
    2023/05/16 13:34:51 starting taskId:task_7
    2023/05/16 13:34:51 starting taskId:task_2
    2023/05/16 13:34:51 starting taskId:task_5
    2023/05/16 13:34:53 taskId:task_0 exec cost : 2.021305666s
    2023/05/16 13:34:53 taskId:task_6 exec cost : 2.021421041s
    2023/05/16 13:34:53 taskId:task_3 exec cost : 2.021258917s
    2023/05/16 13:34:53 taskId:task_2 exec cost : 2.021275458s
    2023/05/16 13:34:53 taskId:task_4 exec cost : 2.021254083s
    2023/05/16 13:34:53 taskId:task_7 exec cost : 2.02146725s
    2023/05/16 13:34:55 taskId:task_5 exec cost : 4.021478584s
    2023/05/16 13:34:55 taskId:task_1 exec cost : 4.02192s

  2. thread_pool_max_threads=8;concurrency=8

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    go run ./main.go
    2023/05/16 13:36:17 starting taskId:task_7
    2023/05/16 13:36:17 starting taskId:task_3
    2023/05/16 13:36:17 starting taskId:task_1
    2023/05/16 13:36:17 starting taskId:task_5
    2023/05/16 13:36:17 starting taskId:task_0
    2023/05/16 13:36:17 starting taskId:task_6
    2023/05/16 13:36:17 starting taskId:task_4
    2023/05/16 13:36:17 starting taskId:task_2
    2023/05/16 13:36:19 taskId:task_6 exec cost : 2.045480167s
    2023/05/16 13:36:19 taskId:task_2 exec cost : 2.045405667s
    2023/05/16 13:36:19 taskId:task_7 exec cost : 2.045507334s
    2023/05/16 13:36:19 taskId:task_1 exec cost : 2.04553075s
    2023/05/16 13:36:19 taskId:task_3 exec cost : 2.04554975s
    2023/05/16 13:36:19 taskId:task_0 exec cost : 2.045697375s
    2023/05/16 13:36:19 taskId:task_4 exec cost : 2.046417375s
    2023/05/16 13:36:19 taskId:task_5 exec cost : 2.046453792s

均符合预期。

percona

由上面分析可以，percona中造成排队的约束是thread_pool_oversubscribe。

执行方案

  • DB配置: thread_pool_max_threads设置一个较大的值，以排除影响。

    1
    2
    3
    4
    | thread_pool_max_threads                 | 1000               |
    | thread_pool_oversubscribe               | 1               |
    | thread_pool_size                        | 1               |
    | thread_pool_stall_limit                 | 500             |

  • 执行SQL select sleep(2)

  • 执行并发：8

预期结果： 客户端观察到的耗时分四个批次输出，每个批次2个SQL，耗时分别为2s,4s,6s,8s.

若调整 thread_pool_oversubscribe=2，则三个批次输出，分别为3条SQL耗时均为2s，3条SQL耗时均为4s，2条SQL耗时均为6s

执行结果

  1. thread_pool_oversubscribe=1,concurrency=8

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    go run ./main.go
    2023/05/16 13:39:35 starting taskId:task_2
    2023/05/16 13:39:35 starting taskId:task_4
    2023/05/16 13:39:35 starting taskId:task_3
    2023/05/16 13:39:35 starting taskId:task_5
    2023/05/16 13:39:35 starting taskId:task_6
    2023/05/16 13:39:35 starting taskId:task_0
    2023/05/16 13:39:35 starting taskId:task_1
    2023/05/16 13:39:35 starting taskId:task_7
    2023/05/16 13:39:37 taskId:task_7 exec cost : 2.063547416s
    2023/05/16 13:39:37 taskId:task_0 exec cost : 2.064091541s
    2023/05/16 13:39:39 taskId:task_5 exec cost : 4.06672125s
    2023/05/16 13:39:39 taskId:task_6 exec cost : 4.066822583s
    2023/05/16 13:39:41 taskId:task_3 exec cost : 6.067720292s
    2023/05/16 13:39:41 taskId:task_2 exec cost : 6.069995s
    2023/05/16 13:39:43 taskId:task_4 exec cost : 8.069296042s
    2023/05/16 13:39:43 taskId:task_1 exec cost : 8.071391709s

  2. thread_pool_oversubscribe=2,concurrency=8 

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    go run ./main.go
    2023/05/16 13:41:02 starting taskId:task_7
    2023/05/16 13:41:02 starting taskId:task_1
    2023/05/16 13:41:02 starting taskId:task_3
    2023/05/16 13:41:02 starting taskId:task_2
    2023/05/16 13:41:02 starting taskId:task_5
    2023/05/16 13:41:02 starting taskId:task_6
    2023/05/16 13:41:02 starting taskId:task_4
    2023/05/16 13:41:02 starting taskId:task_0
    2023/05/16 13:41:04 taskId:task_1 exec cost : 2.057093667s
    2023/05/16 13:41:04 taskId:task_3 exec cost : 2.057156334s
    2023/05/16 13:41:04 taskId:task_5 exec cost : 2.057170667s
    2023/05/16 13:41:06 taskId:task_6 exec cost : 4.066917041s
    2023/05/16 13:41:06 taskId:task_7 exec cost : 4.066944125s
    2023/05/16 13:41:06 taskId:task_2 exec cost : 4.066976875s
    2023/05/16 13:41:08 taskId:task_4 exec cost : 6.070653125s
    2023/05/16 13:41:08 taskId:task_0 exec cost : 6.070612083s

均符合预期。

real-world 模拟（percona）版本

现实场景中，很少会有大批量的2s在SQL在生产环境执行（限互联网业务)，上述的分析过程能否在真实场景中验证呢？尝试用一个执行200ms的SQL来模拟下：

  • DB配置: thread_pool_max_threads设置一个较大的值，以排除影响。

    1
    2
    3
    4
    | thread_pool_max_threads                 | 1000               |
    | thread_pool_oversubscribe               | 1               |
    | thread_pool_size                        | 1               |
    | thread_pool_stall_limit                 | 500             |

  • 执行SQL select sleep(0.2)

  • 执行并发：10

从执行结果中可以看到，只有第一条SQL按照预期的时间执行完成了。
从抓包结果中可以看到，所有SQL几乎是同时发出。观察最慢的一条SQL,但是从客户端发包到服务端响应包发出的耗时，与客户端观察到的耗时也能对应上。

可以验证上述分析过程。

1
2
3
4
5
6
7
8
9
10
2023/05/16 14:47:47 taskId:task_1 exec cost : 239.34925ms
2023/05/16 14:47:47 taskId:task_9 exec cost : 239.560833ms
2023/05/16 14:47:47 taskId:task_5 exec cost : 453.795084ms
2023/05/16 14:47:47 taskId:task_3 exec cost : 458.0005ms
2023/05/16 14:47:47 taskId:task_6 exec cost : 659.441541ms
2023/05/16 14:47:47 taskId:task_8 exec cost : 659.660917ms
2023/05/16 14:47:47 taskId:task_0 exec cost : 862.526375ms
2023/05/16 14:47:47 taskId:task_7 exec cost : 864.450042ms
2023/05/16 14:47:48 taskId:task_2 exec cost : 1.063766875s
2023/05/16 14:47:48 taskId:task_4 exec cost : 1.066266041s

send_sql

response_delay

复现文章中部分线程池卡的现象

配置两个线程池，在其中一个线程池上,通过select sleep()较长时间模拟线程池被慢SQL或者大量任务堵塞的情况，具体配置方案如下：

  • thread_pool_size=2: 保留两个线程池，验证一个卡顿，一个不卡
  • thread_pool_oversubscribe=1: 允许多创建一个线程，每个线程池中可以同时运行1+1=2个线程
  • thread_pool_max_threads=2: 每个线程池的线程数量上限，为thread_pool_oversubscribe的配置约束加一个硬限制，每个线程池中最多允许运行2个线程

操作步骤如下:

  • 通过mysql client在终端发起链接，通过 show processlist语句获取到链接Id, 该链接会分配到 id%2 的线程池中。
  • 用偶数id的链接验证卡顿线程池，用奇数id的链接验证不卡的线程池，链接情况如下:
1
2
3
4
5
6
7
8
9
10
  show processlist;
+-----+-----------------+----------------+------+---------+-------+------------------------+------------------+----------+-----------+---------------+
| Id  | User            | Host           | db   | Command | Time  | State                  | Info             | Time_ms  | Rows_sent | Rows_examined |
+-----+-----------------+----------------+------+---------+-------+------------------------+------------------+----------+-----------+---------------+
|   5 | event_scheduler | localhost      | NULL | Daemon  | 23664 | Waiting on empty queue | NULL             | 23663650 |         0 |             0 |
| 404 | root            | _gateway:51310 | NULL | Sleep   |  7256 |                        | NULL             |  7256057 |         1 |             1 |
| 405 | root            | _gateway:48860 | NULL | Sleep   |  7295 |                        | NULL             |  7295342 |         1 |             1 |
| 406 | root            | _gateway:41144 | NULL | Sleep   |  7254 |                        | NULL             |  7254236 |         1 |             1 |
| 410 | root            | _gateway:46794 | NULL | Sleep   |  7196 |                        | NULL             |  7196042 |         1 |             1 |
+-----+-----------------+----------------+------+---------+-------+------------------------+------------------+----------+-----------+---------------+
  • 在 id=404, id=406的链接上，执行 select sleep(30)，再到 id=410 的链接上执行 select 1，预计 select 'slow'会直接卡顿约30s再执行完成。
  • 同时，在id=405的链接上，反复执行 select 'fast',都可以很快执行完成。

执行结果:

  • id=410 上的语句执行约25s返回结果（终端操作手速影响导致了5s误差）,语句执行时数据库实例输出报错日志，提示线程不足:

    2023-05-16T11:27:09.997916Z 406 [ERROR] [MY-000000] [Server] Threadpool could not create additional thread to handle queries, because the number of allowed threads was reached. Increasing ‘thread_pool_max_threads’ parameter can help in this situation. If ‘admin_port’ parameter is set, you can still connect to the database with superuser account (it must be TCP connection using admin_port as TCP port) and troubleshoot the situation. A likely cause of pool blocks are clients that lock resources for long time. ‘show processlist’ or ‘show engine innodb status’ can give additional hints.

  • id=405链接上的执行都行快。可参考下面抓包截图。

抓包结果:

id=410 上的阻塞SQL,可以看到:

  1. 三条语句在3s内接连发出,但是由于线程池阻塞， select 'slow'原本应该很快返回结果，被卡住
  2. 在30s时，第一个select sleep(30)语句执行完成，空出的线程立刻执行了 select 'slow'并返回结果
    slow query

id=405链接上的执行结果可以看到，每条语句执行都很快。
fast query

参数合理值/已知参数的容量评估

percona 的默认配置中，thread_pool_size=核心数，thread_pool_oversubscribe=3.假设在一台 16core 的服务器上运行percona，默认配置下最多可以有 16*(1+3)=64个worker同时接受请求。也就是最大可并行处理的SQL数量为 64 个。

假设同时有65个执行耗时为10ms的SQL到达服务端，理论上，会有一个进入排队。排查网络、解析等阶段，在客户端观察到的64个SQL执行耗时10ms，1个SQL执行耗时约20ms。这也会导致耗时监控中出现毛刺、耗时分布不符合正态分布。

反之，根据硬件配置、查询的量、耗时等特点，也可以推算合理的参数值。

附录

过程回顾

阶段一 确定原因

看到文章时，基本确认问题根源在执行线程(worker)不够，导致排队，出于以下几点分析:

  • 开头提到的 USE 分析套路，结合排查过类似问题(非SQL)的经验
  • 看到文章作者调大thread_pool_oversubscribe便解决问题, 结合文章中对该参数作用的文档引用，基本可以确定

阶段二 走上弯路

尝试复现时，要先启动一个DB实例，便查询文档该参数如何在配置文件中配置，查了MySQL的文档，似乎只在enterprise版本中才有该配置项，便转头去看mariadb的配置说明(这一步给走弯路埋下了伏笔)。

用docker在本地启动了mariadb实例(thread_pool_size=2 thread_pool_oversubscribe=1)

先尝试用 select sleep(30) 模拟阻塞，用 sysbench 模拟正常流量，结果失败：

  1. 正常流量中有慢的，但是整体还符合正态分布，没有出现都卡的情况。
  2. 加大了 select sleep(30) 查询的并发量，现象同上。

又翻阅了一些文档，看到DB在调度时，对不同类型的SQL调度优先级会有所区别，类似sleep这种啥也不干的SQL，会不会被降低调度优先级，才导致了没有复现呢？(走上了弯路)

尝试人工制造慢查询:

  1. 用 sysbench 制造百万量级的表
  2. 执行 offset limit 的排序查询，并且不走索引

复现结果仍不满意：

  1. 整体耗时上升了，出现几笔长尾的耗时特别长的请求
  2. 但是整体仍然符合正态分布

此时分析了下，整体耗时上升是人工制造的慢查询，占用了过多IO和CPU资源，影响了sysbench SQL执行的效率。

阶段三 柳岸花明

回头又仔细看了下 mariadb关于线程池的文档，注意到文档中提到 thread_pool_oversubscribe 不决定同时有多少线程池被创建出来并执行任务，这个行为逻辑与文章中作者引用的并不相同。
又去查看了另一个MySQL发行版 percona 的文档，对该配置的行为描述与文章中的相符，基本就确定前面复现失败的原因了。

确定了前面提到的复现思路：用有稳定服务端执行耗时、并且不消耗大量硬件资源的SQL,用可控的并发进行模拟流量，到具体执行时：

  • SQL就用 select sleep(N)
  • 可控的并发就用 golang写个小脚本(事后看直接在终端手动操作也是可以的,不过写个脚本也不费事就是了)

mariadb 启动命令和配置

1
2
3
4
5
6
7
8
9
10
11
mkdir mariadb
cat > mariadb/my.cnf << EOF
[mariadb]
#thread pool
thread_handling=pool-of-threads
thread_pool_oversubscribe=1
thread_pool_size=1
thread_pool_max_threads=6
EOF

docker run --name mariadb -v ./mariadb:/etc/mysql/conf.d -e MYSQL_ROOT_PASSWORD=password -p3306:3306 mariadb:10.3

percona 启动命令和配置

1
2
3
4
5
6
7
8
9
10
11
mkdir percona
cat > percona/my.cnf << EOF
[mysqld]
#thread pool
thread_handling=pool-of-threads
thread_pool_oversubscribe=1
thread_pool_size=1
thread_pool_max_threads=1000
default_authentication_plugin=mysql_native_password
EOF
docker run --name percona -v ./percona:/etc/my.cnf.d -e MYSQL_ROOT_PASSWORD=123 -p33060:3306 percona:ps-8

注：Mac M1启动percona时，需要在 docker run 后面添加 --platform linux/x86_64 参数。(percona 未提供arm架构的image)

其他人的重现和分析

https://lotabout.me/2023/Verification-of-Percona-Thread-Pool-Behavior/ 从源代码debug上来分析