Skip to content

Instantly share code, notes, and snippets.

@wych42
Last active June 2, 2023 01:40
Show Gist options
  • Save wych42/87df731da394a14d926c87f51fa9469d to your computer and use it in GitHub Desktop.
Save wych42/87df731da394a14d926c87f51fa9469d to your computer and use it in GitHub Desktop.

原因分析

根据 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配置
| 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
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
  1. thread_pool_max_threads=8;concurrency=8
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设置一个较大的值,以排除影响。
| 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
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
  1. thread_pool_oversubscribe=2,concurrency=8
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设置一个较大的值,以排除影响。
| 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,但是从客户端发包到服务端响应包发出的耗时,与客户端观察到的耗时也能对应上。

可以验证上述分析过程。

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的链接验证不卡的线程池,链接情况如下:
  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 启动命令和配置

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 启动命令和配置

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
EOF
docker run --name percona -v ./percona/:/etc/my.cnf.d -e MYSQL_ROOT_PASSWORD=password -p33060:3306 percona:ps-8

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

module demo/mysqlperf
go 1.20
require github.com/go-sql-driver/mysql v1.7.1
package main
import (
"database/sql"
"fmt"
"log"
"os"
"sync"
"time"
_ "github.com/go-sql-driver/mysql"
)
var logger = log.New(os.Stdout, "", log.Ldate|log.Ltime)
func main() {
db, err := sql.Open("mysql", "root:password@tcp(0.0.0.0:33060)/mysql")
if err != nil {
panic(err)
}
db.SetMaxOpenConns(100)
db.SetMaxIdleConns(100)
// warm up, create actual connection for resue later
// for i := 0; i < 100; i++ {
// err := db.Ping()
// if err != nil {
// panic(err)
// }
// }
var wg sync.WaitGroup
for i := 0; i < 10; i++ {
wg.Add(1)
go func(idx int) {
execQuery(fmt.Sprintf("task_%d", idx), db, 0.2)
wg.Done()
}(i)
}
wg.Wait()
fmt.Println("stopping...")
defer db.Close()
}
func execQuery(taskId string, db *sql.DB, sleep float32) {
defer duration(trace(fmt.Sprintf("taskId:%s exec cost ", taskId)))
logger.Printf("starting taskId:%s", taskId)
row, err := db.Query(fmt.Sprintf("select sleep(%f)", sleep))
defer row.Close()
if err != nil {
logger.Printf("taskId:%s - error exec query: %v", taskId, err)
return
}
// printRows(taskId, result)
}
func printRows(taskId string, rows *sql.Rows) {
for rows.Next() {
var id int
err := rows.Scan(&id)
// handle error
if err != nil {
logger.Printf("taskId:%s - error scan result: %v", taskId, err)
return
}
logger.Printf("taskId:%s - sql result id: %d ", taskId, id)
}
}
func trace(msg string) (string, time.Time) {
return msg, time.Now()
}
func duration(msg string, start time.Time) {
logger.Printf("%v: %v", msg, time.Since(start))
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment