Problem description

These days, I have encountered a problem online, that is, after executing the application for a period of time, it will suddenly report a database connection timeout, and then the application will be unavailable all the time.

### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: LoanMarketPool - Connection is not available, request timed out after 30001ms.
Copy the code

Configuration is as follows

configuration: connectionTimeout............... 30000 driverClassName................." com.mysql.jdbc.Driver" idleTimeout..................... 600000 maxLifetime..................... 900000 maximumPoolSize................. 50 minimumIdle..................... 50Copy the code

The screening process

At first, it was suspected that the connection pool was insufficient, but the exception was still thrown after a period of running again by increasing the number of connection pools. Therefore, the DEBUG log of hikari connection pool was released by modifying the NACOS configuration to locate the problem.

logging:
    com:
      zaxxer:
        hikari: debug
Copy the code

When Hikari is initialized, the checkFailFast method is called to create a connection and pool it to check if there was a problem creating a database connection.

private void checkFailFast(a)
   {...do {
         final PoolEntry poolEntry = createPoolEntry();
         if(poolEntry ! =null) {
            if (config.getMinimumIdle() > 0) {
               connectionBag.add(poolEntry);
               logger.debug("{} - Added connection {}", poolName, poolEntry.connection); }... }}while (elapsedMillis(startTime) < initializationTimeout);
   }
Copy the code

Then check the connection status by creating houseKeeperTask and calling logPoolState to print the number of connections in the connection pool.

void logPoolState(String... prefix)
   {
      if (logger.isDebugEnabled()) {
         logger.debug("{} - {}stats (total={}, active={}, idle={}, waiting={})",
                      poolName, (prefix.length > 0 ? prefix[0] : ""), getTotalConnections(), getActiveConnections(), getIdleConnections(), getThreadsAwaitingConnection()); }}Copy the code

It checks the pool every once in a while to see if the connection has exceeded the minimum idle timeout, as well as the maximum connection lifetime, and closes any connections that have timed out and are not in use. The fillPool method is also called to fill the minimum number of connections in the connection pool after the connection is closed

private synchronized void fillPool(a)
   {
      final int connectionsToAdd = Math.min(config.getMaximumPoolSize() - getTotalConnections(), config.getMinimumIdle() - getIdleConnections())
                                   - addConnectionQueueReadOnlyView.size();
      if (connectionsToAdd <= 0) logger.debug("{} - Fill pool skipped, pool is at sufficient level.", poolName);

      for (int i = 0; i < connectionsToAdd; i++) {
         addConnectionExecutor.submit((i < connectionsToAdd - 1)? poolEntryCreator : postFillPoolEntryCreator); }}Copy the code

At the beginning of startup, Hikari will fill the connection up to the minimumIdle number, but the log shows that not every startup will fill up to the minimumIdle number, the number of each startup is not fixed.

2021-01-20 00:50:31.964 [LoanMarketPool housekeeper] DEBUG C.Z.H.P. Hikaripool - [logPoolState,421] - LoanMarketPool - Pool stats (total=1, active=1, idle=0, Waiting =0) 2021-01-20 00:50:32.023 [LoanMarketPool Connection adder] DEBUG c.z.H.P.Hikaripool - [call,728] - LoanMarketPool - Added connection com. Mysql. JDBC. JDBC4Connection @ 3 f3c777 00:50:32. 2021-01-20, 047 [LoanMarketPool connection adder] DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection Com. Mysql. JDBC. JDBC4Connection @ 777 d19cc 00:50:32. 2021-01-20, 073 [LoanMarketPool connection adder] the DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection com.mysql.jdbc.JDBC4Connection@41062367 2021-01-20 00:50:32.099 [LoanMarketPool Connection adder] DEBUG c.z.H.P.Hikaripool - [Call,728] -LoanMarketPool - Added Connection Com. Mysql. JDBC. JDBC4Connection @ 2290 fc45 00:50:32. 2021-01-20, 123 [LoanMarketPool connection adder] the DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection com.mysql.jdbc.JDBC4Connection@4f3653a2 2021-01-20 00:50:32.167 [LoanMarketPool Connection adder] DEBUG c.z.H.P.Hikaripool - [Call,728] -LoanMarketPool - Added Connection Com. Mysql. JDBC. JDBC4Connection @ 5 d41f91 00:50:32. 2021-01-20, 201 [LoanMarketPool connection adder] the DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection com.mysql.jdbc.JDBC4Connection@12e3e900 2021-01-20 00:50:32.227 [LoanMarketPool Connection adder] DEBUG c.z.H.P.Hikaripool - [Call,728] -LoanMarketPool - Added Connection Com. Mysql. JDBC. 46 a02511 JDBC4Connection @ 2021-01-20 00:50:32, 253 [LoanMarketPool connection adder] the DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection com.mysql.jdbc.JDBC4Connection@1149ea06 2021-01-20 00:50:32.278 [LoanMarketPool Connection adder] DEBUG C.Z.H.P. Hikaripool - [Call,728] -LoanMarketPool - Added Connection Com. Mysql. JDBC. JDBC4Connection @ 58940 a8d 00:50:32. 2021-01-20, 304 [LoanMarketPool connection adder] the DEBUG c.z.h.p.HikariPool - [call,728] - LoanMarketPool - Added connection com.mysql.jdbc.JDBC4Connection@6ac7ac81 2021-01-20 00:50:32.328 [LoanMarketPool Connection adder] DEBUG c.z.H.P.Hikaripool - [Call,728] -LoanMarketPool - Added Connection Com. Mysql. JDBC. 47 afa53b JDBC4Connection @ 2021-01-20 00:51:01, 967 [LoanMarketPool housekeeper] the DEBUG C.Z.H.P.H ikariPool -  [logPoolState,421] - LoanMarketPool - Pool stats (total=13, active=0, idle=13, Waiting =0) 2021-01-20 00:51:31.967 [LoanMarketPool housekeeper] DEBUG C.Z.H.P. Hikaripool - [logPoolState,421] - LoanMarketPool - Pool stats (total=13, active=0, idle=13, waiting=0)Copy the code

Here, in order to quickly expose the problem, change maxLifetime to 90 seconds, and then find that after the connection that the houseKeeper will exceed the maximum life cycle is closed, no new connection is added to the connection pool, resulting in the connection pool in the last connection is not available, the program throws an exception.

2021-01-20 00:54:26.239 [HTTP-niO-8085-exec -8] DEBUG c.z.H.P.Hikaripool - [addBagItem,342] -LoanMarketPool -add connection elided, waiting 1, Queue 50 2021-01-20 00:54:31.971 [LoanMarketPool housekeeper] DEBUG C.Z.H.P. Hikaripool - [logPoolState,421] - LoanMarketPool - Pool stats (total=0, active=0, idle=0, Waiting =1) 2021-01-20 00:54:31.971 [LoanMarketPool] DEBUG C.Z.H.P. Hikaripool - [fillPool,517] - LoanMarketPool - Fill pool skipped, pool is at sufficient level.Copy the code

Add connection elided, waiting 1, queue 50 Read the log. An additional connection to the database is submitted to the addConnectionExecutor thread pool via fillPool, but the houseKeeper seems to be blocked and unable to create a connection, causing subsequent additions to the database to be queued up.

conclusion

The current capacity is limited, so we can only investigate here. At present, I modify the parameter MaxLifetime to set it to 0 so that the houseKeeper will not close the connection when executing the scheduled task each time, as long as the connection pool is filled at the beginning of startup, In addition, there will be no problem if the connection inside is never emptied, but this is only a delaying measure, and it may be necessary to continue to check whether I need to understand the underlying Socket. At the same time, I also found an issue address of similar problem under the Hikari project of GitHub and posted it below, hoping to help you. Github.com/brettwooldr…