【案例】常驻查询引发的thread pool 性能问题之二

千家信息网最后更新 2025年02月02日【案例】常驻查询引发的thread pool 性能问题之二一 现象
某业务单机4个实例中的一个实例出现连接数远高于其他三个实例（正常是4K，问题实例是8K+），但是这4个实例的配置完全相同。业务开发反馈为部分连接失败。
执行show processlist结果显示：
存在大量的Killed状态的连接126个，处于Connect状态的6K+，以及6个binlog dump连接(如果看了前面一篇文章是否有点触动，会不会是这个导致的？)
执行pt-pmp结果显示：
mysqld 十分的空闲
执行show engine innodb status：
不存在空闲大事务

二 处理
根据上一篇文章的知识，初步判断该数据库实例遇到为Thread Pool的部分group被阻塞了，（能把query堵在login阶段的大部分为threadpool调度的问题，当然也不排除是因为逻辑原因造成login中出现内部锁等待）
在调整thread_pool_oversubscribe后所有的Connect/Killed状态的连接全部消失，连接数恢复正常。

三 问题分析
虽然问题是解决了，但是还有大量的疑问存在，显然在原因未知的情况下，如果在业务高峰期意外出现类似现象，后果非常严重，因此我们开始挖掘深层次的原因。
【曲折】
既然调整thread_pool_oversubscribe后问题就解决了，很显然是有group被阻塞了，因此最重要的就是找出是什么阻塞了Thread Pool。
这次最能引起人注意的现象当然是这126个Killed状态的连接了，我们知道当连接在运行中，被kill后处于回滚阶段时，会显示Killed。一般来说这个阶段非常短暂（除非有大量的rollback工作，但是State信息是空的，显然不是在rollback），pt-pmp的结果也证明了这一点。最开始一直怀疑是这些Killed的连接阻塞了threadpool的某些group，但是想来想去没有想到合理的解释，这里浪费了很多的时间。
【柳暗花明】
在Killed session上走不通，那只能看看其他session了，这时发现被阻塞的Connect连接的thread id十分有规律:

1. | 4261587 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
2. | 4261619 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
3. | 4261651 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
4. | 4261683 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
5. | 4261715 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
6. | 4261747 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |

间隔32递增，很明显是其中一个group被阻塞了。对32取模后发现全部为19号group,那看来是binlog dump没跑了。
对binlog dump线程的thread id对32取模后发现，6个thread中有4个在19号group中，而thread_pool_oversubscribe才3（内部限制为3+1），因此把19号group完全堵死。
到这里完全解释了本次拥堵产生的原因。本次问题中的126个Killed session极大的误导了我们的判断。

【深入分析】
回过头来有人会问，那126个Killed session是怎么来的呢？
这里就需要讲一下Thread Pool对kill处理的原理:

1. 当一个正在运行的连接被kill的时候，它所执行的sql会失败，其thd->killed会被置为THD::KILL_CONNECTION，同时通知Thread Pool（回调函数）。Thread Pool在回调函数中会发出一个io信号，worker需要捕获这个event（和正常的event一样处理）后，才会退出这个session，否则一直可以在show processlist看上类似本例子中126个session的状态。

但是本case中，在这126个session被kill以后，刚好有一个binlog dump连接连到了即将拥堵的19号group。

1. | 4261363 | xxxx | 10.9.6.57:10843| xxxx_0133 | Killed | 246196 | | NULL |
   
2. | 4261395 | xxxx | 10.8.9.18:35401| xxxx_0133 | Killed | 246186 | | NULL |
   
3. | 4261459 | xxxx | 10.8.2.61:60919| NULL| Binlog Dump | 246110| Master has sent all binlog to slave; waiting for binlog to be updated | NULL |
   
4. | 4261491 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |
   
5. | 4261502 | xxxx | 10.8.2.41:11862 | xxxx_0133 | Sleep | 1 | | NULL |
   
6. | 4261523 | unauthenticated user | connecting host | NULL | Connect | NULL | login | NULL |

看上图紧跟在Killed连接后面的4261459连接,使得19号group彻底被堵住，可怜的Killed连接连退出的机会都没有了,这就是这126个Killed连接的由来...