扑朔迷离的根因分析

发表于 | 分类于 | 次

扑朔迷离的根因分析

原则

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

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

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

image-20230520101758175

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

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

业务结构

image-20230517113148916

概念说明：

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

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

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

响应时间=RT=耗时监控

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

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

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

监控数据

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

image-20230516150350614

(图1)

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

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

image-20230516150812485

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

补充知识

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

image.png

Tomcat CPU 监控

image-20230516150950383

问题

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

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

继续看另外案例

案例2 yy

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

image-20230519170255718

image-20230519172225890

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

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

image-20230519172519802

第三次压测图

image-20230519165825977

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

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

image-20230519203620163

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

分析

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

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

image-20230520111102697

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之间的问题的理解很关键。

image-20240523084559029

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

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

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

image-20230721170334688

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

Druid 创建连接的堆栈如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
"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，下图右上角是获取失败的日志打堆栈消耗，可以看到异常非常多。

image-20230519174633172

image-20230519175029396

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

maxWaitThreadCount 30, current wait Thread count 0

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
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秒最大等待时间还没有获取到连接：image-20230519191317489

红色错误信息表示等了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

image-20230520092224080

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

分析方法：

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

原因

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

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

分片逻辑

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

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
如果对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 负载不均衡：

image-20230519181628114

Java源码：

image-20230519181451384

总结

问题的根本原因？

多个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更高，进入一种平衡状态

为什么有时候压测能过？

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