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。如果我们没有这些信息，我怀疑还能不能定位这个问题。

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