排查Failed?to?validate?connection?com.mysql.cj.jdbc.ConnectionImpl
整個問題排查過程中基本把Hikari連接池源碼看完了,也發(fā)現(xiàn)了Hikari內(nèi)部的一些實(shí)現(xiàn)細(xì)節(jié),更多細(xì)節(jié)參見:Hikari 數(shù)據(jù)庫連接池內(nèi)部源碼實(shí)現(xiàn)細(xì)節(jié)
問題描述及排查
最近發(fā)布項目測試環(huán)境后,發(fā)現(xiàn)后臺經(jīng)常隔28分鐘時間就打印mysql 連接已經(jīng)被關(guān)閉警告。(應(yīng)用程序每28分鐘訪問一次數(shù)據(jù)庫)
- 數(shù)據(jù)庫: mysql 5.7
- 數(shù)據(jù)庫驅(qū)動:mysql-connector-java-8.0.23
- 連接池:HikariCP-3.4.5
- SpringBoot 2.4.3
連接池配置如下:
spring.datasource.username=${name} spring.datasource.password=${pwd} spring.datasource.url=jdbc:mysql://${ip}:3306/${dbname}?useUnicode=true&characterEncoding=utf-8&useSSL=false&serverTimezone=Asia/Shanghai spring.datasource.type=com.zaxxer.hikari.HikariDataSource spring.datasource.driver-class-name=com.mysql.cj.jdbc.Driver spring.datasource.hikari.minimum-idle=10 spring.datasource.hikari.maximum-pool-size=20 spring.datasource.hikari.connection-test-query=SELECT 1 FROM DUAL spring.datasource.hikari.validation-timeout=10000 spring.datasource.hikari.auto-commit=true
警告信息如下:
2021-03-19 13:25:58.486 WARN 21806 --- [scheduling-1] com.zaxxer.hikari.pool.PoolBase :
slave - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@2e2ce118 (No operations allowed after connection closed.).
Possibly consider using a shorter maxLifetime value.
雖然這只是一個警告,并不影響程序執(zhí)行,但還是很好奇想要排查一下具體原因。
warn信息的描述,程序通過已經(jīng)關(guān)閉的連接來訪問數(shù)據(jù)數(shù)據(jù)庫,這是不允許的操作,并且警告中提醒減小maxLifetime
的值來解決這個問題。
看到這個警告之后,筆者首先想到的就是mysql 8小時主動斷開問題:如果hikari的maxLifetime
的值超過了mysql默認(rèn)的wait_timeout
設(shè)置的時間28800s (8小時),實(shí)際上mysql已經(jīng)主動關(guān)閉了連接。
但示例中并沒有配置hikari的maxLifetime
選項,采用的是默認(rèn)。
查看hikari的源碼發(fā)現(xiàn)了如下幾個默認(rèn)配置
com.zaxxer.hikari.HikariConfig
源碼中的類變量
private static final long CONNECTION_TIMEOUT = SECONDS.toMillis(30); 30s private static final long VALIDATION_TIMEOUT = SECONDS.toMillis(5); 5s private static final long IDLE_TIMEOUT = MINUTES.toMillis(10); 20分鐘 private static final long MAX_LIFETIME = MINUTES.toMillis(30); 30分鐘 private static final int DEFAULT_POOL_SIZE = 10;
hikari中默認(rèn)連接存活的最大時間是30分鐘,小于mysql默認(rèn)的wait_timeout
28800s (8小時),按道理不會是服務(wù)端主動主動關(guān)閉連接導(dǎo)致。
那會不會是mysql
的wait_timeout
被修改過??? 通過如下語句查詢發(fā)現(xiàn)并沒有被修改。
SHOW VARIABLES LIKE '%timeout%'
當(dāng)排除這個常規(guī)問題后,筆者嘗試搜索了有沒有其它可能導(dǎo)致這個警告,最終還是有一個小發(fā)現(xiàn):
搜索到的案例是:雖然mysql服務(wù)端通過SHOW VARIABLES LIKE '%timeout%'
查出來的時間28800s,但是實(shí)際上,/etc/my.cnf
中配置的超時時間更小,導(dǎo)致mysql服務(wù)端主動關(guān)閉連接。
但是經(jīng)過和dba確認(rèn),也排除了這個情況。
既然以上兩種情況都排除了,那只能深入源碼,在測試環(huán)境遠(yuǎn)程斷點(diǎn)調(diào)試。
先搜索下警告打印的位置,只有一處在isConnectionAlive
方法中.
源碼如下: com.zaxxer.hikari.pool.PoolBase#isConnectionAlive
boolean isConnectionAlive(final Connection connection) { try { try { setNetworkTimeout(connection, validationTimeout); final int validationSeconds = (int) Math.max(1000L, validationTimeout) / 1000; if (isUseJdbc4Validation) { return connection.isValid(validationSeconds); } try (Statement statement = connection.createStatement()) { if (isNetworkTimeoutSupported != TRUE) { setQueryTimeout(statement, validationSeconds); } statement.execute(config.getConnectionTestQuery()); } } finally { setNetworkTimeout(connection, networkTimeout); if (isIsolateInternalQueries && !isAutoCommit) { connection.rollback(); } } return true; } catch (Exception e) { lastConnectionFailure.set(e); logger.warn("{} - Failed to validate connection {} ({}). Possibly consider using a shorter maxLifetime value.", poolName, connection, e.getMessage()); return false; } }
該方法用于檢測connection的有效性,catch到異常后,只是簡單打印文章開頭所提的異常警告信息,并返回false,表示連接失效。
然后會繼續(xù)從連接池中獲取有效的連接。
獲取連接的代碼如下: com.zaxxer.hikari.pool.HikariPool#getConnection(long hardTimeout)
public Connection getConnection(final long hardTimeout) throws SQLException { suspendResumeLock.acquire(); final long startTime = currentTime(); try { long timeout = hardTimeout; do { PoolEntry poolEntry = connectionBag.borrow(timeout, MILLISECONDS); if (poolEntry == null) { break; // We timed out... break and throw exception } final long now = currentTime(); if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs && !isConnectionAlive(poolEntry.connection))) { closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE); timeout = hardTimeout - elapsedMillis(startTime); } else { metricsTracker.recordBorrowStats(poolEntry, startTime); return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now); } } while (timeout > 0L); metricsTracker.recordBorrowTimeoutStats(startTime); throw createTimeoutException(startTime); } catch (InterruptedException e) { Thread.currentThread().interrupt(); throw new SQLException(poolName + " - Interrupted during connection acquisition", e); } finally { suspendResumeLock.release(); } }
為了打印更多的異常棧信息,筆者修改了isConnectionAlive
方法源碼,在catch到異常后,打印整個異常棧信息,最終得到如下日志:
2021-03-19 13:25:58.486 WARN 21806 --- [scheduling-1] com.zaxxer.hikari.pool.PoolBase : slave - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@2e2ce118 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2021-03-19 13:25:58.489 ERROR 21806 --- [scheduling-1] com.zaxxer.hikari.pool.PoolBase : poolBase:java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed.
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.ConnectionImpl.setNetworkTimeout(ConnectionImpl.java:2495) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:563) ~[classes!/:na]
at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:173) ~[classes!/:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:186) [HikariCP-3.4.5.jar!/:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) [HikariCP-3.4.5.jar!/:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100) [HikariCP-3.4.5.jar!/:na]
at org.springframework.jdbc.datasource.lookup.AbstractRoutingDataSource.getConnection(AbstractRoutingDataSource.java:194) [spring-jdbc-5.3.4.jar!/:5.3.4]
at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) [spring-jdbc-5.3.4.jar!/:5.3.4]
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) [spring-jdbc-5.3.4.jar!/:5.3.4]
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79) [spring-jdbc-5.3.4.jar!/:5.3.4]
.........................
Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed.
at sun.reflect.GeneratedConstructorAccessor32.newInstance(Unknown Source) ~[na:na]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_91]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_91]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:1171) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:573) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.ConnectionImpl.setNetworkTimeout(ConnectionImpl.java:2491) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
... 44 common frames omitted
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failureThe last packet successfully received from the server was 1,758,048 milliseconds ago. The last packet sent successfully to the server was 1,758,049 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor31.newInstance(Unknown Source) ~[na:na]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_91]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_91]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:577) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:632) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:948) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:894) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1073) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.StatementImpl.executeInternal(StatementImpl.java:722) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.jdbc.StatementImpl.execute(StatementImpl.java:646) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:169) ~[classes!/:na]
... 42 common frames omitted
Caused by: java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:1.8.0_91]
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109) ~[na:1.8.0_91]
at java.net.SocketOutputStream.write(SocketOutputStream.java:153) ~[na:1.8.0_91]
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) ~[na:1.8.0_91]
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) ~[na:1.8.0_91]
at com.mysql.cj.protocol.a.SimplePacketSender.send(SimplePacketSender.java:55) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.TimeTrackingPacketSender.send(TimeTrackingPacketSender.java:50) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
at com.mysql.cj.protocol.a.NativeProtocol.send(NativeProtocol.java:568) ~[mysql-connector-java-8.0.23.jar!/:8.0.23]
... 49 common frames omitted
從最后的Caused by: java.net.SocketException: Broken pipe 似乎只能看出在發(fā)送數(shù)據(jù)時socket已經(jīng)被斷開。
于是想到是不是socket
的connectionTime
和 socketTimeout
太短,網(wǎng)絡(luò)較差導(dǎo)致發(fā)送sql請求時超時???
又是一通debug之后,深入到mysql-connector-java客戶端源碼中,最終發(fā)現(xiàn)了如下兩段重要的代碼,用于初始化mysql的連接。
其中成員變量propertySet
則保存了全部的連接參數(shù)以及數(shù)據(jù)連接配置參數(shù)。
com.mysql.cj.NativeSession#connect
源碼
com.mysql.cj.protocol.StandardSocketFactory#configureSocket
源碼
com.mysql.cj.CoreSession#propertySet
中保存的連接配置屬性如下:
result = {Properties@10050} size = 167 "useCompression" -> "false" "maxRows" -> "-1" "tcpTrafficClass" -> "0" "allowNanAndInf" -> "false" "databaseTerm" -> "CATALOG" "sendFractionalSeconds" -> "true" "loadBalanceBlocklistTimeout" -> "0" "tcpKeepAlive" -> "true" "allowReplicaDownConnections" -> "false" "maxQuerySizeToLog" -> "2048" "verifyServerCertificate" -> "false" "cacheServerConfiguration" -> "false" "dontCheckOnDuplicateKeyUpdateInSQL" -> "false" "paranoid" -> "false" "allowSourceDownConnections" -> "false" "xdevapi.ssl-truststore-type" -> "JKS" "fallbackToSystemTrustStore" -> "true" "enableQueryTimeouts" -> "true" "blobSendChunkSize" -> "1048576" "useNanosForElapsedTime" -> "false" "readOnlyPropagatesToServer" -> "true" "profilerEventHandler" -> "com.mysql.cj.log.LoggingProfilerEventHandler" "secondsBeforeRetrySource" -> "30" "parseInfoCacheFactory" -> "com.mysql.cj.PerConnectionLRUFactory" "includeThreadNamesAsStatementComment" -> "false" "xdevapi.compression" -> "PREFERRED" "socketTimeout" -> "5000" "socksProxyPort" -> "1080" "requireSSL" -> "false" "largeRowSizeThreshold" -> "2048" "xdevapi.fallback-to-system-keystore" -> "true" "allowMultiQueries" -> "false" "rewriteBatchedStatements" -> "false" "enablePacketDebug" -> "false" "allowPublicKeyRetrieval" -> "false" "noDatetimeStringSync" -> "false" "includeThreadDumpInDeadlockExceptions" -> "false" "enableEscapeProcessing" -> "true" "failOverReadOnly" -> "true" "readFromSourceWhenNoReplicas" -> "false" "clientCertificateKeyStoreType" -> "JKS" "overrideSupportsIntegrityEnhancementFacility" -> "false" "disconnectOnExpiredPasswords" -> "true" "clobberStreamingResults" -> "false" "trustCertificateKeyStoreType" -> "JKS" "jdbcCompliantTruncation" -> "false" "useLocalTransactionState" -> "false" "cacheCallableStmts" -> "false" "rollbackOnPooledClose" -> "true" "cacheResultSetMetadata" -> "false" "loadBalanceValidateConnectionOnSwapServer" -> "false" "selfDestructOnPingMaxOperations" -> "0" "elideSetAutoCommits" -> "false" "loadBalanceHostRemovalGracePeriod" -> "15000" "serverConfigCacheFactory" -> "com.mysql.cj.util.PerVmServerConfigCacheFactory" "cacheDefaultTimeZone" -> "true" "allowLoadLocalInfile" -> "false" "loadBalanceAutoCommitStatementThreshold" -> "0" "getProceduresReturnsFunctions" -> "true" "forceConnectionTimeZoneToSession" -> "false" "useInformationSchema" -> "false" "reportMetricsIntervalMillis" -> "30000" "alwaysSendSetIsolation" -> "true" "tinyInt1isBit" -> "true" "xdevapi.ssl-keystore-type" -> "JKS" "xdevapi.auth" -> "PLAIN" "processEscapeCodesForPrepStmts" -> "true" "emptyStringsConvertToZero" -> "true" "sslMode" -> "DISABLED" "xdevapi.connect-timeout" -> "10000" "zeroDateTimeBehavior" -> "EXCEPTION" "sendFractionalSecondsForTime" -> "true" "maxReconnects" -> "3" "autoDeserialize" -> "false" "callableStmtCacheSize" -> "100" "prepStmtCacheSqlLimit" -> "256" "resultSetSizeThreshold" -> "100" "useSSL" -> "false" "metadataCacheSize" -> "50" "useHostsInPrivileges" -> "true" "tcpRcvBuf" -> "0" "dontTrackOpenResources" -> "false" "autoGenerateTestcaseScript" -> "false" "characterEncoding" -> "utf-8" "xdevapi.fallback-to-system-truststore" -> "true" "nullDatabaseMeansCurrent" -> "false" "useLocalSessionState" -> "false" "detectCustomCollations" -> "false" "useOldAliasMetadataBehavior" -> "false" "autoReconnect" -> "false" "autoReconnectForPools" -> "false" "traceProtocol" -> "false" "maxAllowedPacket" -> "16777216" "populateInsertRowWithDefaultValues" -> "false" "useUnbufferedInput" -> "true" "ignoreNonTxTables" -> "false" "useAffectedRows" -> "false" "ha.loadBalanceStrategy" -> "random" "loadBalancePingTimeout" -> "0" "compensateOnDuplicateKeyUpdateCounts" -> "false"
最后發(fā)現(xiàn)在驗(yàn)證connection有效性時,connectionTime
和 socketTimeout
設(shè)置的就是數(shù)據(jù)源中配置的connection-timeout
和validation-timeout
,并通過ping命令檢測發(fā)現(xiàn),網(wǎng)絡(luò)并不是很慢,所以網(wǎng)絡(luò)請求超時這個可能也排除。
調(diào)試過程中發(fā)現(xiàn)mysql客戶端和服務(wù)端之間Socket通信,心跳是通過TCP協(xié)議中默認(rèn)的tcpKeepAlive
參數(shù)來維護(hù)心跳的。
通過搜索得知,linux中默認(rèn)是2小時。
會不會服務(wù)器tcp_keepalive_time時間被修改過,但因?yàn)榫W(wǎng)絡(luò)緩慢,心跳未接收到,導(dǎo)致服務(wù)器關(guān)閉了連接???
可以通過linux的如下命令查看
cat /proc/sys/net/ipv4/tcp_keepalive_time
在筆者的應(yīng)用服務(wù)器上發(fā)現(xiàn)這個時間確實(shí)被改成了較短的180s,那么mysql所在的機(jī)器,很可能也是被改過。
于是找到dba查看該項的配置。同樣是180s,但這個時間也不至于讓心跳超時啊!
最終原因: 好在dba詢問了一下為什么要查這個參數(shù),然后筆者將警告信息以及排查的過程描述了一下,結(jié)果dba那邊竟然告訴我有定時任務(wù), 刪除4分鐘內(nèi)沒有請求的連接,而我的程序訪問數(shù)據(jù)庫時間間隔是28分鐘一次,所以早就在mysql服務(wù)端關(guān)閉了(捂臉哭的表情)
那如何讓這個告警不打印呢?
既然數(shù)據(jù)庫服務(wù)端會在4分鐘后刪除沒有請求的連接,我們可以減小Hikari中maxLifetime
的值小于該值,這樣達(dá)到maxLifetime
時Hikari連接池會通過軟驅(qū)逐的方式來主動關(guān)閉該連接,下次就不會獲取到因超時而關(guān)閉的連接,也就不會出現(xiàn)警告了。
彩蛋:Hikari中max-lifetime參數(shù)作用及實(shí)現(xiàn)
該參數(shù)就是用于控制連接池中一個connection的最大存活時間。
Hikari內(nèi)部有一個ScheduledExecutorService
對象houseKeepingExecutorService
,每創(chuàng)建一個連接,就會被封裝成一個PoolEntry
對象,然后放在定時任務(wù)中,定時時間就是設(shè)置的max-lifetime
。只要到達(dá)這個時間就會采取軟驅(qū)逐的方式從池中移除。
除此之外,houseKeepingExecutorService
還用于每隔30s來檢查一次池中的空閑連接、最大連接情況,并維護(hù)池中連接數(shù)的平衡。
何謂軟驅(qū)逐
- 如果這個連接正在被使用,則不立即關(guān)閉連接,但是通過PoolEntry對象中的
private volatile boolean evict;
字段來標(biāo)記為需要關(guān)閉。下次有線程來獲取到這個連接時,發(fā)現(xiàn)evict=true
則調(diào)用異步關(guān)閉方法。重新獲取池中其它的連接。 - 如果這個連接未被使用,則立即調(diào)用異步關(guān)閉連接的方法。
源碼見: com.zaxxer.hikari.pool.HikariPool#createPoolEntry
private PoolEntry createPoolEntry() { try { final PoolEntry poolEntry = newPoolEntry(); final long maxLifetime = config.getMaxLifetime(); if (maxLifetime > 0) { // variance up to 2.5% of the maxlifetime final long variance = maxLifetime > 10_000 ? ThreadLocalRandom.current().nextLong( maxLifetime / 40 ) : 0; final long lifetime = maxLifetime - variance; poolEntry.setFutureEol(houseKeepingExecutorService.schedule( () -> { if (softEvictConnection(poolEntry, "(connection has passed maxLifetime)", false /* not owner */)) { addBagItem(connectionBag.getWaitingThreadCount()); } }, lifetime, MILLISECONDS)); } return poolEntry; } catch (ConnectionSetupException e) { if (poolState == POOL_NORMAL) { // we check POOL_NORMAL to avoid a flood of messages if shutdown() is running concurrently logger.error("{} - Error thrown while acquiring connection from data source", poolName, e.getCause()); lastConnectionFailure.set(e); } } catch (Exception e) { if (poolState == POOL_NORMAL) { // we check POOL_NORMAL to avoid a flood of messages if shutdown() is running concurrently logger.debug("{} - Cannot acquire connection from data source", poolName, e); } } return null; }
總結(jié)
整個問題排查過程中基本把Hikari連接池源碼看完了,也發(fā)現(xiàn)了Hikari內(nèi)部的一些實(shí)現(xiàn)細(xì)節(jié),更多細(xì)節(jié)參見:Hikari 數(shù)據(jù)庫連接池內(nèi)部源碼實(shí)現(xiàn)細(xì)節(jié)
如果Hikari連接池遇到Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl問題注意從下面三個方向排查。
- 1.Hikari連接池的
max-lifetime
(默認(rèn)30分鐘)(對應(yīng)springboot中的spring.datasource.hikari.max-lifetime
)是否大于了MySQL中wait_timeout
和interactive_timeout
(默認(rèn)8小時)。 - 2.檢查MySQL服務(wù)的
/etc/my.cnf
配置文件中wait_timeout
和interactive_timeout
兩個超時時間是否和通過sqlSHOW VARIABLES LIKE '%timeout%'
查出的結(jié)果一致。 - 3.檢查是否和筆者的情況一下,dba為了節(jié)約連接資源,通過腳本定時清理了長時間沒有請求的連接。
以上為個人經(jīng)驗(yàn),希望能給大家一個參考,也希望大家多多支持腳本之家。
相關(guān)文章
SpringMVC如何在生產(chǎn)環(huán)境禁用Swagger的方法
本篇文章主要介紹了SpringMVC如何在生產(chǎn)環(huán)境禁用Swagger的方法,小編覺得挺不錯的,現(xiàn)在分享給大家,也給大家做個參考。一起跟隨小編過來看看吧2018-02-02Filter、Servlet、Listener的學(xué)習(xí)_動力節(jié)點(diǎn)Java學(xué)院整理
這篇文章主要為大家詳細(xì)介紹了Filter、Servlet、Listener的學(xué)習(xí)資料,具有一定的參考價值,感興趣的小伙伴們可以參考一下2017-07-07MyBatis實(shí)現(xiàn)動態(tài)查詢、模糊查詢功能
這篇文章主要介紹了MyBatis實(shí)現(xiàn)動態(tài)查詢、模糊查詢功能,非常不錯,具有一定的參考借鑒價值,需要的朋友可以參考下2018-06-06Java實(shí)現(xiàn)文件復(fù)制及文件夾復(fù)制幾種常用的方式
這篇文章主要給大家介紹了關(guān)于Java實(shí)現(xiàn)文件復(fù)制及文件夾復(fù)制幾種常用的方式,java復(fù)制文件的方式其實(shí)有不少種,文中通過代碼介紹的非常詳細(xì),需要的朋友可以參考下2023-09-09IntelliJ?IDEA2022.3?springboot?熱部署含靜態(tài)文件(最新推薦)
這篇文章主要介紹了IntelliJ?IDEA2022.3?springboot?熱部署含靜態(tài)文件,本文結(jié)合實(shí)例代碼給大家介紹的非常詳細(xì),對大家的學(xué)習(xí)或工作具有一定的參考借鑒價值,需要的朋友可以參考下2023-01-01解決springboot無法注入JpaRepository的問題
這篇文章主要介紹了解決springboot無法注入JpaRepository的問題,具有很好的參考價值,希望對大家有所幫助。一起跟隨小編過來看看吧2021-01-01java算法入門之有效的括號刪除有序數(shù)組中的重復(fù)項實(shí)現(xiàn)strStr
大家好,我是哪吒,一個熱愛編碼的Java工程師,本著"欲速則不達(dá),欲達(dá)則欲速"的學(xué)習(xí)態(tài)度,在程序猿這條不歸路上不斷成長,所謂成長,不過是用時間慢慢擦亮你的眼睛,少時看重的,年長后卻視若鴻毛,少時看輕的,年長后卻視若泰山,成長之路,亦是漸漸放下執(zhí)念,內(nèi)心歸于平靜的旅程2021-08-08