localhost和127.0.0.1的区别

发表于 2023-09-24 更新于 2025-11-29 分类于 network

localhost和127.0.0.1的区别

背景

有人告诉我localhost和127.0.0.1的区别是localhost 不经过网卡，所以性能也高。把我惊到了，因为我还真不知道这个知识点，于是去特别去验证了一下：这是个错误的理解。正确的解释是：localhost会解析成127.0.0.1 然后接下来的流程和127.0.0.1 一模一样

我用Google搜了下标题，果然得到如下图:

红框里是排第一、第四的文章，都大言不惭地说localhost不经过网卡、不受防火墙限制等。

我也看了下第二、第三的文章，这两篇都是说在MySQL命令行中连 localhost 的时候，MySQL命令行会判断 localhost 这个字符串认为是本地连接然后不走DNS 解析流程(走的话就肯定解析成了127.0.0.1)，从而绕过OS 的内核网络协议栈用MySQLD 启动的时候生成的 unix-socket 管道直接连上MySQLD，这样效率更高。

错误信息大概就是在MySQL这个特殊场景下演变而来的，英文搜索就没有这个错误污染信息

但这不是我要说的重点，我想说的是自己动手去求证！这一直都是我们星球里强调的能力和目标，我把这条发到Twitter上后有无数的初学者跑出来质疑或者一知半解不去验证就丢一个结论，这是我比较痛恨的。比如：

Localhost 写死了在 /etc/hosts(那我就要问，你清空/etc/hosts localhost还能工作吗？)
Localhost 不走网卡（但凡抓个包就知道走了，我估计他们抓了，抓的是eth0. 这里有个小小的歧义 loopback 本地回环网卡算不算网卡）

所以我特意再写篇文章再验证下各种质疑，并让大家看看是怎么验证的，我希望你们可以跟着验证一遍而不是只要知道个结论

结论

Localhost 会按dns解析流程进行解析，然后和127.0.0.1 一样。在特殊的程序中比如 MySQL client 会对localhost提前做特别处理。

完整的区别见这篇英文(Google 英文第一篇就是)总结：

验证

问题1：经过网卡吗？

Ping localhost/127.0.0.1，然后 tcpdump -i any icmp or icmp6 [说明：any（抓所有网卡）icmp (精确点只抓ping包) ]，可以明显抓到网络包，所以你可以理解为经过网卡。这指的是这个网络包完整地经过了内核协议栈，加tcp包头、ip包头、mac 包头等等。

而很多人理解的不经过网卡是指不走内核协议栈(毕竟是本机)，加tcp包头、ip包头、mac 包头然后又脱mac包头、脱ip包头、tcp包头，有点像没必要的折腾。比如你通过unix socket 连就不走内核协议栈，性能要高一些

但严格来说是没经过物理意义上的网卡，因为 lo 是一块虚拟网卡，不需要插网线，不会真的走到网卡、网线然后回来。如果让内核重新设计，让127.0.0.1 不过经过内核协议栈行不行？我觉得是完全可以的，当时为什么这么设计我也不懂。

总之，我强调经过网卡是从完整经过了内核协议栈、用 tcpdump 能抓到这个概念上来说的，为了跟别人说用127.0.0.1比用本机物理IP 性能要好而言(实际没有区别)，你如果用本机物理IP 也同样走 lo 网卡

问题2：localhost和127.0.0.1 的关系

如图是我在centos、微软azure(应该是个ubuntu)、macOS下做的测试：

问题3：如果/etc/hosts 中没有写死 localhost 127.0.0.1 会怎么样？

如下图，ping的时候即使没有 /etc/hosts 也可以把localhost 解析成127.0.0.1，为什么呢？所以接着我就 nslookup 看一下是哪个 DNS server做的这事，最后我用114.114.114.114 这个公网的DNS 做了解析，就不认识localhost了，说明去掉 /etc/hosts 之后会把localhost 发给dns server解析，标准的dns(比如114.114.114.114,8.8.8.8) 都不会返回127.0.0.1 ，但是有些特定的实现为了省事帮你解析到127.0.0.1了

问题4：127.0.0.1比localhost少了查/etc/hsots 到底快多少?

这个问题来自这个评论：https://twitter.com/InnerHack/status/1700012845302436087 所以我去验证了一下，特别强调这个数据意义不大，但是你们可以学会用strace，命令：

1	strace -tt ping -c 1 localhost

然后你得到如下图，从strace时间戳你可以看到 localhost 解析成127.0.0.1 的过程，再后面就是ping 127.0.0.1(这里也说明了前面的结论，两者是一样的，就是多了域名解析)

域名解析的时候，先去找/etc/hosts 没找到再去找 /etc/resolv.conf 拿dns server ip然后把localhost发给这个dns server 解析，tcpdump抓包如下，红框是dns server返回的结果：

问题5：127.0.0.1 和127.1 的关系

127.1 会自动补全成127.0.0.1

问题6：为什么还是抓不到包

ping localhost的时候没有包，只有127.1有，如下图：

这是对提示信息敏感度不够，仔细看上图右下角的 ::1 这是个ipv6地址；也就是localhost被默认指向了这个 ipv6(localhost其实可以随便配置指向哪里，新一点的OS 默认都是指向 ipv6了)，抓包命令多加一个 icmp6 (一个协议名字，默认不抓这个协议) 就能抓到了：tcpdump -i any icmp6

总结

唯有动手能解释一切，不要空逼逼(不是说你们，是说Twitter上那帮人，我是被他们留言多了逼着写了这篇)

我是欢迎一切有理有据的质疑，事实文中很多信息来源于别人的质疑，然后我去验证

然后好多验证手段你们可以学学，比如nslookup/tcpdump/strace 等。

我给的文章链接也可以仔细读读，能学到很多东西，每一次进步都来自你深挖、展开能力。

RFC6761 中对 localhost 有详细的说明，且已经定义的非常清楚：localhost 表示Loopback Address（127.0.0.1 或 ::1），另外应用程序可以对这个域做特殊识别处理，可以不走DNS解析流程。

如果你觉得看完对你很有帮助可以通过如下方式找到我

find me on twitter: @plantegg

知识星球：https://t.zsxq.com/0cSFEUh2J

开了一个星球，在里面讲解一些案例、知识、学习方法，肯定没法让大家称为顶尖程序员(我自己都不是)，只是希望用我的方法、知识、经验、案例作为你的垫脚石，帮助你快速、早日成为一个更合格的程序员。

争取在星球内：

养成基本动手能力，对各种技能试试，祛魅
拥有起码的分析推理能力–按我接触的程序员，大多都是没有逻辑的
知识上教会你几个关键的知识点

解决Java/MySQL性能问题的思路

发表于 2023-08-28 更新于 2025-11-16 分类于 performance

解决 Java/MySQL 性能问题的思路

10年前写的，重新发一下

系统性能问题

CPU（基本上WEB服务器没有多少IO，主要是CPU有瓶颈）
- top/vmstat 观察CPU使用率，Load负载，r/b线程数量等；
- IO（数据库大多数时候瓶颈是IO，主要是索引没建好；如果数据库CPU紧张的话，检查一下是不是order by/group by 等操作太多）
- vmstat 观察IO/Util吞吐，磁盘最怕随机读写了（比如：索引命中后，需要离散地从磁盘读数据）
- 对于数据库来说最怕内存不够的时候使用Swap了，所以尽量增大分配给数据库的内存，一旦有Swap就要引起注意了

Java程序问题（运行慢）

先通过 top 查看整个CPU资源使用情况；
通过top -Hp pid查看java进程的每一个线程占用CPU的情况；
如果有一个线程占用CPU过高，有两种可能：
没有内存了，Java垃圾回收线程不停地运行尝试回收内存，但是每次无法收回，确认：
jstat -gcutil pid 1s 观察10多秒钟就能发现了，看是不是内存使用率接近100%了
类似于死循环（hash冲突攻击），就是一个线程一直占用一个核的所有CPU资源（其实一个线程总是占用一个核超过50%的资源都是不太正常的），解决：
用我的checkPerf脚本，定位这个线程具体执行的任务（能具体到某一行），对应看代码解决。

    如果有很多线程，每个线程占用的CPU都不多(基本都在10%以下)，那基本是正常的，只是程序并发确实很高。

如果死锁：
    jstack -l pid 多执行几次，统计一下stack中总是在等待哪些锁，可以对锁id进行排序统计（sort uniq grep）
上面列出来的都是明显的瓶颈，最可怕的是哪里都没有明显的瓶颈，哪里都要偷一点点CPU资源走，这是可以试试JProfiler这样更专业一点的工具，同时要配合自己对业务的了解来解决。

一旦触发频繁地抛出异常，CPU占用率会急剧地上升（抛异常比正常情况下会慢2个数量级）主要是由于：Throwable的构造函数中会调用native的fillInStackTrace()，这个方法就会构造整个异常栈了。

Java内存的问题，如果有内存泄露（就是执行完fgc/old gc后不能回收的内存不断地增加）：
怎么确认没有内存了：
jps -lmv pid 先确认你的参数，也就是你给JVM分配了多大的堆(-Xmx 比如1G); 然后jstat -gcutil pid 1s 看看GC运行情况，如果(O/E 两列基本接近100%的话就是内存不够了)
内存不够分两种：一种是真的不够，就是你们的系统很庞大需要1G以上的内存，而你只分配了1G，这个没什么好说的，增大内存，物理内存不够就投钱买；
第二一种是你们的代码写的烂，有内存泄露，这样的话分配多少内存都不够，得找出是否有内存泄露，看接下的解决方案

快速解决：jmap -histo:live pid  来统计所有对象的个数（String/char/Integer/HashEntry 这样的对象很多很正常，主要是盯着你们公司的包名下的那些对象）
每隔一分钟执行一次上面的命令，执行5次以上，看看你们公司报名下的对象数量哪个在一直增加，那基本上就是这个对象引起了泄露；
用课堂上的工具HouseMD(java -Xbootclasspath/a:/usr/java/jdk1.6.0_29/lib/tools.jar -jar housemd-assembly-0.2.2.jar pid)来动态监控创建这个对象的地方（一般来说很多时候创建了这些对象把他们丢到一个HashMap然后就不管了），分析一下有没有释放！
    >trace -s -d ClassName

上面的方法实在没法定位就用: jmap -dump:live,format=b,file=heap.bin pid 导出整个内存（耗时间，需要很大的内存的机器才能对这个导出文件进行分析，会将JVM锁住一段时间）
    在Eclipse的插件EMA中打开这个文件（2G的物理文件需要4G以上的内存，5G以上的需要将近20G的内存来分析了）
    盯着你们公司报名的那些对象，看看引用关系，谁拿着这些对象没释放（是否是必要的），可以一直追查的RootReference

MySQL 数据库的性能问题

大部分情况下是磁盘IO的问题（索引没建好、查询太复杂）；

索引问题的话分析慢查询日志，explain 他们挨个解决。

偶尔也有数据库CPU不够的情况，如果并发高CPU不够很正常，如果并发不高，那很可能就是group by/order by/random之类的操作严重消耗了数据库的CPU

1
2
3

mysql -e "show full processlist" | grep -v Sleep | sort -rnk6 查看那些SQL语句执行的太长
拿出这个SQL语句分析他们的执行计划: explain SQL 然后改进；
分析慢查询日志，统计top10性能杀手的语句，挨个explain他们，然后改进（具体改进办法具体分析，这里只谈思路）

总结一下数据库问题就只有这三招：show full processlist/分析慢查询日志/explain（然后建好联合索引）

补充一个数据库连接数不够的问题，很多人碰到了，不知道怎么解决：

在mysql 命令行里执行：show variables like ‘%max_connections%’; 看看你们的数据实际配置是多少（比如1000）
show full processlist 数一下多少行，一行代表一个连接，比如这里是1000行，那基本上就是连接数不够了，你要解决的为什么你的数据库需要这么多连接
接下来分析这些连接是从哪来的IP，然后问你自己：根据你们的服务类型的特点需要这么多连接吗？

数据库性能问题提问请给出：

show full processlist;
查询语句;
表结构(包括索引结构);
数据库引擎类型;

如何从几百万个抓包中找到一个异常的包

发表于 2023-08-23 更新于 2025-11-16 分类于 tcpdump

如何从几百万个抓包中找到一个异常的包

这篇算是对抓包定位原因在哪里的落地篇，没什么高深的技术，都是很low但是你一定可以照着操作的，算是星球内必须学会和带走的内容

场景

问题

一次业务请求包含160个拖数据的SQL查询，通过160个连接，发给160个Database，但是过几分钟后总有报错。几分钟抓包文件10G左右，网络包几百万个，怎么找到报错的那个？

几个麻烦的地方

虽然问题每次稳定重现，但是每次重现的Database不是固定的；
从开始拖到出现问题需要几分钟不等，抓包量巨大
有一个连接报错后剩下的其它连接也会断开
这么多端口怎么解析成MySQL协议，请看：https://t.zsxq.com/0f7nMlKax

问题发生条件

一个Client同时开160条连接，发160个类似的SQL去160个MySQL Database上拖数据时必现
如果将拖数据的SQL拖取数量改小一点就不再出现——拖取少执行更快，没达到触发bug条件
网络传输得慢一点、JDBC streaming 模式下发生，比如streaming流模式拖数据是几MB每秒，去掉流模式拖数据是几十MB每秒且不报错。这里可以通过设置内核 tcp rmem/加大rtt延时来模拟重现——和我们的必做实验callback一下，无时不刻不展示下我们必做实验的用途。

分析过程

分析技巧和步骤：

抓包，从握手到报错断开全抓下来，时间跨度3分多钟，抓下来10个G左右，怎么分析？
editcap -c 200000 把抓包切小，每个文件20万个包，保证wireshark打开不太慢（editcap 是安装wireshark附带的小命令，附带的还有tshark、capinfos等）
wireshark打开切小后的最后一个文件，搜reset/fin 找到第一个断开的连接(如下图)，找到9913/42909这对连接端口
回到10个G的抓包中，用 tshark -r ./big.pcap -Y “tcp.port==42909” -w 42909.pcap 把42909这条连接所有包过滤出来，-r 读，-w 写
wireshark 打开42909.pcap 傻子也能看到问题在哪里了

切完后的包，切完后的文件会加时间戳，时间戳可以和报错时间对应：

-rw-r--r--  1 root  root   329M Jun 16 17:46 big00_00000_20230616170456.pcap
-rw-r--r--  1 root  root   1.1G Jun 16 17:46 big00_00001_20230616170524.pcap
-rw-r--r--  1 root  root  1022M Jun 16 17:46 big00_00002_20230616170546.pcap
-rw-r--r--  1 root  root   1.1G Jun 16 17:46 big00_00003_20230616170608.pcap
-rw-r--r--  1 root  root  1012M Jun 16 17:46 big00_00004_20230616170630.pcap
-rw-r--r--  1 root  root   982M Jun 16 17:46 big00_00005_20230616170652.pcap
-rw-r--r--  1 root  root   938M Jun 16 17:46 big00_00006_20230616170714.pcap
-rw-r--r--  1 root  root   1.1G Jun 16 17:46 big00_00007_20230616170735.pcap
-rw-r--r--  1 root  root   661M Jun 16 17:46 big00_00008_20230616170759.pcap

搜reset/fin 找到第一个断开的连接，第一个断开的连接才是罪魁祸首：

进一步分析发生问题的连接

知识点：

MySQL 协议是一来一回，也就是client发查询然后等查询结果全部返回，然后再发下一个

按协议在一个SQL查询的数据传输完毕前client不能再发任何请求，MySQL Server负责一直发送查询结果直到发送完毕。

如下两个截图是从42909.pcap文件中过滤到的抓包从握手到断开的全过程，图1过滤条件：tcp.srcport eq 42909 and tcp.len>0 (42909是客户端，9913是MySQL端口)，可以看到客户端 login（连数据库肯定得要user、password认证），然后是client查了MySQL的一堆服务端参数(下图第二行)，再然后是client设置了几个参数(set 那些)。关键的是倒数第二行client发了一个SQL给MySQL需要拉取大量数据(建立连接17.98秒的时候)，然后是数据传数据过程，第190秒的时候client发了 Quit断开连接

上图因为加了过滤条件，只看client端并去掉ack后的所有包，没看到全貌，这个过程9913的MySQL 服务端又做了啥呢？因为太长前面漫长的传数据就不截图了，只看最后连接的断开。

但是下图红框所示的地方可以看到MySQL Server 传着传着居然带了个 fin 包在里面，表示MySQL Server要断开连接了，无奈Client只能也发送quit 断开连接。红框告诉我们一个无比有力的证据MySQL Server 在不应该断开的地方断开了连接，问题在 MySQL Server 端

结论

就抓包结论来看是 MySQL 在不应该断开的时候发送了 fin 主动断开连接，可能是MySQL的bug

题外话，这个包证据抓了有一周了，但是MySQL研发同学始终绕来绕去(比如我的代码没记录下这个SQL就是没收到，我的代码没问题——熟悉的味道)跟我打了一周太极(异地)，我一查发现我和他老板认识且在一层楼，赶紧面对面找他老板讲清楚这个问题，且签字画押承认是MySQL的问题，然后继续推进排查，最终结果是为啥我跟你们一起期待吧，有了结果我再来update。

练习

找个MySQL，然后开始抓包，用mysql-client连一下MySQL Server随便发几个SQL，然后看看一来一回的响应

如果哪怕在星球一年你只要好好掌握这一篇用到的技能也能帮助你在日常工作中互相扯皮的时候快速给出精准定位和分析，值回星球票价，加油

比如这个案例我同时打开了5/6个wireshark分析不同的流、整体搜索等

其它

这些技巧不只是用在MySQL 上，其它微服务、redis等涉及网络调用场景的扯皮的地方都可以用

wireshark 附带的一些小工具

capinfos rsb2.cap

tshark -q -n -r rsb2.cap -z “conv,ip” 分析流量总况

tshark -q -n -r rsb2.cap -z “conv,tcp” 分析每一个连接的流量、rtt、响应时间、丢包率、重传率等等

editcap -c 100000 ./rsb2.cap rsb00.cap //把大文件rsb2.cap按每个文件100000个package切成小文件

存放在这里：

/usr/sbin/capinfos
/usr/sbin/dftest
/usr/sbin/dumpcap
/usr/sbin/editcap
/usr/sbin/mergecap
/usr/sbin/randpkt
/usr/sbin/rawshark
/usr/sbin/reordercap
/usr/sbin/text2pcap
/usr/sbin/tshark

net_write_timeout 报错

最后回答一下上一篇中提到的流模式下 net_write_timeout 报错

如下图，JDBC 在 streaming 模式下，不断读取下一行，如果这个过程只要报错抛出的异常就是 StreamingNotifiable 异常

错误信息定义如下，这个报错误导太严重，从以上JDBC 代码可以看到只要读取下一行报错了就会报调大 net_write_timeout 错误，但是实际原因却是连接异常断开，和 timeout 没有一点关系，你看久经考验的 JDBC 代码也不是那么完善还得你会 Debug

1	CommunicationsException.ClientWasStreaming=Application was streaming results when the connection failed. Consider raising value of ''net_write_timeout'' on the server.

这个报错误导了排查分析方向，不知道坑了多少人了！当然如果MySQL 因为net_write_timeout 超时断开连接当然应该报如上错误，但是 JDBC 搞不清楚MySQL 为啥断开，就瞎猜是 timeout 了，然后只要是连接异常读数据错误(包含断开)就报这个错误。希望你们不要被坑

记住这个坑人的报错堆栈：

Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of 'net_write_timeout' on the server.
    at sun.reflect.GeneratedConstructorAccessor150.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3749)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3649)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4090)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:972)
    at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:2123)
    at com.mysql.jdbc.RowDataDynamic.nextRecord(RowDataDynamic.java:374)
    at com.mysql.jdbc.RowDataDynamic.next(RowDataDynamic.java:354)
    at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:155)
    at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:6726)
    at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:865)
    at com.alibaba.druid.pool.DruidPooledResultSet.close(DruidPooledResultSet.java:86)

不过你要仔细看的话，它还是有caused by，如下，但是绝大部分工程师看到这个堆栈会忽视，上面都有 net_write_timeout 我还管个屁 Can not read response from server, 不过要是结合抓包的话就能理解：at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3186) 这个根本的原因是 JDBC 从服务端读取数据的时候报错了

Caused by: java.io.EOFException: Can not read response from server. Expected to read 405 bytes, read 272 bytes before connection was unexpectedly lost.
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3186)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3709)
    ... 40 common frames omitted

最后希望你没被绕晕，再去看看上一篇中推荐的流模式原理，把代码和网络应用层完美地结合起来

完整堆栈也可以参考网络上别人碰到的：https://github.com/brettwooldridge/HikariCP/issues/1771

看 Google 里面对这个问题的分析基本都没入门：https://www.google.com/search?q=Caused+by%3A+com.mysql.jdbc.exceptions.jdbc4.CommunicationsException%3A+Application+was+streaming+results+when+the+connection+failed.+Consider+raising+value+of+%27net_write_timeout%27+on+the+server.&hl=en&sxsrf=APwXEddTwJGjFpkKuWHyXjlTvwTo2OUMhA%3A1687226872136&ei=-AmRZI7gB6-C0PEPmOGbwAE&ved=0ahUKEwiOvPny4dD_AhUvATQIHZjwBhgQ4dUDCBE&uact=5&oq=Caused+by%3A+com.mysql.jdbc.exceptions.jdbc4.CommunicationsException%3A+Application+was+streaming+results+when+the+connection+failed.+Consider+raising+value+of+%27net_write_timeout%27+on+the+server.&gs_lcp=Cgxnd3Mtd2l6LXNlcnAQA0oECEEYAFAAWABgAGgAcAF4AIABAIgBAJIBAJgBAKABAqABAQ&sclient=gws-wiz-serp

下次在你们的业务代码里如果出现查询结果太大导致JVM OOM的话你可以站出来说把拉取数据改成流模式会有奇效 :) , 当然随之而来的是会有 net_write_timeout 报错，嗯，你的机会来了，业务技术上按照你的指引发展，出了问题你能顶得上

扑朔迷离的根因分析--抖动和并发

发表于 2023-07-23 更新于 2025-11-16 分类于 performance

扑朔迷离的根因分析–抖动和并发

前言

我们之前说过根因分析第一就是要追着 RT跑，随着并发的增加哪里RT增加快哪里就是瓶颈，这是我们的基本原则，但总有一些例外，我们今天想说说例外

场景

如下图，应用是多个Tomcat集群，Tomcat节点可以随意增加，后端是一组DB集群，有几百个Database实例，每一次业务请求都会对应多个Database查询

问题

开始的时候客户端压2个Tomcat集群，QPS 700，Tomcat节点CPU 90%，Database每个节点CPU 20%左右，于是增加1个Tomcat 节点这个时候QPS 还是700，Tomcat的RT增加了50%，Tomcat CPU 降低到60%，继续增加Tomcat 节点 RT、QPS保持稳定，CPU使用率下降。

所以这里要搞清楚哪里是瓶颈，如果Tomcat是瓶颈加Tomcat节点为什么没有效果。如果Database是瓶颈但是增加Tomcat节点的时候Database 的RT有一点点增加，远远没有到增加50%的RT 程度

分析

首先最容易想到的是Tomcat 和 Database之间的网络、网关、LVS 等资源到了瓶颈，但是经过排查分析这些环节都排除了，另外也排除了Tomcat到Database的连接池、Database的磁盘等瓶颈，另外Tomcat 访问Database全是查询，没有事务。

看起来事情比想象的复杂，于是进行了如下压测：

先用一个压力端压3个Tomcat中的2个，QPS 跑到700，然后新开一个压力端压第三个Tomcat(新开压力端是排查压力机的问题，新开Tomcat是想排除Tomcat 的问题)，如果Tomcat是瓶颈的话QPS应该上去，或者说后端没有问题的话那两个Tomcat 的700 QPS得保持基本稳定不变或略微下降才对。

实际上第二个压力端跑起来后，前两个Tomcat的QPS 铛就掉下去了，总QPS 保持稳定不变，也就是随着Tomcat给后端并发压力的增加后端肯定给了一个负反馈给那两Tomcat，导致那两Tomcat QPS掉下去了。这个负反馈明显得是Database的RT在增加，但是从监控来看Database的RT 从0.6增加到了0.8，但是Tomcat 的RT 增加更快从19.7增加到了29.8.

单独压DB，DB的QPS能高5倍，CPU 也可以跑到100%。看起来单压都没问题，一组合就不行了

问题在Database

绕过Tomcat 用相同的SQL 压Database QPS 一下子就能上去，Database 的CPU 也跑到了100%，但是只要走Tomcat 就会上不去。

打开Tomcat 日志将所有Database的响应时间拉出来分析，发现随着并发的增加 100 ms的响应也多了很多，实际上这些查询都是1ms就应该返回

具体分析过程看这里：https://plantegg.github.io/2019/12/16/Intel%20PAUSE%E6%8C%87%E4%BB%A4%E5%8F%98%E5%8C%96%E6%98%AF%E5%A6%82%E4%BD%95%E5%BD%B1%E5%93%8D%E8%87%AA%E6%97%8B%E9%94%81%E4%BB%A5%E5%8F%8AMySQL%E7%9A%84%E6%80%A7%E8%83%BD%E7%9A%84/

原因

当压力增加的时候MySQL端等锁导致的 RT 抖动或者说长尾越来越多，虽然没有数据库的写，但是查询的时候优化器也需要统计行数等数据来为查询优化器做选择依据，这个统计动作会触发加锁排队(极短)，但是因为这一代Intel CPU指令的变化导致这个锁被放大了10 被，所以最终Tomcat 端看到的长尾就多了

为什么

为什么同样的环境、同样的SQL 绕过Tomcat 就能压上去？

绕过后的压测场景没有业务逻辑，每次请求就是一条SQL，虽然有抖动但是对平均RT拉升不明显。

走业务逻辑压Tomcat 为什么不行？

业务逻辑是一次请求会发256条SQL，等这256条SQL全部返回来了业务请求才会返回！请反复读这句话3遍再往下看

如果256条SQL 中有一条花了100 ms返回那么整个业务逻辑的RT 就是100ms，假设1%的概率一条SQL是100ms，99%的SQL 是 1ms，你可以先停下来算一算这种业务模型下的平均RT是多少

计算抖动下的平均RT

关于这个抖动对整体rt的影响计算：

注:假设正常查询rt 1ms，逻辑平均rt=(1-power(1-抖动概率,物理查询次数))*抖动大小+(power(1-抖动概率,物理查询次数))*1ms

当前场景下，逻辑QPS:物理QPS=1:256，假如每次查询有1%的物理（RDS）rt抖动到100ms，则会导致逻辑平均rt恶化到92.44ms.

在一次逻辑查询里，只有所有物理查询都不抖整体才是不抖，RT正常；如果有一个或多个物理查询抖了，那么逻辑RT就是抖动RT。

所以一次逻辑查询不抖的概率是： power(1-抖动概率, 物理查询次数)

反过来想这256条SQL都不碰上抖动这次业务请求才会1ms返回(概率极低)，否则就是256ms返回

为什么要讲这个案例

倒不是出于原因分析，这个原因几年前就分析清楚了，但是这个场景：一次业务请求会涉及多次SQL、Redis、MQ的调用，只要其中有一个有短板、抖动这次业务请求就慢了。这简直太常见了

但难在别人的抖动很低被平均掉了，但是业务(Tomcat) 就要替别人背锅了，因为别人的RT 几乎没有增加或者加很少，但是Tomcat RT增加很明显，瓶颈当然看着像是在Tomcat 上。背锅吧也不可怕可怕的是你增加Tomcat 节点也不能解决问题，这才是你要从这个案例里学到的。

如果你的Tomcat 调后端因为短板(抖动)导致压力打不到后端，因为抖动导致Tomcat不能快速返回

上游影响下游：

和本文无关但是可以放一起综合来看上下游互相影响的复杂性

以前认为事务不提交的主要代价是行锁持有时间变长(这确实是个问题)，今天见识到了新代价，事务不提交会导致事务活跃链表变长，增加copy readview的代价，进而导致DB的RT 增高，实际导致DB RT高的根本原因是DB前面的业务早到了瓶颈，来不及发送commit，导致DB端事务堆积严重。也就是业务瓶颈导致了后端DB RT高，只看RT就会被蒙蔽——怎么解决？可以抓包看commit发送慢

扑朔迷离的根因分析

发表于 2023-07-23 更新于 2025-11-29 分类于 performance

扑朔迷离的根因分析

原则

追着RT 跑，不断加压力，到瓶颈前随着并发的增加RT很稳定。

但是你要对你的RT怎么来的，包含哪些环节的消耗，这样才不会出错。

如下图左边是QPS不停地增加，每一次台阶(增加20%流量)都是一次加压过程，右边是对应的 RT，可以看到在绿线阶段几乎是平稳的，直到最后的红色箭头 RT略微有一点点提升，但是整体也还好，说明基本没到瓶颈

当然这个图是经过长时间调优的结果，来之不易，是理想的期望系统状态，但在这之前是长时间的痛苦分析和瓶颈在哪里的定位过程。

凡是复杂的实际业务总是有很多干扰项出现在你的理论图上，你得很好地识别他们

业务结构

概念说明：

黑色=Database=被依赖业务=物理

蓝色=Tomcat=上游业务=逻辑

上游响应时间=下游业务响应时间+网络时间+上游自身处理耗时

响应时间=RT=耗时监控

tcprt：从内核网络取Database的响应时间

实际很魔幻的是同样流量有时候压测很稳定，有时候又不稳定，性能上不去(稳定时可能是压测数据、没有触发Database雪崩之类的问题)，所以导致问题

所有压测过程中肯定是没有任何资源上的瓶颈(CPU、内存、网络带宽、磁盘等等)

监控数据

如图，蓝线表示Tomcat，黑线表示Database被调用方，可以看到每次黑色 RT上升QPS下跌很猛(符合预期)，奇怪的是黑色RT很快降下来后蓝色RT还会维持较高一段时间，监控频率每5秒采集一次，以下所有监控图时间范围是一样的，但采集频率不一样

(图1)

上图的两个 RT 监控数据都是Tomcat的业务代码记录下来的，比如Database的响应时间就包含网络+Database的处理时间

如下图通过网络监控看响应时间(tcprt 阿里云文档，从OS 内核中取到网络包的响应时间)，蓝线表示Tomcat，紫线表示Database，监控力度每1分钟采集一次，有被平均

以上两个监控图的矛盾点：如果从网络层面记录的Database RT 可以看到上升幅度不明显，但是Tomcat 的RT上升很明显，但是Tomcat记录的RT则又是Database 上升明显。

补充知识

tcprt和tomcat业务进程记录的 Database rt差异，tcprt记录到的是RDS/Database的响应时间+网络时间，tomcat在这个基础上还要加入自己进程调出处理时间，比如tomcat进程取到数据库连接的时候连接需要排队等待1秒钟(后面有分析)，那么这个一秒钟对tcprt来说是不会记录进去的，但是客户端感知到的这次调用是1秒以上。当然业务记录的Database 还可以更精准，比如在连接池Druid(或者其它连接池的实现)内取记录，但是无论如何从业务进程到OS内核这里的差距总是存在的。

Tomcat CPU 监控

问题

可以很清楚看到 QPS 下降是因为 RT上升，那么究竟是Database的RT上升导致的还是Tomcat的RT上升导致的。

但是我们从监控图也能看到Database RT降下来后Tomcat RT还维持高水位，所以有点迷惑了。

继续看另外案例

案例2 yy

两次压测监控数据，左右两个图标是同一时间的QPS和RT，蓝线表示Tomcat，黑线表示Database被调用方

从两个图来看，随着并发加高(QPS加高) 黑色RT增加明显，但是跑着跑着降下去了，可以理解成突发流量导致黑色RT增加，但是很快黑色RT稳住了阵脚，降回去了，但是蓝色 RT没降，所以表面看起来是蓝色(Tomcat)处理能力到了瓶颈

上图时间点内核监控的tcprt，可以看到还是Database 处理耗时增加，和上图的黑色RT下降根本不匹配，上图黑色RT最后在2.96ms，下图内核监控到的Database的tcprt在8.49，差异矛盾点

第三次压测图

从第一个图来看，随着并发加高(QPS加高) 黑色RT增加明显，蓝色 RT去掉黑色部分也有增加，并且黑色、蓝色都没降回去，看起来主要是黑色(Database)处理能力到了瓶颈

纠结的时候就在Tomcat上抓包确认一下，如下图黑色 Database服务端口是5493，可以看到Tomcat 发request总是很快，但是Database 响应都是几十毫秒(下图红色框)，和监控一致。其实监控可以说明问题，但是我担心业务记录时间不准，以及建连接时间都考虑在内，所以想抓包微观上印证一下，这种项目牵扯到很多人你搞错了方向丢人不说，大家合作联调浪费很大，所以必须稳！

如果说问题在Database上，那为什么会有Database RT忽上忽下，Database RT降下去了Tomcat RT不降？我们要继续分析一下 Tomcat RT以及Database RT是怎么记录和实现的

分析

问题解决后的原因分析以及数据整理

这个时候我们再把Tomcat部分的业务调用和RT记录再细化一下，如下图：

Druid分析

创建和回收逻辑：https://exceting.github.io/2019/08/28/%E6%B1%A0%E5%8C%96%E6%8A%80%E6%9C%AF%EF%BC%88%E4%B8%80%EF%BC%89Druid%E6%98%AF%E5%A6%82%E4%BD%95%E7%AE%A1%E7%90%86%E6%95%B0%E6%8D%AE%E5%BA%93%E8%BF%9E%E6%8E%A5%E7%9A%84%EF%BC%9F/#%E4%B9%9D%E3%80%81%E4%B8%BB%E6%B5%81%E7%A8%8B5%EF%BC%9A%E5%9B%9E%E6%94%B6%E8%BF%9E%E6%8E%A5

作为Tomcat和Database的连接点、枢纽点搞清楚Druid的逻辑对理解Tomcat和Database之间的问题的理解很关键。

比如以下要说的三个Druid 错误状态如果你不放到一起比较，看到这个错误你最多反应就是连接池不够了，什么原因不知道。但是如果放到一次比较一次后你以后对详细错误提示会积极敏感，进而发现第四、第五种错误提示

这就是综合比较、总结的好处。

Druid 最核心的类是 DruidDataSource，连接的构建，入池，获取，收缩，销毁，以及核心监控数据都在这个类维护

连接池初始化流程：初始化驱动实例 -> 加锁 -> 初始化属性 -> 初始化过滤器 -> 校验参数 -> 创建初始化连接并校验后加入池中 -> 创建logStatsThread、createConnectionThread和destroyConnectionThread -> 注册MBean，用于支持JMX -> 如果设置了keepAlive，通知createConnectionThread创建连接对象 -> 解锁

Druid 创建连接的堆栈如下：

"Druid-ConnectionPool-Create-1647809146" #265 daemon prio=5 os_prio=0 tid=0x00007fbcdfd5f000 nid=0x1a0 runnable [0x00007fbcdf9fd000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
        - locked <0x00000000e71ca648> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3001)
        at com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:567)
        at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1018)
        at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2253)
        at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2284)
        at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2083)
        - locked <0x00000000e7f898f0> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:806)
        at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
        at sun.reflect.GeneratedConstructorAccessor196.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
        at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:410)
        at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:328)
        at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1558)
        at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1623)
        at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2468)       
        
"Druid-ConnectionPool-Create-1823047135" #160 daemon prio=5 os_prio=0 tid=0x00007fbd60cf0000 nid=0x142 waiting on condition [0x00007fbd043fe000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park0(Native Method)
        - parking to wait for  <0x00000000c448b348> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at sun.misc.Unsafe.park(Unsafe.java:1036)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:176)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2047)
        at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2443)

Druid 报错1

获取连接排队是基本不消耗CPU，下图右上角是获取失败的日志打堆栈消耗，可以看到异常非常多。

Druid最大连接数默认是30，多次调大，30->60->120->160，一直调下去对调大能解决问题都没有信心了，总是报错

maxWaitThreadCount 30, current wait Thread count 0

调大到160后的报错堆栈，对应源码这个报错说明报错时已经有160个线程在等连接了，别等了，先快速报错返回吧

Caused by: java.sql.SQLException: maxWaitThreadCount 160, current wait Thread count 0
        at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1620)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1404)
        at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059)
        at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2756)
        at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1382)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1374)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:98)

对应代码：
                   final Lock lock = this.lock;
                    lock.lock();
                    try {
                        if (activeCount < maxActive) {
                            activeCount++;
                            holder.active = true;
                            if (activeCount > activePeak) {
                                activePeak = activeCount;
                                activePeakTime = System.currentTimeMillis();
                            }
                            break;
                        } else {
                            discard = true;
                        }
                    } finally {
                        lock.unlock();
                    }

                    if (discard) {
                        JdbcUtils.close(pyConnInfo.getPhysicalConnection());
                    }
                }
            }

            final ReentrantLock lock = this.lock;
            try {
                lock.lockInterruptibly();
            } catch (InterruptedException e) {
                connectErrorCountUpdater.incrementAndGet(this);
                throw new SQLException("interrupt", e);
            }

            try {
                if (maxWaitThreadCount > 0
                        && notEmptyWaitThreadCount >= maxWaitThreadCount) {
                    connectErrorCountUpdater.incrementAndGet(this);
                    throw new SQLException("maxWaitThreadCount " + maxWaitThreadCount + ", current wait Thread count "
                            + lock.getQueueLength());//bug? lock.getQueueLength()永远为0，应该改成：lock.getWaitQueueLength(notEmpty)
                }

以下两个Druid 报错这次压测没有出现但是可以放一起比较一下，其它项目场景经常出现

Druid 报错2

Druid类似报错，明显是等了5秒最大等待时间还没有获取到连接：

红色错误信息表示等了5006毫秒（设置的5000毫秒超时）还没有取到连接，所以超时了，然后抛出错误堆栈。

红色信息还提示我们当前连接池最大10，目前 active 0, 说明不是连接池满了取不到，而是连接池里一直是空的。

看到这个错误不能说明数据库、访问数据库有啥问题，只能说明Druid 连接池取不到连接，要继续分析Druid创建连接的线程栈。或者比如Druid 参数设置不合理，可以把min、init、max 连接数设置为相同的值，避免压力高峰期再去创建连接。

Druid通过另外一个task（thread）异步给连接池补充连接，也就是这里可能是Druid创建连接失败，比如密码错误、比如连不上数据库，比如创建的thread卡死了、报其他异常了

Druid创建连接和业务取连接是两个线程，所以业务取连接报错是看不到创建连接报错的堆栈和原因的

1
2
3

#grep CreateConnectionThread.run stack4.log
	at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2818)
	at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2813)

Druid 报错3

借出连接为0(active 0)，creating也是0，没有新连接正在创建。

分析方法：

dump Java应用内存，用MAT内存分析工具打开dump文件
使用OQL，select * from com.alibaba.druid.pool.DruidDataSource where createTaskCount=3
选出来的DruidDataSource即为有问题的datasource

原因

Druid中有个计数器createTaskCount，用来记录每个连接池当前正在创建连接的任务数，默认不能超过3。Druid中，在keepAlive=true的情况下，这个计数器有bug，存在加了但没减的情况，导致这个值涨到3之后没有减回去，从而无法提交新的创建连接任务。

注意，进入这个状态后的连接池，是无法自动恢复的。Druid升级到1.1.24可以修复这个问题。

Druid 报错 4

下图这个堆栈很有意思，栈顶是连接不够触发 Druid 创建新连接，但是建新连接报错了，于是需要记录日志，但是有些场景(比如任务流) 要求，错误信息要往数据库存，于是记录日志触发取连接，然后就死锁了：

分片逻辑

因为数据量太大，一台Database存放不下，自然会分片，或者说单表几千万之后也是建议分片。

分片逻辑是取业务id最后两位的字符去取string hashcode，再对16个Database分片

如果对id后两位字符(从00-99供100个数字，因为不排除id里面有字符，但实际主要是0-9的数字)的ascii码取hash然后按16取模的结果：
0
1
2
3
4
5
6
7
8
9  --开始不正常，10-14号分片没有直接跳到15号分片
15
0
1
2
3
4
5
6
7
8
14
15
……

//分片求模代码
for(int i=0;i<10;++i) //0的ascii码是48，依此类推
	for(int j=0;j<10;++j)
		 int value=((48+i)*31+j) mod 16;

补充个小八卦

为什么取某几位尾数来求模？比如很多业务按user_id拆分片，然后希望这个用户的所有订单拆分也落在一个分片内。于是他们想到的办法是在订单id最后几位上追加进去下单人的user_id后几位，对订单拆分会取订单id后几位hash，这样同一个用户肯定到同一个分片

这样查询某个用户的所有订单时(高频需求)就只需要查一个分片，否则就要扫描所有分片。

掏出你的某宝、某东看看你的订单后几位

分片后的数据，明显两头的多中间的少，这必然导致后面的 Database 负载不均衡：

Java源码：

总结

问题的根本原因？

多个Database中的某几个瓶颈，为什么会这样见数据分布部分的分析

为什么Database RT监控能降下来？

业务Tomcat 帮Database拦截了流量，一旦Database响应慢 Druid 连接就会不够，请求都堵在Tomcat中，导致Tomcat RT升高(包含等待连接时间)——替人堵了枪眼，很好，Tomcat crash总比 Database crash要好，但是业务要清楚这是替人挨枪子，该往哪里去查瓶颈。

比如加流量20%，开始Database RT升高，很快连接不可用，可能有接近20%的流量被Tomcat拦截，这个时候Database RT能稳定，也有可能拦截的不够多，这个时候Database RT还是很高，但Tomcat RT更高，进入一种平衡状态

为什么有时候压测能过？

应该是数据分布比较巧，刚好压测流里面的数据分布没那么不均衡，没触发数据库雪崩

实战瓶颈定位-我的MySQL为什么压不上去--写场景

发表于 2023-06-30 更新于 2025-11-16 分类于 performance

实战瓶颈定位-我的MySQL为什么压不上去–写场景

纠结好久要不要写这篇，因为原因非常坑爹，你们基本不会遇到，想了很久觉得思路还是有些价值，所以还是写一下，我尽量简单

背景

继续上文 https://plantegg.github.io/2023/06/20/%E5%AE%9E%E6%88%98%E7%93%B6%E9%A2%88%E5%AE%9A%E4%BD%8D-%E6%88%91%E7%9A%84MySQL%E4%B8%BA%E4%BB%80%E4%B9%88%E5%8E%8B%E4%B8%8D%E4%B8%8A%E5%8E%BB/ ，纯读场景问题解决后，继续压纯写场景，比另外一套类似环境差了很多，大概是2折。

纯写肯定有预期：会有锁、磁盘瓶颈等问题

分析

先看top，结果很明显CPU上不去，并且有一个单核长时间 100%，然后 top -Hp mysqld-pid 展开所有线程，果然一直有一个线程几乎一直 100%，这就太明显了，这个线程遇到了瓶颈，导致整体上不去。

top -Hp mysqld-pid 看到165935 线程一直几乎是 100% 的CPU 状态

所以接下来要搞清楚这个线程在忙什么，刷盘？抢锁？

如果是Java应用就简单了，直接jstack一看就很清楚了，但是MySQLD没这么容易，另外环境里没有 pstack也没法安装，所以这条路走不通。

但是大概率能猜出来和磁盘有点关系，于是iostat -x -d 看看磁盘情况，好家伙果然ioutil 100%，磁盘 IO TPS 好几万。如下nvme0n1是MySQLD 使用的SSD 数据盘，vdb 是OS 系统盘

#iostat  -d vdb nvme0n1 3
Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
nvme0n1       45317.33        37.33    322150.67        112     966452
vdb               0.00         0.00         0.00          0          0

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
nvme0n1       45215.33        37.33    319228.00        112     957684
vdb               0.00         0.00         0.00          0          0

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
nvme0n1       45146.00        42.67    320677.33        128     962032
vdb               0.00         0.00         0.00          0          0

通过：iostat -x -d vdb nvme0n1 3 可以看到如下图

但这是不是正常情况不好说，于是找到家里同样的环境跑起来(没有单线程 100%问题，QPS 比问题环境高了 5倍)，于是也看一下 iostat 做一个对比，对比发现 ioutil 很小，然后磁盘 IO TPS 才我问题环境的30%，在QPS 5倍，IO TPS才 30%的情况下傻子也能看出来这两场景肯定不一样。一个QPS触发的IO TPS差了 15倍了。

不啰嗦，将问题环境的sysbench 脚本复制到正常环境，这下问题重现了，再diff看看两个脚本果然被人改了。问题环境使用的sysbench是别人装的，经过分析后发现里面被改动过一些东西。

之所以一直没有怀疑 sysbench 的问题，也有之前测试只读场景的时候符合预期，所以忽视了sysbench的差异。

这让我想起贝尔实验室Ken Thompson’s “cc hack” 的八卦(有兴趣的同学可以自行查证一下)：

当年在贝尔实验室，人们都用Unix系统，但是只有Ken可以绕过密码直接登录，让其他人百思不得其解。按理说整个Unix系统是开源的，很多人检查了系统代码，尤其是登录部分，并没有发现任何漏洞或者后门。

Ken的同事们不断重新编译Unix，但是Ken依旧如幽灵一般来去自如。

有人怀疑编译Unix的编译器里面有代码，但是当他们反复检查编译器源码，甚至重新编译c编译器后，依旧没有任何发现。

多年后，在Turing Award Lecture中，Ken终于道出了事情真相，登录源码和编译器源码都是干净的。事实上，这个幽灵般的木马在编译器的可执行文件中。

总结

这里的思路是：单线程100%->磁盘IO TPS非常高->和正常环境对比(常用手段，也要运气好有两个环境可以对比)->一个QPS 对应的IO TPS差异巨大->压测脚本问题

这算是个坑爹的小问题，大家也不会碰到，比网络限速难查多了，网络限速那里我们有放之四海而皆准的 RT 逻辑+抓包，所以很好定位。但是查证分析过程我觉得有一定的参考性，所以记录下。

如果MySQLD能提供一个内部任何一个操作的时间就好了，实际很难实现。当然通过火焰图去看异常偏高的调用是另外一个方向。

跨网络我们有抓包很好界定，但是问题到进程内部的时候反而没了抓包这种一锤定影的工具了

等额本息和等额本金以及提前还贷误区

发表于 2023-06-30 更新于 2025-11-16 分类于技巧

等额本息和等额本金以及提前还贷误区

1 等额本金和等额本息的差异

没有差异。等额本金=等额本息+每月提前还贷一点点()

2 为什么等额本金总利息少

因为每个月等额本金还款多，第一个月后欠本金少了，后面每个月都是这样，所还本金更多，最终总利息自然更少

其实可以用极限思维来分析他们的差异：假设等额本息和等额本金都借100万，周期一个月(没看错，一个月还清，极限假设)，所以一个月后他们还钱一样多！所以这个时候没有任何区别；现在继续假设，假如还款周期是2个月，那么等额本金在第一个月还钱多，导致等额本金在第二个月的时候欠钱少了，到第二个月月底还清所有欠款的时候利息要少(本金少了)——这才是他们的差异，所以是没区别的。等额本金这两个月相当于欠了银行150万一个月(第一个月欠100万，第二个月欠50万) 应还利息就是150万乘以月利率；等额本息相当于欠了银行 151万（第一个月欠100万，第二个月51万，因为第一个月还钱的时候只还了49万本金），所以应还利息就是 151万乘以月利率；欠得多利息就多天经地义这里没有投机、没有人吃亏

再或者换个思路：第一个月借100万，月底都还清，此时利息一样多；然后再借出来99.X万，这时等额本金借得少这个X更小，所以从第二个月开始等额本金还的利息少，归根结底换利息少是因为借得少(即现实中的还本金多)

把上面的极限思维图形化就是下图中的灰色部分面积代表你的欠款(每个月的欠款累加)，等额本息的方式欠得多，自然利息多：

3 为什么总有等额本金划得来的说法

同样贷款金额下等额本金总还款额少，也就是总利息少，所以给了很多人划得来的感觉，或者给人感觉利息便宜。其实这都是错的，解释如上第二个问题

4 利息的计算方式

利息每个月计算一次，这个月所欠本金*月利率。所以利息只和你欠钱多少有关（我们假设所有人的利率都一样）。每个月的月供，都是先还掉这个月的利息，多余的再还本金

等额本金因为每个月还掉的本金多，所以计算下来每个月的利息更少

5 如何理解等额本金和等额本息

同样贷款额+利率的话等额本金开始还款一定比等额本息要多一些，那么你可以把等额本金分成两块，一块和等额本息一样，多出来的部分你把他看成这个月额外做了一次提前还款。你提前还款了后面的总利息自然也会更少一些，然后每个月的等额本息也会减少，以此类推每个月都是这样额外做一次提前还款直到最后一个月。

总结：等额本金=等额本息+提前还贷

额本金开始还款一定比等额本息要多一些，可以把等额本金分成两块，一块和等额本息一样，多出来的部分把他看成这个月额外做了一次提前还款。提前还款后总利息也会更少一些，然后每个月的等额本息也会减少，以此类推每个月都是这样额外做一次提前还款直到最后一个月。

6 提前还款划不划得来

钱在你手里没法赚到比利息更高的收益的话(99%的人属于这种)提前还贷划得来，之所以以前不建议大家提前还贷，是因为以前普遍涨薪快、通胀厉害、房价涨得块，把钱留出来继续买二套、三套更赚钱。另外钱留在手里会有主动权和应急方便

7 提前还贷会多付利息吗？

不会，见第四条利息的计算方式。担心提前还贷的时候这比贷款把后面10年的利息收走了的是脑子不好使的人。但有些银行提前还贷会有违约金

8 为什么等额本金和等额本息给了这么多人错觉

从知识的第一性出发，他们都没理解第4条，受社会普遍意识影响都预先留下了错误经验。本质就是利息只和贷款额、利率有关。

9 贷款30年和10年利率有差异吗？

没有

10贷款30年，还了6年了，然后一次还清所有欠款会多还利息吗？

不会，你前6年只是还了前6年的利息，没为之后的6年多付一分利息

11 那为什么利率不变我每个月利息越来越少

因为你欠的钱越来越少了，不是你提前还了利息，是你一直在还本金

12 网购分期合适吗？

大部分小贷公司的套路就是利用你每个月已经在还本金的差异，利息自然越来越少，然后计算一个大概5%的年息误导你，实际这种网购分期的实际利息要是他计算的2倍……好好想想

等额本金、本息都搞不清楚的人就不要去搞分期了，你的脑瓜子在这方面不好使。

聪明人只看第4条就能在大脑里得出所有结论，普通人除了要有第4条还需要去看每个月的还款额、还款额里面的本金、还款额里的利息等实践输入才能理解这个问题，这就是差异

https://zhuanlan.zhihu.com/p/161405128

提前还贷

要不要提前还贷

要

提前还贷划得来吗？

划不划得来要看这笔钱在你手里能否获得比房贷利息更高的收入以及你对流动资金的需要。其实万一有个啥事也可以走消费贷啥的，现在利息都很低

等额本息比等额本金提前还贷更划得来？

一样的，你这个问题等价于我欠100万，老婆欠50万，所以我提前还贷比朋友合算吗？显然你两谁提前还贷合算只和你两的贷款利率是否有差别

等额本息和等额本金利率一样的，所以没有差别

20年的房贷我已经还了15年了是不是不值得提前还贷了？

错误！利率还是那个利率，跟你还剩10年和还剩5年没关系，提前还贷都是等价的。记住有闲钱就提前还

问题的本质

搞清楚每个月的利息怎么计算出来的利息=欠款额*月利率，月供都是把本月利息还掉多出来的还本金，也就是每个月欠款额会变少

总结

每个领域都有一些核心知识点代表着这些问题的本质，你只有把核心知识点或者说问题本质搞懂了才能化繁为简、不被忽悠！

那贷款这里的本质是什么？就是利息只和你每个月欠款以及利率有关！这简直是屁话，太简单了，但你不能理解他，就容易被套上等额本金、等额本息、提前还贷的外壳给忽悠了。

再或者说这里的本质就是：你去搞清楚每个月的还款是怎么计算的。月供=本月所欠X利率+本月还掉的本金这是个核心公式，差别在每个月还掉的本金不一样！

就这样吧该懂的也该看懂了，看不懂的大概怎么样也看不懂！只能说是蠢，这些人肯定理科不好、逻辑不行，必定做不了程序员。

比如网上流传的如图总结的所有结论都是错的：

实战瓶颈定位-我的MySQL为什么压不上去

发表于 2023-06-20 更新于 2025-11-29 分类于 performance

实战瓶颈定位-我的MySQL为什么压不上去

背景

环境两台云上相同 128C的EC2(有点豪)，一台当压力机一台当服务器，用Sysbench测试MySQL纯读场景，不存在任何修改，也就几乎没有锁

#uname -r
5.10.84.aarch64

Server:            MySQL
Server version:        8.0.18 Source distribution

EC2机器128核，故意只给MySQLD绑定了其中的24Core，网卡32队列

#ethtool -l eth0
Channel parameters for eth0:
Pre-set maximums:
RX:        0
TX:        0
Other:        0
Combined:    32
Current hardware settings:
RX:        0
TX:        0
Other:        0
Combined:    32

压测过程

走同一交换机内网IP压MySQL跑不满CPU，跑压力和不跑压力时ping rtt 分别是 0.859/0.053(RTT 有增加–注意点), 此时TPS：119956.67 1000并发 RT 8.33

下图是压测时 htop 看到的MySQLD 所在EC2的 CPU使用情况，右边65-88是MySQLD进程(绿色表示us, 红色表示sys+si CPU)

用top查看详细的每个 core 使用(只展示MySQLD使用的24core ，top 然后按1–还可以试试2/3，有惊喜)

top - 13:49:55 up 160 days, 18:10,  3 users,  load average: 555.26, 720.12, 462.21
Tasks: 1065 total,   1 running, 499 sleeping,   0 stopped,   0 zombie
%Node1 : 10.1 us,  5.3 sy,  0.0 ni, 83.3 id,  0.0 wa,  0.0 hi,  1.3 si,  0.0 st
%Cpu64 : 29.3 us, 16.5 sy,  0.0 ni, 54.2 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu65 : 37.0 us, 18.5 sy,  0.0 ni, 26.9 id,  0.0 wa,  0.0 hi, 17.5 si,  0.0 st
%Cpu66 : 34.2 us, 17.8 sy,  0.0 ni, 47.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu67 : 26.0 us, 15.1 sy,  0.0 ni, 58.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu68 : 26.1 us, 14.8 sy,  0.0 ni, 59.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu69 : 27.2 us, 13.8 sy,  0.0 ni, 59.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu70 : 25.7 us, 11.8 sy,  0.0 ni, 62.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu71 : 18.3 us, 10.6 sy,  0.0 ni, 71.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu72 : 29.7 us, 12.6 sy,  0.0 ni, 57.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu73 : 21.2 us, 13.0 sy,  0.0 ni, 65.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu74 : 18.9 us, 10.8 sy,  0.0 ni, 70.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu75 : 28.9 us, 15.1 sy,  0.0 ni, 36.1 id,  0.0 wa,  0.0 hi, 19.9 si,  0.0 st
%Cpu76 : 30.3 us, 15.5 sy,  0.0 ni, 54.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu77 : 25.1 us, 13.2 sy,  0.0 ni, 61.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu78 : 18.2 us, 10.3 sy,  0.0 ni, 71.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu79 : 14.9 us,  8.8 sy,  0.0 ni, 76.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu80 : 23.4 us, 12.2 sy,  0.0 ni, 64.4 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu81 : 35.3 us, 17.6 sy,  0.0 ni, 30.2 id,  0.0 wa,  0.0 hi, 16.9 si,  0.0 st
%Cpu82 : 28.2 us, 16.1 sy,  0.0 ni, 55.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu83 : 37.5 us, 16.9 sy,  0.0 ni, 27.0 id,  0.0 wa,  0.0 hi, 18.6 si,  0.0 st
%Cpu84 : 35.4 us, 18.5 sy,  0.0 ni, 46.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu85 : 27.9 us, 16.8 sy,  0.0 ni, 55.2 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu86 : 28.2 us, 13.7 sy,  0.0 ni, 58.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu87 : 27.2 us, 11.0 sy,  0.0 ni, 61.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu88 :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

继续尝试用2000并发，TPS、CPU、ping rtt都和1000并发没有区别，当然按照我们以前QPS、RT理论2000并发的时候RT应该翻倍，实际确实是16.66，所以这里的问题就是翻倍的 RT哪里来的瓶颈就在哪里。

也试过用两个压力机每个压力机分别用1000并发同时压，QPS一样稳定——目的快速排除压力端、链路上有瓶颈。

写到这里RT 刚好翻倍16.66=8.33*2 数字精准得好像编故事一样，不得不贴一下原始数据证实一下：

1000 并发和2000并发时的ping RTT对比(ttl 64说明内网直达)

#ping mysqld27
PING yt27 (mysqld217) 56(84) bytes of data.
---以下是2000并发
64 bytes from mysqld27 (mysqld217): icmp_seq=1 ttl=64 time=0.867 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=2 ttl=64 time=0.952 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=3 ttl=64 time=0.849 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=4 ttl=64 time=0.857 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=5 ttl=64 time=0.987 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=6 ttl=64 time=0.860 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=7 ttl=64 time=0.909 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=8 ttl=64 time=0.875 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=9 ttl=64 time=0.979 ms  
---终止压测，无无压力的rtt
64 bytes from mysqld27 (mysqld217): icmp_seq=10 ttl=64 time=0.104 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=11 ttl=64 time=0.079 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=12 ttl=64 time=0.075 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=13 ttl=64 time=0.075 ms 
64 bytes from mysqld27 (mysqld217): icmp_seq=14 ttl=64 time=0.074 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=15 ttl=64 time=0.078 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=16 ttl=64 time=0.075 ms
---开启1000并发时的rtt
64 bytes from mysqld27 (mysqld217): icmp_seq=17 ttl=64 time=0.872 ms 
64 bytes from mysqld27 (mysqld217): icmp_seq=18 ttl=64 time=0.969 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=19 ttl=64 time=0.862 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=20 ttl=64 time=0.877 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=21 ttl=64 time=0.961 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=22 ttl=64 time=0.828 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=23 ttl=64 time=0.098 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=24 ttl=64 time=0.083 ms

抓包证明

在抓保证明前推荐一个工具快速绕过抓包(原理也是通过pcap lib去分析网络包，tcpdump也会调用pcap lib)

监控tcprstat，从网络层抓包来对比两个并发下的RT：

//./tcprstat -p 3307 -t 1 -n 0 -l 10.9.10.22 -f "%T\t\t%n\t\t%a\t%h\t%S\t%C\t%95M\t%95a\t%95S\t%99M\t%99a\t%99S\n"
#tcprstat -p 14822 -t 1 -n 0 -l mysqld217 -f "%T\t\t%n\t\t%a\n"
timestamp        count        avg
1683785023        50743        626
1683785024        120004        100
1683785025        120051        103
1683785026        120042        102
1683785027        120031        103
1683785028        120034        104
1683785029        120034        104
1683785030         55209        103    ---以上是2000并发
1683785038        0        0
1683785039        0        0
1683785040         55224        614    ---以下是1000并发
1683785041        119998        104
1683785042        120039        105
1683785043        120039        105
1683785044        120026        107
1683785045        120039        108
1683785046        120047        108
1683785047        120037        108
1683785048        120032        108
1683785049        120041        108

也就是网卡层面确认了压不上去瓶颈不在MySQL 上，加并发后网卡的RT没变(网卡RT包含MySQLD RT)，因为ping RTT 在1000和2000并发也没有差异，推测交换机不是瓶颈，大概率出网卡的虚拟层面

在客户端的机器上抓包，上面我们说过了1000并发的RT是8.33毫秒：

注意上图，我把RT排序了，明显看到5ms到17ms 中间没有这个RT范围的包，但是有很多25ms的RT，平均下来确实是8.33毫秒，留下一个疑问：RT分布不符合正态，而且中间有很大一段范围镂空了！这是不应该的。

同样我们再到MySQLD 所在机器抓包分析(注：正常路径先抓MySQLD上的包就行了)：

同样是对RT 排序了，但是慢的RT都是对端发慢了(注意最右边的select， MySQL相应是 response)，同样对这个抓包求平均时间就是tcprstat 看到的103微秒，也就是0.1毫秒。如下图红框是请求，请求的间隔是11毫米，绿框是响应，响应的间隔都是0.2ms不到

同样在2000并发时也对MySQLD所在网卡抓包对比，response 的RT 没有变化，从这里可以看出瓶颈点在sysbench 和 MySQLD 的网卡之间的链路上，似乎有限流、管控

快速验证

到这里我们已经找到了有力的证据，RT是在离开MySQLD网卡后增加上去的，先验证下走走本机127.0.0.1快速压一把，让sysbench 跑在0-7 core上，这时可以看到MySQL跑满了CPU，下图左边1-8核是压力进程，右边65-88是业务进程，TPS：239969.91 1000并发 RT 4.16

htop状态：

各CPU 详细分析：

us MySQL解析SQL、处理查询
si 网络软中断
sy OS 的sys API 消耗，一般用户进程会调用系统 API, 比如读写文件、分配内存、网络访问等

//sysbench
top - 13:44:27 up 160 days, 18:04,  3 users,  load average: 792.17, 619.09, 311.58
Tasks: 1073 total,   1 running, 500 sleeping,   0 stopped,   0 zombie
%Cpu0  : 14.0 us, 29.1 sy,  0.0 ni, 33.3 id,  0.0 wa,  0.0 hi, 23.5 si,  0.0 st
%Cpu1  : 12.5 us, 33.0 sy,  0.0 ni, 33.7 id,  0.0 wa,  0.0 hi, 20.8 si,  0.0 st
%Cpu2  : 11.2 us, 32.7 sy,  0.0 ni, 34.2 id,  0.0 wa,  0.0 hi, 21.9 si,  0.0 st
%Cpu3  : 13.4 us, 31.2 sy,  0.0 ni, 34.4 id,  0.0 wa,  0.0 hi, 21.0 si,  0.0 st
%Cpu4  : 12.1 us, 31.3 sy,  0.0 ni, 34.2 id,  0.0 wa,  0.0 hi, 22.4 si,  0.0 st
%Cpu5  : 10.5 us, 31.8 sy,  0.0 ni, 33.6 id,  0.0 wa,  0.0 hi, 24.1 si,  0.0 st
%Cpu6  : 12.9 us, 31.3 sy,  0.0 ni, 34.2 id,  0.0 wa,  0.0 hi, 21.6 si,  0.0 st
%Cpu7  : 12.3 us, 31.4 sy,  0.0 ni, 34.3 id,  0.0 wa,  0.0 hi, 22.0 si,  0.0 st
%Cpu8  :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

//MySQLD
Tasks: 1073 total,   1 running, 505 sleeping,   0 stopped,   1 zombie
%Node1 : 22.6 us, 10.1 sy,  0.0 ni, 62.4 id,  0.0 wa,  0.0 hi,  4.8 si,  0.0 st
%Cpu64 : 57.9 us, 29.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.9 si,  0.0 st
%Cpu65 : 60.3 us, 26.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 13.6 si,  0.0 st
%Cpu66 : 57.6 us, 28.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 14.2 si,  0.0 st
%Cpu67 : 60.9 us, 25.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 13.6 si,  0.0 st
%Cpu68 : 59.9 us, 26.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 13.9 si,  0.0 st
%Cpu69 : 57.9 us, 27.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 14.6 si,  0.0 st
%Cpu70 : 61.3 us, 26.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.6 si,  0.0 st
%Cpu71 : 64.0 us, 23.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.5 si,  0.0 st
%Cpu72 : 61.3 us, 26.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 11.9 si,  0.0 st
%Cpu73 : 63.0 us, 22.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 14.2 si,  0.0 st
%Cpu74 : 61.4 us, 27.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 11.2 si,  0.0 st
%Cpu75 : 63.9 us, 26.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  9.6 si,  0.0 st
%Cpu76 : 61.3 us, 27.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 11.6 si,  0.0 st
%Cpu77 : 55.0 us, 30.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 14.6 si,  0.0 st
%Cpu78 : 60.9 us, 26.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.3 si,  0.0 st
%Cpu79 : 58.4 us, 26.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 14.9 si,  0.0 st
%Cpu80 : 58.7 us, 29.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.2 si,  0.0 st
%Cpu81 : 62.6 us, 27.2 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 10.3 si,  0.0 st
%Cpu82 : 61.9 us, 25.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.6 si,  0.0 st
%Cpu83 : 58.7 us, 27.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 13.9 si,  0.0 st
%Cpu84 : 59.4 us, 27.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.9 si,  0.0 st
%Cpu85 : 58.9 us, 28.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 12.6 si,  0.0 st
%Cpu86 : 58.4 us, 28.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 13.2 si,  0.0 st
%Cpu87 : 61.1 us, 27.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 11.6 si,  0.0 st

就以上sysbench VS MySQLD 的CPU 消耗来看，因为sysbench 处理逻辑简单，就是发SQL给MySQLD，所以 sysbench自身US很少，大部分都是调用OS的网络操作，而MySQLD有 60% CPU用于US，也就是自身业务逻辑，MySQLD收到SQL要做SQL解析，要去查找数据，这些都是用户态消耗，找到数据后走网络发给Sysbench，这部分是sy

到这里可以拿着证据去VIP通道(土豪+专业的客户得有VIP通道)找做网络管控的了，不会再有撕逼和甩锅

sysbench 结果不是正态分布

把所有请求RT 分布进行图形化，此时平均 RT 8.33，理论上是一个正态分布，下图是有限速时：

 3.615 |                                         2177
 3.681 |**                                       14738
 3.748 |*******                                  55690
 3.816 |*************                            109713
 3.885 |***************                          121830
 3.956 |***************                          124851
 4.028 |*******************                      154927
 4.101 |***********************                  188826
 4.176 |***************************              226206
 4.252 |************************************     302617
 4.329 |**************************************** 333310  //这里以4.329为中心符合正态
 4.407 |*******************************          257048
 4.487 |********************                     163100
 4.569 |************                             101785
 4.652 |********                                 63871
 4.737 |*****                                    43998
 4.823 |*****                                    40854
 4.910 |*****                                    42189
 4.999 |*****                                    41182
 5.090 |****                                     35652
 5.183 |****                                     30343
 5.277 |***                                      28573
 5.373 |***                                      24763
 5.470 |***                                      22210
 5.570 |***                                      21808
 5.671 |***                                      25606
 5.774 |***                                      26994
 5.879 |***                                      24672
 5.986 |***                                      22087
 6.095 |**                                       18466
 6.205 |**                                       14822
 6.318 |**                                       13688
 6.433 |**                                       15381
 6.550 |**                                       13573
 6.669 |*                                        11325
 6.790 |*                                        9442
 6.913 |*                                        7412
 省略一大堆
20.736 |*                                        11407
21.112 |*                                        9755
21.496 |*                                        8957
21.886 |*                                        9434
22.284 |*                                        9715
22.689 |**                                       12774
23.101 |**                                       17000
23.521 |***                                      22937
23.948 |*****                                    40401
24.384 |********                                 65370
24.827 |**********                               82186
25.278 |**********                               85505
25.737 |***********                              94347 //以25.7附近大概又是一个新正态
26.205 |**********                               82958
26.681 |****                                     30760
27.165 |                                         2222
27.659 |                                         69
28.162 |                                         16
28.673 |                                         15
29.194 |                                         20
29.725 |                                         17

去掉限速后平均 RT 3.26(比下图中大概的中位数2.71大了不少) 完美正态

1.857 |**                                       19894
1.891 |***                                      23569
1.925 |***                                      27912
1.960 |****                                     33720
1.996 |****                                     39892
2.032 |*****                                    48289
2.069 |******                                   57649
2.106 |********                                 69437
2.145 |*********                                83611
2.184 |***********                              99507
2.223 |*************                            119275
2.264 |****************                         141013
2.305 |*******************                      165450
2.347 |**********************                   191778
2.389 |*************************                219706
2.433 |****************************             250885
2.477 |*******************************          278379
2.522 |**********************************       303931
2.568 |*************************************    325777
2.615 |***************************************  342948
2.662 |**************************************** 354029
2.710 |**************************************** 356295
2.760 |**************************************** 353068
2.810 |**************************************   341345
2.861 |************************************     324600
2.913 |**********************************       303525
2.966 |*******************************          280221
3.020 |*****************************            255042
3.075 |**************************               230861
3.130 |***********************                  206909
3.187 |*********************                    184616
3.245 |*******************                      164903
3.304 |****************                         146199
3.364 |***************                          131427
3.425 |*************                            117059
3.488 |************                             104954
3.551 |***********                              94404
3.615 |*********                                83739
3.681 |********                                 75705
3.748 |********                                 67944
3.816 |*******                                  60727
3.885 |******                                   53757
3.956 |*****                                    47053
4.028 |*****                                    42130
4.101 |****                                     38069
4.176 |****                                     33666
4.252 |***                                      30048
4.329 |***                                      26923
4.407 |***                                      23886
4.487 |**                                       21615
4.569 |**                                       19897
4.652 |**                                       18458
4.737 |**                                       17729
4.823 |**                                       17041
4.910 |**                                       16011
4.999 |**                                       16099
5.090 |**                                       16090
5.183 |**                                       16393
5.277 |**                                       16729
5.373 |**                                       17412

用其他网络业务验证

先测试一下网络下载时的ping：

--无流量
64 bytes from 172.16.0.205: icmp_seq=11 ttl=64 time=0.075 ms
64 bytes from 172.16.0.205: icmp_seq=12 ttl=64 time=0.080 ms
--从有网络限速的机器下载，带宽100MB
64 bytes from 172.16.0.205: icmp_seq=13 ttl=64 time=0.738 ms 
64 bytes from 172.16.0.205: icmp_seq=14 ttl=64 time=0.873 ms
64 bytes from 172.16.0.205: icmp_seq=15 ttl=64 time=0.993 ms
64 bytes from 172.16.0.205: icmp_seq=16 ttl=64 time=0.859 ms
64 bytes from 172.16.0.205: icmp_seq=17 ttl=64 time=0.892 ms
64 bytes from 172.16.0.205: icmp_seq=18 ttl=64 time=0.972 ms
64 bytes from 172.16.0.205: icmp_seq=19 ttl=64 time=1.05 ms
64 bytes from 172.16.0.205: icmp_seq=20 ttl=64 time=0.973 ms
64 bytes from 172.16.0.205: icmp_seq=21 ttl=64 time=0.997 ms
64 bytes from 172.16.0.205: icmp_seq=22 ttl=64 time=0.915 ms
64 bytes from 172.16.0.205: icmp_seq=23 ttl=64 time=0.892 ms
64 bytes from 172.16.0.205: icmp_seq=24 ttl=64 time=0.960 ms
64 bytes from 172.16.0.205: icmp_seq=25 ttl=64 time=1.05 ms
64 bytes from 172.16.0.205: icmp_seq=26 ttl=64 time=0.089 ms
64 bytes from 172.16.0.205: icmp_seq=27 ttl=64 time=0.097 ms
64 bytes from 172.16.0.205: icmp_seq=28 ttl=64 time=0.081 ms 
--从没有网络限速的机器下载，带宽1000MB
64 bytes from 172.16.0.205: icmp_seq=29 ttl=64 time=0.078 ms
64 bytes from 172.16.0.205: icmp_seq=30 ttl=64 time=0.077 ms
64 bytes from 172.16.0.205: icmp_seq=31 ttl=64 time=0.073 ms
64 bytes from 172.16.0.205: icmp_seq=32 ttl=64 time=0.072 ms
64 bytes from 172.16.0.205: icmp_seq=33 ttl=64 time=0.079 ms
64 bytes from 172.16.0.205: icmp_seq=34 ttl=64 time=0.074 ms
64 bytes from 172.16.0.205: icmp_seq=35 ttl=64 time=0.080 ms
64 bytes from 172.16.0.205: icmp_seq=36 ttl=64 time=0.077 ms

有限速方向，尝试了BBR和cubic 拥塞算法：

#tcpperf -c 172.16.0.205 -t 100
Connected mysqld217:51254 -> 172.16.0.205:2009, congestion control: cubic
Time (s)  Throughput   Bitrate    Cwnd    Rwnd  sndbuf  ssthresh  Retr  CA  Pacing  rtt/var
  0.000s   0.00kB/s   0.00kbps  14.3Ki  41.3Ki  85.0Ki    2048Mi     0   0  65.2Mi  427us/213
  1.029s    122MB/s    975Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/8
  2.005s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/10
  3.010s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/17
  4.016s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/13
  5.022s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/14
  6.028s    105MB/s    842Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/17
  7.003s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/15
  8.009s    105MB/s    843Mbps  1595Ki  1595Ki  9512Ki     576Ki     0   0   123Mi  15.2ms/13
 #tcpperf -c 172.16.0.205 -t 100
Connected mysqld217:51932 -> 172.16.0.205:2009, congestion control: bbr
Time (s)  Throughput   Bitrate    Cwnd    Rwnd  sndbuf  ssthresh  Retr  CA  Pacing  rtt/var
  0.000s   0.00kB/s   0.00kbps  14.3Ki  41.3Ki   128Ki    2048Mi     0   0  98.0Mi  406us/203
  1.011s    120MB/s    957Mbps   271Ki  2281Ki  10.4Mi     560Ki  2244   0   108Mi  2427us/11
  2.033s    104MB/s    831Mbps   271Ki  2281Ki  10.4Mi     560Ki  1056   0   109Mi  2417us/18
  3.021s    104MB/s    830Mbps   274Ki  2281Ki  10.4Mi     560Ki  1056   0   109Mi  2428us/18
  4.014s    103MB/s    827Mbps   271Ki  2281Ki  10.4Mi     560Ki  1452   0   108Mi  2423us/19
  5.031s    104MB/s    835Mbps   274Ki  2281Ki  10.4Mi     560Ki   660   0  80.2Mi  2435us/22
  6.033s    102MB/s    818Mbps   271Ki  2272Ki  10.4Mi     560Ki  2112   0   109Mi  2426us/17
  7.030s    103MB/s    823Mbps   274Ki  2281Ki  10.4Mi     560Ki  1716   0   117Mi  2430us/18
  8.023s    103MB/s    826Mbps   274Ki  2281Ki  10.4Mi     560Ki  1452   0   109Mi  2428us/20
  9.016s    103MB/s    827Mbps   271Ki  2281Ki  10.4Mi     560Ki  1452   0   108Mi  2423us/15

跑tcpperf触发限速时的监控(上下两个窗口是同一台机器)，红色是丢包率挺高的，绿色丢包就没了，应该是拥塞算法和限速管控达成了平衡

反过来限速被我去掉了(限速可以进出双向单独控制)

#tcpperf -c mysqld217 -t 1000
Connected 172.16.0.205:32186 -> mysqld217:2009, congestion control: bbr
Time (s)  Throughput   Bitrate    Cwnd    Rwnd  sndbuf  ssthresh  Retr  CA  Pacing  rtt/var
  0.000s   0.00kB/s   0.00kbps  14.3Ki  41.3Ki   128Ki    2048Mi     0   0   100Mi  397us/198
  1.001s   1107MB/s   8859Mbps   471Ki   985Ki  4641Ki     277Ki     0   0  1083Mi  390us/22
  2.001s   1103MB/s   8823Mbps   465Ki   985Ki  4641Ki     277Ki     0   0  1089Mi  393us/16
  3.000s   1111MB/s   8892Mbps   465Ki   985Ki  4641Ki     277Ki     0   0  1072Mi  403us/25
  4.000s   1099MB/s   8789Mbps   459Ki   985Ki  4794Ki     277Ki     0   0   799Mi  399us/18
  5.001s   1098MB/s   8786Mbps   459Ki   985Ki  4794Ki     277Ki     0   0  1066Mi  387us/12
  6.000s   1100MB/s   8799Mbps   462Ki   974Ki  4794Ki     277Ki     0   0  1069Mi  399us/16
  7.001s   1135MB/s   9078Mbps   453Ki   985Ki  4794Ki     277Ki     0   0  1059Mi  377us/19

查看限速配置如下：

{txcmbps:844.000, txckpps:120.000}

//限速解释
0-31 我猜这是网卡队列(可以修改);
txcmbps:844.000 105.5MB/s     每秒带宽105.5MB
txckpps:120.000 120K packet/s 每秒12万网络包

sysbench(主键查询-小包) 12万QPS 正好命中 txckpps:120，tcpperf (大包)稳定的105MB带宽命中txcmbps:844

去掉后长这样：

#ovsctl -n set_out_pps -v -1  //把pps限制为-1==不限制
#ovsctl set_tx -p {} -r -1;   //带宽不限制

{vport:  2 {map:  0, prio:L, weight:   0}meter: {-}queue: [  0- 31L]}

对这块网络管控感兴趣可以去了解一下 ovs 这个开源项目(open virtual switch)

去掉网卡限速后的结果

实际结构如下：

放开所有网络控制后，1000并发压力 30万QPS，RT 3.28，此时从sysbench 以及空闲机器ping MySQLD机器的 RTT和没压力基本一致

top状态：

%Node1 : 23.4 us, 12.3 sy,  0.0 ni, 61.4 id,  0.0 wa,  0.0 hi,  3.0 si,  0.0 st
%Cpu64 : 63.2 us, 36.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu65 : 44.4 us, 21.9 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 33.8 si,  0.0 st
%Cpu66 : 66.6 us, 33.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu67 : 63.4 us, 36.6 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu68 : 64.2 us, 35.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu69 : 64.9 us, 35.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu70 : 66.6 us, 33.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu71 : 65.3 us, 34.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu72 : 67.7 us, 32.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu73 : 63.6 us, 36.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu74 : 66.7 us, 33.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu75 : 42.4 us, 19.9 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 37.7 si,  0.0 st
%Cpu76 : 63.9 us, 36.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu77 : 67.0 us, 33.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu78 : 68.3 us, 31.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu79 : 64.9 us, 35.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu80 : 65.2 us, 34.8 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu81 : 44.4 us, 21.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 34.1 si,  0.0 st
%Cpu82 : 63.9 us, 36.1 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu83 : 44.2 us, 23.4 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi, 32.3 si,  0.0 st
%Cpu84 : 65.7 us, 34.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu85 : 68.3 us, 31.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu86 : 67.5 us, 32.5 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu87 : 62.4 us, 37.6 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu88 :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st

小思考：

我们中间尝试走本机127.0.0.1 压测时QPS 是24万，比跨机器压的 30万打了8折，想想为什么？网络延时消耗完全没影响？

总结

简单可复制的证明办法：抓包，快速撕逼和分析

肯定有很多人想到：内存、磁盘、线程池、队列、网络等等原因，但是这些所有原因有一个共同的爹：RT，所有这些影响因素最后体现出来就是RT 高了，你CPU资源不够、内存慢最后总表现就是在客户端看来你的 RT 太高。

所以我们去掉这些复杂因素先在MySQLD所在EC2 的网卡上抓一个包看看RT，再对比一下1000/2000并发时抓包看到的 RT 有没有升高，如果有升高说明问题在MySQLD这端(含OS、MySQLD的问题)，如果 RT 不变那么问题不在MySQLD这端，并且从EC2网卡出去都是很快的，那么问题只能是在路上或者客户端的sysbench自己慢了。

这是我们星球里说的无招胜有招–抓包大法，扯皮过程中我还没见过几个不认网络抓包的，也有那么一两个扯上是不是网卡驱动有问题，我的代码不会有问题

两个限速条件：pps 120k(每秒最多12万网络包)，带宽 844mbps=105.5MB/s

Sysbench 查询都是小包，触发第一个条件，tcpperf触发第二个条件

ping ping神功失效了吗？也没有，我后来又测试了100、200并发，rtt 0.2ms和0.4ms，也就是说随着并发的增加rtt 增加到0.8ms后就不再增加了。上来1000并发已经到了天花板

64 bytes from polardbxyt27 (mysqld217): icmp_seq=159 ttl=64 time=0.226 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=160 ttl=64 time=0.334 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=161 ttl=64 time=0.336 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=162 ttl=64 time=0.213 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=163 ttl=64 time=0.104 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=164 ttl=64 time=0.096 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=165 ttl=64 time=0.101 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=166 ttl=64 time=0.116 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=167 ttl=64 time=0.104 ms--以上 100并发，QPS 119K
64 bytes from polardbxyt27 (mysqld217): icmp_seq=168 ttl=64 time=0.093 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=169 ttl=64 time=0.088 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=170 ttl=64 time=0.405 ms--以下 200并发，QPS 119K
64 bytes from polardbxyt27 (mysqld217): icmp_seq=171 ttl=64 time=0.419 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=172 ttl=64 time=0.386 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=173 ttl=64 time=0.474 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=174 ttl=64 time=0.462 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=175 ttl=64 time=0.410 ms

Nginx reuseport 导致偶发性卡顿

发表于 2023-06-08 更新于 2025-11-16 分类于 performance

Nginx reuseport 导致偶发性卡顿

by @橘橘球

背景

从2018年开始，我们有个业务陆续接到反馈 Nginx 线上集群经常出现不响应或者偶发性的“超慢”请求。这种卡顿每天都有少量出现。而只有多个集群中的一个出现，其他压力更大的集群皆未出现。
业务结构比较简单：LVS->Nginx->后端，如图

一些观察到的现象：

出问题前不久升级 Nginx 配置，打开了 reuseport 功能
在压力大的后端（upstream）服务环境不容易出现，后端压力轻对应的Nginx卡顿概率更高
关闭 reuseport 后问题少了很多
失败的请求响应时间都是 0ms（Nginx日志不靠谱了）
从 Nginx 日志上看，所有失败的健康检查请求都是0ms 的499 错误码（健康检查设置超时是2秒），但实际出问题的时候有5s-2分钟没有任何日志输出（Nginx卡了这么久）要么是Nginx卡住没去accept，要么是accept了没响应
所有超时来自同一个worker(一个Nginx服务一般按照机器核数开启多个worker)

并且已知，卡顿的原因是打开 reuseport 后，新进来的请求可以由内核 hash 派发给一个 Nginx woker ，避免了锁争抢以及惊群。但如果网络条件足够好，压力足够低，Nginx worker 一直来不及读完 receive buffer 中的内容时，就无法切换并处理其他的 request，于是在新请求的客户端会观测不间断的卡顿，而压力大的后端由于网络传输慢，经常卡顿，Nginx worker 反而有时间能处理别的请求。在调小 receive buffer 人为制造卡顿后该问题得以解决。

目标

由于所述场景比较复杂，缺乏直接证据，打算通过构造一个较简单的环境来复现这个问题，并且在这个过程中抓包、观测Nginx worker的具体行为，验证这个假设。

术语

快连接和慢连接

快连接：通常是传输时间短、传输量小的连接，耗时通常是ms级别
慢连接：通常是传输时间长、传输量大的连接，可以维持传输状态一段时间（如30s, 1min）

在本次场景复现过程中，这两种连接都是短连接，每次请求开始前都需要三次握手建立连接，结束后都需要四次挥手销毁连接

Epoll

Nginx使用了epoll模型，epoll 是多路复用的一种实现。在多路复用的场景下，一个task（process）会批量处理多个socket，哪个来了数据就去读那个。这就意味着要公平对待所有这些socket，不能阻塞在任何socket的”数据读”上，也就是说不能在阻塞模式下针对任何socket调用recv/recvfrom。

epoll 每次循环为O(1) 操作，循环前会得到一个就绪队列，其中包含所有已经准备好的 socket stream（有数据可读），不需要循环全部 socket stream 读取数据，在循环后会将被读取数据的 stream 重新放回睡眠队列。睡眠队列中的 socket stream 有数据可读时，再唤醒加入到就绪队列中。

epoll 伪代码（不包含唤醒、睡眠）

while(true) {  
    streamArr = getEpollReadyStream(); // 找到准备好的stream
    for(Stream i: streamArr) {         // 循环准备好的stream
        doSomething();
    }
}

reuseport与惊群

Nginx reuseport 选项解决惊群的问题：在 TCP 多进程/线程场景中（B 图），服务端如果所有新连接只保存在一个 listen socket 的全连接队列中，那么多个进程/线程去这个队列里获取（accept）新的连接，势必会出现多个进程/线程对一个公共资源的争抢，争抢过程中，大量资源的损耗，也就会发生惊群现象。

而开启reuseport后（C 图)，有多个 listener 共同 bind/listen 相同的 IP/PORT，也就是说每个进程/线程有一个独立的 listener，相当于每个进程/线程独享一个 listener 的全连接队列，新的连接请求由内核hash分配，不需要多个进程/线程竞争某个公共资源，能充分利用多核，减少竞争的资源消耗，效率自然提高了。

但同时也是由于这个分配机制，避免了上下文切换，在服务压力不大，网络情况足够好的情况下，进程/线程更有可能专注于持续读取某个慢连接数据而忽视快连接建立的请求，从而造成快连接方卡顿。

复现过程

思路

整体的架构是N个client->1个Nginx->N个server。因为卡顿原因和reuseport机制有关，和server数量无关，server数量设为任意数字都能复现，这里为了方便设成1。client数量设为2，为了将快连接和慢连接区分开便于抓包观测
用慢连接制造卡顿环境，用快连接观测卡顿。在快连接客户端进行观测和抓包
进程数量要足够少，使得同一个 worker 有几率分配到多个连接 worker_processes 2
连接数目要足够多，慢连接数目>=进程数量，使得快连接在分配时，有一定概率分配到一个正在处理慢连接的worker上
reuseport: 这个配置要开启，卡顿现象才能观测到。listen 8000 reuseport

环境

linux kernal version: 6.1  
linux image: amazon/al2023-ami-2023.0.20230419.0-kernel-6.1-x86_64  
instance type:  
1X AWS t2.micro (1 vCPU, 1GiB RAM) – Nginx client(fast request)  
3X AWS t3.micro (2 vCPU, 1GiB RAM) – Http server, Nginx server, Nginx client(slow request)

复现操作

在server instance上放置一个 2GiB 大文件（0000000000000000.data）和一个 3MiB 小文件（server.pcap），并开启一个http server

1	nohup python -m http.server 8000

在Nginx instance上安装、配置好Nginx，并启动Nginx (注意要绑核！)

# install
sudo yum install nginx
# config (/etc/nginx/nginx.conf)
user nginx;
worker_processes 2;
error_log /var/log/nginx/error.log notice;
pid /run/nginx.pid;

include /usr/share/nginx/modules/*.conf;

events {
    worker_connections 1024;
}

http {
    log_format  main  '$remote_addr [$time_local] "$request" '
                      'status=$status body_bytes_sent=$body_bytes_sent '
                      'rt=$request_time uct="$upstream_connect_time" uht="$upstream_header_time" urt="$upstream_response_time"';

    access_log  /var/log/nginx/access.log  main;

    sendfile            on;
    tcp_nopush          on;
    keepalive_timeout   60;
    types_hash_max_size 4096;

    include             /etc/nginx/mime.types;
    default_type        application/octet-stream;

    # Load modular configuration files from the /etc/nginx/conf.d directory.
    # See http://nginx.org/en/docs/ngx_core_module.html#include
    # for more information.
    include /etc/nginx/conf.d/*.conf;

    server {
        listen       8000 reuseport;
        server_name  server1;
        root         /usr/share/nginx/html;

        # Load configuration files for the default server block.
        include /etc/nginx/default.d/*.conf;
        
        location / {
        proxy_pass http://172.31.86.252:8000; # server ip
        proxy_set_header Host $host;
        proxy_set_header X-Real-IP $remote_addr;
        }

        error_page 404 /404.html;
        location = /404.html {
        }

        error_page 500 502 503 504 /50x.html;
        location = /50x.html {
        }
    }
}
# start nginx
sudo taskset -c 0 nginx

启动慢连接client，开启4个下载进程并计时，测试脚本在此
启动快连接client，开启1个下载进程并计时，抓包，测试脚本在此
需要注意的是此处使用了curl –max-time 1，意味着即使1s内文件没有下载完，也会自动终止。
进入Nginx instance观察access.log
关掉reuseport或者调小recv buffer大小，重试一次

结果

ip maping:

172.31.86.252: http server
172.31.89.152: nginx server
172.31.91.109: 快连接 client
172.31.92.10:  慢连接 client

快连接client端：下载同一个小文件的下载时长有快有慢，方差很大，完整日志在此

[2023-05-31 08:27:32,127] runtime=1010
[2023-05-31 08:27:33,140] runtime=1009
[2023-05-31 08:27:34,152] runtime=38
[2023-05-31 08:27:34,192] runtime=1011
[2023-05-31 08:27:35,205] runtime=37
[2023-05-31 08:27:35,245] runtime=1008
[2023-05-31 08:27:36,256] runtime=57
[2023-05-31 08:27:36,315] runtime=1011

快连接client：无论耗时长短，抓包结果都显示存在不同程度卡顿，抓包文件在此耗时长的下载过程

耗时短的下载过程
Nginx access.log 存在大量未下载完的200请求，和少量499请求，且499请求的耗时为0，access.log文件在此
卡顿的日志建立连接时长（utc）在0.3-0.4ms左右，超过1s的就出现499了

172.31.91.109 [31/May/2023:08:27:49 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=102195 rt=0.790 uct="0.413" uht="0.592" urt="0.791"
172.31.91.109 [31/May/2023:08:27:50 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.058 uct="0.000" uht="0.002" urt="0.053"
172.31.91.109 [31/May/2023:08:27:51 +0000] "GET /server.pcap HTTP/1.1" status=499 body_bytes_sent=0 rt=0.000 uct="-" uht="-" urt="0.000"
172.31.91.109 [31/May/2023:08:27:51 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=102195 rt=0.763 uct="0.400" uht="0.580" urt="0.763"
172.31.91.109 [31/May/2023:08:27:52 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=102195 rt=0.767 uct="0.480" uht="0.768" urt="0.768"
172.31.91.109 [31/May/2023:08:27:53 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=580007 rt=0.773 uct="0.330" uht="0.431" urt="0.773"
172.31.91.109 [31/May/2023:08:27:55 +0000] "GET /server.pcap HTTP/1.1" status=499 body_bytes_sent=0 rt=0.000 uct="-" uht="-" urt="0.000"
172.31.91.109 [31/May/2023:08:27:55 +0000] "GET /server.pcap HTTP/1.1" status=499 body_bytes_sent=0 rt=0.000 uct="-" uht="-" urt="0.000"

下载中途被关闭的连接（200），可以观测到Nginx server在客户端已经请求FIN并被ACK之后仍然在发送一些网络数据包，客户端非常迷惑，向Nginx发送RST

未和Nginx建立连接就被关闭的连接（499），可以观测到连接始终没有被建立，在等待1s后客户端超时，主动请求关连接

限制Nginx server所在的instance的recv buffer大小，重新进行实验，可以观测到仍然有少量停顿，但整体耗时好了很多，不再有长达1s的卡顿，也不再有RST，完整日志在此

1	sysctl -w net.ipv4.tcp_rmem="40960 40960 40960"

client runtime log: 耗时稳定在50-100ms，比无慢连接、纯跑快连接时要大一倍（25-50ms）

[2023-06-05 06:13:22,791] runtime=120
[2023-06-05 06:13:22,913] runtime=82
[2023-06-05 06:13:22,997] runtime=54
[2023-06-05 06:13:23,054] runtime=61
[2023-06-05 06:13:23,118] runtime=109
[2023-06-05 06:13:23,229] runtime=58
[2023-06-05 06:13:23,290] runtime=55
[2023-06-05 06:13:23,347] runtime=79
[2023-06-05 06:13:23,429] runtime=65
[2023-06-05 06:13:23,497] runtime=53

client 抓包结果：

Nginx access.log: 都发完了，而且发得很流畅，建立连接时间（utc)非常短

172.31.91.109 [05/Jun/2023:06:13:22 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.101 uct="0.001" uht="0.004" urt="0.101"
172.31.91.109 [05/Jun/2023:06:13:22 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.064 uct="0.001" uht="0.002" urt="0.064"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.044 uct="0.000" uht="0.001" urt="0.044"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.047 uct="0.000" uht="0.001" urt="0.047"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.100 uct="0.000" uht="0.001" urt="0.099"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.047 uct="0.000" uht="0.001" urt="0.047"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.045 uct="0.001" uht="0.002" urt="0.045"
172.31.91.109 [05/Jun/2023:06:13:23 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=3602590 rt=0.066 uct="0.000" uht="0.002" urt="0.066"

对于慢连接大文件下载时长略有影响：46s (无限制) vs 53s (有限制)

关闭nginx reuseport

卡顿依然大量存在，但大多以连接能够建立但是下载不完的形式（200）出现，499较少，并且存在惊群现象，完整日志在此

1 2	server { listen 8000;

client runtime log：存在卡顿，和benchmark没有区别

[2023-06-05 06:38:06,682] runtime=1008
[2023-06-05 06:38:07,692] runtime=1008
[2023-06-05 06:38:08,703] runtime=220
[2023-06-05 06:38:08,926] runtime=112
[2023-06-05 06:38:09,040] runtime=60
[2023-06-05 06:38:09,103] runtime=865
[2023-06-05 06:38:09,970] runtime=1009
[2023-06-05 06:38:10,982] runtime=1008
[2023-06-05 06:38:11,992] runtime=1009

client抓包结果：存在卡顿，存在RST，和benchmark没有区别

access.log：卡顿的日志连接时间比benchmark略短，在0.2-0.3s左右，出现499的情况少了但是依然会有

172.31.91.109 [05/Jun/2023:06:38:02 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=204595 rt=0.844 uct="0.362" uht="0.539" urt="0.845"
172.31.91.109 [05/Jun/2023:06:38:03 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=204595 rt=0.907 uct="0.334" uht="0.476" urt="0.906"
172.31.91.109 [05/Jun/2023:06:38:04 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=543900 rt=0.836 uct="0.319" uht="0.504" urt="0.836"
172.31.91.109 [05/Jun/2023:06:38:05 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=204595 rt=0.831 uct="0.161" uht="0.480" urt="0.830"
172.31.91.109 [05/Jun/2023:06:38:06 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=552849 rt=0.820 uct="0.180" uht="0.329" urt="0.819"
172.31.91.109 [05/Jun/2023:06:38:07 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=204595 rt=0.800 uct="0.122" uht="0.462" urt="0.800"
172.31.91.109 [05/Jun/2023:06:38:08 +0000] "GET /server.pcap HTTP/1.1" status=200 body_bytes_sent=543900 rt=0.871 uct="0.251" uht="0.380" urt="0.871"

存在惊群现象，以下是Nginx worker进程的cpu使用率和上下文切换频率对比

1 2	# 每5s输出一次统计结果 pidstat -w -u 5

两者的cpu使用率和上下文切换频率差不多，但关闭reuseport后花在wait上的cpu时间明显增加（1.3-1.6% vs 2.8-2.9%），这就是惊群带来的性能损耗。原始文件：开启reuseport，关闭reuseport

# 开启reuseport
Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:      992      2590    1.77    9.57    0.00    1.25   11.35     -  nginx
Average:      992      2591    1.37    5.75    0.00    1.62    7.12     -  nginx

Average:      UID       PID   cswch/s nvcswch/s  Command
Average:      992      2590    179.18     49.64  nginx
Average:      992      2591    342.51      9.87  nginx

# 关闭reuseport
Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:      992      2788    1.02    8.02    0.00    2.80    9.04     -  nginx
Average:      992      2789    0.92    9.07    0.00    2.97    9.99     -  nginx

Average:      UID       PID   cswch/s nvcswch/s  Command
Average:      992      2788    159.06     28.68  nginx
Average:      992      2789    250.26     22.93  nginx

惊群对于慢连接大文件下载时长略有影响：46s (开reuseport) vs 53s (关reuseport)

其他的观察

最初复现的场景是所有的instance都是t2.micro，但开2个慢连接进程时比较难复现，开4个进程又太容易触发限流，所以开始考虑用大一些又没那么容易限流的instance型号。考虑到aws是通过间歇掉包来限速的，慢连接进程数量并非越大越好，引发限速后反而会造成网络连接不畅，造成慢连接卡顿，使得快连接卡顿反而不容易观测。最后选择将慢连接全链路改成t3.micro，结果好复现多了.

可以观察到有一些access.log上499的连接，各种计时也是0，这其实是因为计时也是通过worker进行的，只有进行epoll和上下文切换才会在日志上打入时间信息，worker如果一直不进行切换，那么计时就会失真，就会看到日志上计时也是0的现象。

结论

reuseport是Nginx避免惊群的优秀feature，应该开启
开启reuseport后如果网络情况非常好且后端服务压力不大，且存在大量慢连接时，会造成快连接卡顿，这是Nginx的worker-epoll架构带来的，原因是recv buffer一直读不完，NGINX采用的epoll ET 触发模式在这种情况下一直无法触发暂停导致worker无法响应其它请求
减小recv buffer通过人为制造卡顿，提供了epoll ET切换连接的条件，可以很大程度上缓解这个问题，同时带来的负面效果是有一定性能损耗。但卡顿无法根除，只能控制在可接受范围内

参考资料

MySQL线程池卡顿重现

发表于 2023-05-26 更新于 2025-11-16 分类于 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/

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

这个案例的重要性

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

重现后请思考：

MySQL为什么要将多个线程分成小池子，小池子肯定容易局部资源不足
Nginx 一个连接固定在一个worker上，那么同样多个Worker也会有不均衡(有的worker很闲，有的很卡)
动手实验一下将多个小池子改成一个大线程池会怎么样
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配置

| 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

执行结果

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

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

执行结果

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

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,可以看到:

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

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 模拟正常流量，结果失败：

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

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

尝试人工制造慢查询:

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

复现结果仍不满意：

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

此时分析了下，整体耗时上升是人工制造的慢查询，占用了过多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
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上来分析