背景

線上某臺機器出現(xiàn)頻繁的獲取mysql連接超時, 項目用的是阿里的Druid連接池

排查步驟

1兔毒、 通過日志可以看出服務(wù)時獲取連接池超時

2017-07-14 13:10:01,973 [DubboServerHandler-10.25.65.225:20900-thread-174] ERROR com.alibaba.dubbo.rpc.filter.ExceptionFilter (ExceptionFilter.java:87) -  [DUBBO] Got unchecked and undeclared exception which called by 10.25.68.15. service: com.bilin.user.dynamic.service.IUserDynamicService, method: queryNewestDynamicMsgByUser, exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 10000, active 0, dubbo version: 2.4.9, current host: 10.25.65.225
org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 10000, active 0
        at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82)
        at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:183)
        at org.springframework.orm.ibatis.SqlMapClientTemplate.executeWithListResult(SqlMapClientTemplate.java:220)
        at org.springframework.orm.ibatis.SqlMapClientTemplate.queryForList(SqlMapClientTemplate.java:267)
        at com.bilin.sdk.dao.base.BaseDAO.queryForList(BaseDAO.java:27)
Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 10000, active 0
        at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1071)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:898)
        at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4544)
        at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:661)

2、 猜測可能的原因

• 并發(fā)量太高
  從數(shù)據(jù)上看甸箱，每秒不到1k請求育叁，后端mysql服務(wù)器的負(fù)載也不高，所以這個原因基本排除
• 連接池連接數(shù)設(shè)置過低
  業(yè)務(wù)設(shè)置的minIdel 100, maxConnection 300, 所以這個原因基本排除芍殖。
• mysql服務(wù)故障
  部署在別的機器上的服務(wù)豪嗽，還有使用同一個db實例的其它業(yè)務(wù)沒出現(xiàn)異常情況，所以這原因概率不大
• mysql鏈接設(shè)置過低

3、 由于沒有比較明顯的可能性龟梦，所以只能看下源碼(版本1.0.5)找下具體的原因隐锭。
DruidDataSource
異常的拋出是在1071行
throw new GetConnectionTimeoutException(errorMessage);
由于設(shè)置了鏈接獲取的超時時間

<property name="maxWait" value="10000" />

同時由報錯的日志可知，連接等待了10秒獲取失敗计贰，所以可得知執(zhí)行的方法時pollLast

            if (maxWait > 0) {
                holder = pollLast(nanos); //L 1021
            } else {
                holder = takeLast();
            }

druid的連接獲取成榜，是通過notEmpty和empty兩個變量協(xié)調(diào)線程的同步，pollLast發(fā)現(xiàn)沒可用連接時蹦玫，就會notEmpty.await(),同時empty.signal(). emtpy.signal主要喚醒了CreateConnectionThread. 通過了解CreateConnectionThread的源碼赎婚，發(fā)現(xiàn)在某些情況下線程會退出。
情況1

  try {
      connection = createPhysicalConnection();
  } catch (SQLException e) {
      LOG.error("create connection error", e);

      errorCount++;
      //當(dāng)錯誤次數(shù)達(dá)到設(shè)置值時樱溉，breakAfterAcquireFailure設(shè)置為true時線程會退出
      if (errorCount > connectionErrorRetryAttempts && timeBetweenConnectErrorMillis > 0) {
          if (breakAfterAcquireFailure) {
              break;
          }

          try {
              Thread.sleep(timeBetweenConnectErrorMillis);
          } catch (InterruptedException interruptEx) {
              break;
          }
      }
  } catch (RuntimeException e) {
      LOG.error("create connection error", e);
      continue;
  } catch (Error e) {
      LOG.error("create connection error", e);
      break;
  }

情況2

DruidConnectionHolder holder = null;
try {
    holder = new DruidConnectionHolder(DruidDataSource.this, connection);
} catch (SQLException ex) {
    //這里也會退出
    LOG.error("create connection holder error", ex);
    break;
}

情況1由于在該項目中沒設(shè)置breakAfterAcquireFailure挣输，采用默認(rèn)值false,所以情況1不大可能出現(xiàn)，Error屬于不可恢復(fù)錯誤福贞，所以退出也合理撩嚼。
情況2就有點不合理，單個的SQLException也會導(dǎo)致整個的生存線程結(jié)束挖帘。

4完丽、 所以接下來主要是確認(rèn)CreateConnectionThread是否存在異常
通過jstack grep線程名Druid-ConnectionPool-Create（線程有設(shè)置線程名是個好習(xí)慣）,從grep的結(jié)果，發(fā)現(xiàn)存在一個CreateConnectionThread拇舀，由于業(yè)務(wù)設(shè)置了兩個連接池逻族，所以一個是不正常

# sudo -u www-data jstack 10750  | grep "Druid-ConnectionPool-Create"
"Druid-ConnectionPool-Create-376416626" daemon prio=10 tid=0x00007faab4039800 nid=0x2ae3 waiting on condition [0x00007faac3ec6000]

繼續(xù)grep一下Destroy線程，確認(rèn)是兩個線程骄崩，所以Destroy線程正常聘鳞，進(jìn)一步確認(rèn)了CreateConnectionThread線程存在問題。

# sudo -u www-data jstack 10750  | grep "Druid-ConnectionPool-Des"   
"Druid-ConnectionPool-Destory-376416626" daemon prio=10 tid=0x00007faab403a800 nid=0x2ae4 waiting on condition [0x00007faac3e85000]
"Druid-ConnectionPool-Destory-190586441" daemon prio=10 tid=0x00007faad8fb1800 nid=0x2a3d waiting on condition [0x00007faac9dda000]

5要拂、 基本確認(rèn)了是由于CreateConnectionThread不正常結(jié)束抠璃，所以最后一步就是找尋證據(jù)證明線程不正常的結(jié)束。通過以上源碼脱惰，可看到Druid在每一步的異常處理都會記錄日志搏嗡，所以通過日志關(guān)鍵字進(jìn)行g(shù)rep,發(fā)現(xiàn)在1682行寫了個錯誤日志，對應(yīng)到的正式線程退出情況2.所以問題的原因就是druid在獲取mysql連接后創(chuàng)建DruidConnectionHolder時由于網(wǎng)絡(luò)原因報了MySQLException導(dǎo)致了CreateConnectionThread退出拉一。

2017-07-14 00:26:59,609 [Druid-ConnectionPool-Create-190586441] ERROR com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread (DruidDataSource.java:1682) - create connection holder error
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 0 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
        at sun.reflect.GeneratedConstructorAccessor33.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:525)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
        at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1121)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3673)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3562)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4113)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2812)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2761)
        at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1612)
        at com.mysql.jdbc.ConnectionImpl.getTransactionIsolation(ConnectionImpl.java:3352)
        at com.alibaba.druid.filter.FilterChainImpl.connection_getTransactionIsolation(FilterChainImpl.java:347)
        at com.alibaba.druid.filter.FilterAdapter.connection_getTransactionIsolation(FilterAdapter.java:872)
        at com.alibaba.druid.filter.FilterChainImpl.connection_getTransactionIsolation(FilterChainImpl.java:344)
        at com.alibaba.druid.filter.FilterAdapter.connection_getTransactionIsolation(FilterAdapter.java:872)
        at com.alibaba.druid.filter.FilterChainImpl.connection_getTransactionIsolation(FilterChainImpl.java:344)
        at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.getTransactionIsolation(ConnectionProxyImpl.java:260)
        at com.alibaba.druid.pool.DruidConnectionHolder.<init>(DruidConnectionHolder.java:92)
        at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:1680)
Caused by: java.net.SocketException: Connection reset
        at java.net.SocketInputStream.read(SocketInputStream.java:189)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3573)
        ... 16 more

6采盒、 查看了最新版本1.1.2這部分的代碼，發(fā)現(xiàn)這部分代碼已經(jīng)重構(gòu)了舅踪，不存在該問題纽甘，所以升級版本即可良蛮。

總結(jié)

1抽碌、故障的版本時1.0.5，發(fā)布于2014年，屬于比較舊的版本货徙，開源工具不可避免的會存在bug,所以需要即時的進(jìn)行升級
2左权、使用開源工具時，盡可能的使用最新的版本痴颊。