DAS 解决延时突高的案例分享

DAS 是信也科技自研的数据库访问框架。它包括数据库控制台 das console，数据库客户端 das client 和数据库服务端 das server 三部分。DAS 是基于 Java 语言开发的，支持数据库管理，ORM，SQL 创建，分库分表操作的一体化数据库访问解决方案。

DAS 项目从去年开始已经在 GitHub 上开源：https://github.com/ppdaicorp/das

DAS 直连方式架构图

信也科技的应用大量使用 DAS 作为数据库访问中间件，目前几百个应用接入了 DAS。

作为公司的标准数据库访问技术，DAS 上线以来一直运行稳定。作为 DAS 团队，我们在接入的众多应用实战中积累了不少数据库访问相关的经验。

虽然我们这里分享的是 DAS 的真实技术支持的案例，但是我认为它的经过和结果对类似的情景仍旧很有借鉴的意义。

问题背景

去年公司有一个使用了 DAS 的对接外部系统的应用，应用开发人员反映系统会时不时地发生数据库慢查询。我们通过日志系统发现这些慢查询发生的比率极低，甚至低于千分之一。

如果这是个普通的应用，低于千分之一的慢查询比率是可以接受的。但是这一个对接外部系统的应用，外部系统对延时要求非常高，即使千分之一的高延迟仍旧不满足需求。

问题定位

首先，我们联系了 DBA，从数据库日志角度查看是数据库端是否有慢查询发生。DBA 团队在 MySQL 上面有专门记录慢查询的日志。慢查询的日志结果是否定的，而且数据库的数据量也在合理的水平。如果数据库端没有发生慢查询，那一定是整个链路其他地方发生了延时，随后我们把精力回到应用端。

通过研究日志，我们发现了和直觉相反的现象：延时没有发生在数据库操作频率比较高的操作上，而是发生在一些操作频率很低的操作上。

问题很可能和程序状态变迁有关。在应用端，DAS 本身是一个无状态的架构，它主要依赖于无状态的 JDBC 和 DataSource。DataSource 是典型有状态的程序，所以问题发生在 DataSource 的可能性最大。

DataSource 的本质是为了节省程序的时间和空间，对数据库连接做的缓存。它的设计思路和其他软件缓存的设计思路是一样的：要把实例放到缓存池管理，只不过这里的实例是数据库连接。每种数据库缓存池都有一系列的配置参数，它们都是用来调节缓存池的行为，通过不同的参数配置就能为不同的场景服务。

通过分析 DataSource 的配置，我们找到了原因。原因是由于数据库数据库两次操作间隔空闲时间太长，导致连接池里所有的 idle 连接被清空。后续新连接需要建立物理连接，每次建立物理连接，需要建立 socket 以及数据库的安全认证这些费时操作。

既然问题定位在 DataSource 对 idle 连接的行为上，那么我们就从 idle 的配置着手。DAS 使用 Tomcat 的 DataSource 获取数据库连接实例。Tomcat 的数据源提供了有很多的配置参数，这些参数决定了数据源的行为。

我们最后把参数定位在 minIdle 这个参数上。从 Tomcat 官方文档上这样解释这个参数：

The minimum number of established connections that should be kept in the pool at all times.

如果把数据源看做一个缓存，那么 minIdle 就是这个缓存的 minimum pool size。当时我们这个 minIdle 参数设置的是 0，设置成 0 的目的在于节省数据库连接。数据库连接是一种宝贵的资源，一个程序保持 idle 的连接太多不释放是一种浪费，对数据库这个共享的资源更是浪费，一个数据库往往同时被多个应用共同使用。

DBA 会设置每个数据库的最大连接数（max_connections）用以保护数据库不被请求压垮。当一个应用占据过多 idle 的连接，势必会影响其他应用的连接获取。

当 minIdle 参数设置成 0，固然节约连接，但是它在极端情况下可能产生效果就是：当连接池中的连接长久不用时，连接池内所有 idle 连接全部被清空。Tomcat 数据源会在后台定时启一个线程清理 idle 的连接，将 idle 的连接数降到 minIdle。

在设置成 0 之后，相当于连接池会被清空，于是后续第一个连接就需要建立真正的物理数据库连接，导致耗时飙高。在这个案例中，就是发生了这个情况。

解决方案

我们将参数 minIdle 从 0 改为 1，这样一来连接池中至少有一个连接可以被复用，而且保持一个 idle 连接也不算浪费。同时，我们通过增大了 minEvictableIdleTimeMillis 的参数把连接池中 idle 连接的最小空闲时间从 30 秒增大到 10 分钟。这样的话，位于缓存池里的 idle 连接生命周期延长了，池子里的 idle 数变多，增加了缓存命中率。需要注意的是 minEvictableIdleTimeMillis 这个参数控制的是 evict 掉缓存池里大于 minIdle 数的连接，在 minIdle 范围里面的连接是不会被它 evict 的。

是不是完美解决问题？不，故事未完。

遇到新问题

当我们在测试的时候发现，程序会报异常：

Caused by:

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:

The last packet successfully received from the server was 9,969,393 milliseconds ago.

这是由 minIdle 设置为 1 造成的。通过调查发现，这是由于 MySQL 服务器有一个 wait_timeout 的参数，默认是 8 小时。这也是一个保护 MySQL 数据库自我节省资源的行为。我们的数据库设置的 30 分钟，是也就是说一个连接空闲超过 30 分钟，MySQL 服务器将主动断开该连接。例子中的 9,969,393 毫秒相当于好几个小时，远超 30 分钟，所以导致了这种异常。这时应用从 DataSource 取连接的话，取到的就是那个失效的连接。minIdle 设置成 1 以后，那个长时间 idle 的连接就一直呆在连接池里面，甚至被 MySQL 服务器端断掉。

那加大 wait_timeout？加大 wait_timeout 是不符合 DBA 规范。怎么办？Tomcat 数据源提供了另一个有用的参数 testOnBorrow，官方文档上这样解释这个参数：

The indication of whether objects will be validated before being borrowed from the pool.

If the object fails to validate, it will be dropped from the pool, and we will attempt to borrow another.

如果把这个默认 false 值变为 true 之后，连接池会把连接从连接池拿出的时候会做验证连接有效性。这样就保证了从池里出来都是有效的连接。

验证与上线

最后，我们在本地开发环境验证了解决这个连接超时的方案。首先，先把本地测试 MySQL 服务器的 wait_timeout 的参数调低便于模拟超时，然后通过代码逻辑控制，将两次访问数据库的时间间隔超过 wait_timeout 参数时间，观察数据源在这种场景下的表现。在两个不同的数据源配置测试条件下，观察两次程序的结果。

本地验证成功之后，为了避免修改配置之后引发新的问题，我们首先进行了 JUnit 单元回归测试，保证基本功能完整。通过这几百个 JUnit 单元测试之后，把新配置部署到正式的测试环境进行观察。确认测试环境运行正常以后，最后才把配置更新到预发和生产环境。正规完善的流程是软件质量的保证。

至此，完美解决了这个问题。

其他数据源？

有人会问如果我没用 Tomcat 的数据源，用的是其他的数据源实现该如何做呢？

对于一个成熟的数据源产品来说，Idle connection handling 和 Validation 都是必有的功能。市面上大部分主流的数据源产品都有这些类似的参数。

譬如说流行的 Druid 和 DBCP2，他们也都有一模一样的 minIdle，minEvictableIdleTimeMillis 和 testOnBorrow 配置项。HikariCP 的类似配置项是 minimumIdle 和 idleTimeout。

感悟与总结

解决这个延时突高的问题，只是我们中间件团队众多日常技术支持的一个案例。

我们中间件团队和其他技术团队相比有特别之处，在于需要服务于公司各种不同的业务线和技术线。我们的用户有着不同的需求和特性，应用场景不同，技术要求也不同，也就会产生各种各样的问题。有对并发要求高的，有对延时要求高的，有对 API 易用性要求高的，有对监控数据要求高的，等等。

虽然遇到故障和问题各色各样，但是我们还是从这些实战中总结出一些共性的地方。我们可以把解决问题的过程总结为：反复地假设问题和论证，最后定位解决问题的过程。拿这个案例来说，起初用户来找到我们报问题的时候，我们也一头雾水：为啥低并发的延时比高并发还高？起初，因为没有明确的怀疑点，所以我们将链路上的每一点都检查了一下。从数据库到网络，甚至咨询了做监控的同学，以确认延时时间的正确性。通过反复调查，我们才将问题定位在客户端。

在排查问题的过程中，好的监控起到了关键作用。一般监控有两类输出：警告和日志。应用团队就是通过警告及时发现了问题，而我们中间件团队利用日志排查问题。日志的质量往往决定了定位问题的效率。好的监控能够提高你从表面现象到找到背后原因（从 what 到 why）的效率。

在这个解决这个延时突高的案例上，我们也是从日志上得到蛛丝马迹。DAS 本身会打详细的日志，通过这些日志，我们可以看到 DAS 的代码和它底层 JDBC 消耗的时间，从而定位耗时发生在 DAS 的更底层。我们还有个集中式日志系统，能在上面看到异常日志的原始信息，也可以在这个系统上面看各种维度的统计数据，譬如说，对这个案例至关重要的 999 线和 QPS。如果我们没有这些信息，我怀疑还能不能定位这个问题。

希望我们的这次排查问题的经历经过对大家有所帮助！