从很早以前,我维护的一个应用在做数据源主备切换时,经常出现切换后获取连接超时。前些时候,我对这个问题做了深入的分析,并得到一些结论,在这里分享给大家。

1. 起因

在我的一个应用中,对数据源做了高可用保障,具体实现是底层数据库是异地双机房,当其中一个机房流量出现异常时,可以在应用中通过配置将数据源访问切换到另一个机房。其中两地数据库的数据源在应用启动时,就已经创建完成,当线上发生异常时,可以快速地做出切换。

然而,在该高可用功能上线后,当切换时,备库数据源时不时出现撂挑子的现象。具体来说,就是当切换后的几分钟内,线上访问超时、数据库连接超时。这种情况在我们意料之外,也不符合高可用要求。

2. 排查过程

前些时候,总算是空出一些时间,开始对这个问题进行修复。由于我们用的数据库是分布式数据库,数据源DataSource也是定制开发的,该数据源底层实际包装了druid数据源,整体从使用方式上来说,基本上无差别。

2.1 参数配置

最开始,DBA给出的方案增加testWhileIdle检测,从名字上来看,应该是空闲时间检测的意思。由于之前也用过druid数据源,也大概了解底层运行原理,于是配置上了参数。

druid连接检测参数:

<property name="validationQuery" value="select 1" />
<property name="testWhileIdle" value="true" />
<property name="testOnBorrow" value="false" />
<property name="testOnReturn" value="false" />

在配置好上述参数并发布预发后,我等了一天,第二天向DBA咨询具体查询日志,DBA告诉我,从昨天到今天,并没有客户端调用过select 1

这令我很困惑,难道是定制开发的数据源有问题?闲时检测没有生效?

2.2 validator原理

带着这个困惑,我联系上了数据库开发同学,准备一起看看这个问题。为了能快速验证validate功能,我将配置参数中的testOnBorrowtestOnReturn设置成true,但线上是不建议开启的。其原理是在业务从druid获取每一个连接时,当设置了testOnBorrow,每次返回连接前都会执行一次validate,但实际上线上不可能每次获取连接都需要做检测,所以这里开启只是为了验证该功能已正常开启。

druid连接检测参数:

<property name="validationQuery" value="select 1" />
<property name="testWhileIdle" value="true" />
<property name="testOnBorrow" value="true" />
<property name="testOnReturn" value="true" />

当配置完这些参数发布预发后,我在预发发起了一次数据库查询,数据库开发同学检测到了数据库查询,但还是没有select 1请求。这下,我和开发同学都蒙了,难道真是定制开发的数据源有问题?带着这个疑问,我仔细走读了druid获取连接的源码。最终定位到了原因。

首先,getConnection()方法最终会调用到下面这个方法getConnectionDirect

    public DruidPooledConnection getConnectionDirect(long maxWaitMillis) throws SQLException {
        int notFullTimeoutRetryCnt = 0;
        for (;;) {
            // handle notFullTimeoutRetry
            DruidPooledConnection poolableConnection;
            try {
                poolableConnection = getConnectionInternal(maxWaitMillis);
            } catch (GetConnectionTimeoutException ex) {
                if (notFullTimeoutRetryCnt <= this.notFullTimeoutRetryCount && !isFull()) {
                    notFullTimeoutRetryCnt++;
                    if (LOG.isWarnEnabled()) {
                        LOG.warn("get connection timeout retry : " + notFullTimeoutRetryCnt);
                    }
                    continue;
                }
                throw ex;
            }

            if (testOnBorrow) {
                boolean validate = testConnectionInternal(poolableConnection.holder, poolableConnection.conn);
                if (!validate) {
                    if (LOG.isDebugEnabled()) {
                        LOG.debug("skip not validate connection.");
                    }

                    discardConnection(poolableConnection.holder);
                    continue;
                }
            } 
            // ...... 省略部分代码

            return poolableConnection;
        }
    }

其中启用testOnBorrow会调用testConnectionInternal方法:

    protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
        String sqlFile = JdbcSqlStat.getContextSqlFile();
        String sqlName = JdbcSqlStat.getContextSqlName();

        if (sqlFile != null) {
            JdbcSqlStat.setContextSqlFile(null);
        }
        if (sqlName != null) {
            JdbcSqlStat.setContextSqlName(null);
        }
        try {
            if (validConnectionChecker != null) {
                boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);
                long currentTimeMillis = System.currentTimeMillis();
                if (holder != null) {
                    holder.lastValidTimeMillis = currentTimeMillis;
                    holder.lastExecTimeMillis = currentTimeMillis;
                }

                if (valid && isMySql) { // unexcepted branch
                    long lastPacketReceivedTimeMs = MySqlUtils.getLastPacketReceivedTimeMs(conn);
                    if (lastPacketReceivedTimeMs > 0) {
                        long mysqlIdleMillis = currentTimeMillis - lastPacketReceivedTimeMs;
                        if (lastPacketReceivedTimeMs > 0 //
                                && mysqlIdleMillis >= timeBetweenEvictionRunsMillis) {
                            discardConnection(holder);
                            String errorMsg = "discard long time none received connection. "
                                    + ", jdbcUrl : " + jdbcUrl
                                    + ", jdbcUrl : " + jdbcUrl
                                    + ", lastPacketReceivedIdleMillis : " + mysqlIdleMillis;
                            LOG.error(errorMsg);
                            return false;
                        }
                    }
                }

                if (valid && onFatalError) {
                    lock.lock();
                    try {
                        if (onFatalError) {
                            onFatalError = false;
                        }
                    } finally {
                        lock.unlock();
                    }
                }

                return valid;
            }

            if (conn.isClosed()) {
                return false;
            }

            if (null == validationQuery) {
                return true;
            }

            Statement stmt = null;
            ResultSet rset = null;
            try {
                stmt = conn.createStatement();
                if (getValidationQueryTimeout() > 0) {
                    stmt.setQueryTimeout(validationQueryTimeout);
                }
                rset = stmt.executeQuery(validationQuery);
                if (!rset.next()) {
                    return false;
                }
            } finally {
                JdbcUtils.close(rset);
                JdbcUtils.close(stmt);
            }

            if (onFatalError) {
                lock.lock();
                try {
                    if (onFatalError) {
                        onFatalError = false;
                    }
                } finally {
                    lock.unlock();
                }
            }

            return true;
        } catch (Throwable ex) {
            // skip
            return false;
        } finally {
            if (sqlFile != null) {
                JdbcSqlStat.setContextSqlFile(sqlFile);
            }
            if (sqlName != null) {
                JdbcSqlStat.setContextSqlName(sqlName);
            }
        }
    }

可以看到该方法内容大致分为两部分,第一部分是当validConnectionChecker不为空的时候,由validConnectionChecker来校验;第二部分当validConnectionChecker为空,则通过调用query来校验。

定制化的数据源默认配置了validConnectionChecker为MySqlValidConnectionChecker。查看MySqlValidConnectionChecker中的isValidConnection方法

    public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) throws Exception {
        if (conn.isClosed()) {
            return false;
        }

        if (usePingMethod) {
            if (conn instanceof DruidPooledConnection) {
                conn = ((DruidPooledConnection) conn).getConnection();
            }

            if (conn instanceof ConnectionProxy) {
                conn = ((ConnectionProxy) conn).getRawObject();
            }

            if (clazz.isAssignableFrom(conn.getClass())) {
                if (validationQueryTimeout <= 0) {
                    validationQueryTimeout = DEFAULT_VALIDATION_QUERY_TIMEOUT;
                }

                try {
                    ping.invoke(conn, true, validationQueryTimeout * 1000);
                } catch (InvocationTargetException e) {
                    Throwable cause = e.getCause();
                    if (cause instanceof SQLException) {
                        throw (SQLException) cause;
                    }
                    throw e;
                }
                return true;
            }
        }

        //...... 省略部分代码

    }

哦,原来是用ping命令代替了select 1查询,估计是使用该命令要比执行查询响应速度快。

在查看源码的时候也发现了testWhileIdle参数并不是说druid背后有一个线程会定期执行select 1或ping命令,而是在getConnection的时候,判断池子中连接的闲置时间如果大于指定时间,就会去做检测。

同时在debug的时候,我发现定制化的数据源实际上是强制开启testWhileIdle参数的。

2.3 定制化数据源原理

经过上面这些折腾,最终发现问题并不在druid数据源。那为什么会出现获取connection超时呢?带着这个疑问,我又查看了报错日志,日志中显示:maxActive=200,currentCount=201。

这是什么意思呢?数据库开发同学告诉我,这是业务在获取第201个connection时,超时了。原因是池子最多允许有200个连接,第201个请求只能等前面的连接被放回来后才能获取connection。

也就是说,切换数据源后,有200个连接被借出去后,长时间未归还。可是为什么会出现这样的情况?前面的连接为什么会使用的那么久?开发同学建议我调大maxActive的值,但我觉得调整这个参数治标不治本。如果访问qps很高,再调整maxActive也没用。

于是,我又扒了扒出错时的日志,发现出错时,定制数据源竟然有重建druid的操作,并且创建一个连接竟然要30ms。把这些日志拿到数据库开发同学的面前,他终于知道是怎么回事了。

原来用到的分布式数据库有这么个思路,如果查询直接打到表所在的服务器上,那么执行速度要比服务器间转发调用速度快。定制化数据源内部也就有一个服务器地址到druid数据源的缓存,该数据源会根据要查询的表,找到对应的服务器地址。在缓存中拿着这个地址,找到对应的druid,然后获取连接并执行。如果缓存没有命中,那么就会立刻创建一个对应该服务器地址的druid。

那为什么在做完数据源切换后,会出现重建druid操作呢?原来分布式数据库会定期整理表,整理完后,表和服务器地址的对应关系就会变化,如果表对应的服务器地址是新的,那么定制化数据源就只能重建。

重建耗时长的原因也有了结论,原因是连接是跨城的,跨城访问速度特别慢,基本上就在30ms左右。

这应该是算做定制化数据源的bug,定制化数据源目前能够定期拿到表到服务器地址的映射关系,那么顺手做一下服务器地址到druid的缓存也应该不是困难的事。目前的解决方案是在做切换数据源操作时,先重建数据源,然后再切换。

3. 小结

上边整个排查过程,大概花了两天时间。经过这次排查,我对druid数据源配置有了更深入的了解,也对分布式数据库原理有了进一步认识。

druid数据源并不支持闲时检测,他支持的只是闲时空闲连接释放。配合minIdlemaxActivetimeBetweenEvictionRunsMillis minEvictableIdleTimeMillis参数使用。每间隔timeBetweenEvictionRunsMillis时间,它会检测每一个连接的空闲时间是否超过minEvictableIdleTimeMillis时间,如果超过了,那么会将被检测的连接释放掉,直到池子里只剩minIdle个的连接。

druid数据源在做testWhileIdle时,只是在getConnection的时候,判该连接空闲时间是否大于timeBetweenEvictionRunsMillis时间,如果大于,那么就会被拿出来做检测,检测这个连接是否可用。

分布式数据库,原来也会在客户端做优化,将请求打到表所在的服务器地址上,这样就能初步减少数据库内部服务器间调用。

标签: java, database, druid

添加新评论