brettwooldridge / HikariCP

光 HikariCP・A solid, high-performance, JDBC connection pool at last.
Apache License 2.0
19.91k stars 2.92k forks source link

Spring Boot + Hikari datasource + MSSql - Connection Pooling - Application instance dies after 2 days #1420

Open satscreate opened 5 years ago

satscreate commented 5 years ago

Problem:

Using spring boot application with hikari configured as below

Hikari Config:

HikariPool-1 - configuration:
allowPoolSuspension.............false
autoCommit......................true
catalog.........................none
connectionInitSql...............none
connectionTestQuery.............none
connectionTimeout...............40000
dataSource......................none
dataSourceClassName.............none
dataSourceJNDI..................none
dataSourceProperties............{password=<masked>}
driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"
healthCheckProperties...........{}
healthCheckRegistry.............none
idleTimeout.....................600000
initializationFailTimeout.......1
isolateInternalQueries..........false
jdbcUrl.........................jdbc:sqlserver://<server>:<port>;databaseName=<database>
leakDetectionThreshold..........0
maxLifetime.....................1200000
maximumPoolSize.................100
metricRegistry..................none
metricsTrackerFactory...........none
minimumIdle.....................100
password........................<masked>
poolName........................"HikariPool-1"
readOnly........................false
registerMbeans..................false
scheduledExecutor...............none
schema..........................none
threadFactory...................internal
transactionIsolation............default
username........................"username"
validationTimeout...............5000

And everything works well with below successful pool status,

HikariPool-1 - Pool stats (total=100, active=0, idle=100, waiting=0)

And every time i access the pool connection it add connection to active and clear back to the same status within seconds.

After 2 to 3 days suddenly application instance getting crashed without any logs in Spring. As i enabled the TRACE mode log in application the last log which shows related to hikari and connection pool as below,

  1. Right exactly from the starting of the spring log, the connection getting dropped from total pool size as below.

    HikariPool-1 - Pool stats (total=99, active=0, idle=99, waiting=0)

    --omitted

    HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)

  2. No trace of kill signal by the way. below is the spring log

Spring.log

 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection adder] DEBUG com.microsoft.sqlserver.jdbc.Driver - ENTRY Arguments not traced.
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN false
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.SQLServerDriver - Property:serverName Value:<servername>
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.SQLServerDriver - Property:portNumber Value:<port>
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY 15,000
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.SQLServerDriver - Property:databaseName Value:<databaseName>
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 created by (SQLServerDriver:1)
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48501): Closing inputStream...
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 Start time: 1564566479298 Time out time: 1564566519298 Timeout Unit Interval: 5000
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48501): Closing outputStream...
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 This attempt server name: <servername> port: <port> InstanceName: null useParallel: false
 [HikariPool-1 connection closer] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48501): Closing TCP socket...
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 This attempt endtime: 1564566484298
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 This attempt No: 0
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 Connecting with server: <servername> port: <port> Timeout slice: 5000 Timeout Full: 40
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601): Opening TCP socket...
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Requesting encryption level:OFF
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f ActivityId 56f3e862-55d1-488c-82f0-1d5b04ce316e-1
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.DATA - /<ip>:<port> SPID:0 ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Prelogin request
   ...C............
--ommited
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.DATA - /<ip>:<port> SPID:0 ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Prelogin response
   ................
   ...............
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Server returned major version:11
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Negotiated encryption level:OFF
 [HikariPool-1 connection adder] DEBUG c.m.s.j.i.SQLServerConnection - ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f Ignoring prelogin response option:5
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) Enabling SSL...
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) SSL handshake will trust any certificate
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) Getting TLS or better SSL context
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) Initializing SSL context
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) Creating SSL socket
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (ProxySocket): Getting input stream
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (ProxySocket): Getting output stream
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) Starting SSL handshake
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyOutputStream@19ee233d Writing 238 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeOutputStream): Starting new TDS packet...
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Writer - TDSWriter@1729dfa8 (ConnectionID:48601) Writing 8 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeOutputStream): Writing 238 bytes...
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Writer - TDSWriter@1729dfa8 (ConnectionID:48601) Writing 238 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyOutputStream@19ee233d Flushing
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeOutputStream): Ignored a request to flush the stream
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream@1dd1b4d8 Reading 5 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeInputStream): Reading 5 bytes...
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeInputStream): No handshake response bytes available. Flushing SSL handshake output stream.
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeOutputStream): Finishing TDS message
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Writer - TDSWriter@1729dfa8 (ConnectionID:48601) Finishing TDS message
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.DATA - /<ip>:<port> SPID:0 TDSWriter@1729dfa8 (ConnectionID:48601) sending packet (246 bytes)
   ................

   m.....
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeInputStream): Reading first packet of SSL handshake response
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.DATA - /<ip>:<port> SPID:0 TDSReader@140283 (ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f) received Packet:1 (2885 bytes)
   ...M........@...

   ...m..\2.....
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Reader - TDSReader@140283 (ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f) Moving to next packet -- unlinking consumed packet
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Reader - TDSReader@140283 (ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f) Reading 5 bytes from offset 0
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream@1dd1b4d8 Read 5 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream@1dd1b4d8 Reading 2880 bytes
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (SSLHandshakeInputStream): Reading 2880 bytes...
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Reader - TDSReader@140283 (ConnectionID:48601 ClientConnectionId: c82d4e67-ad38-4a63-9833-d36d5f75cc8f) Reading 2880 bytes from offset 5
 [HikariPool-1 connection adder] TRACE c.m.s.jdbc.internals.TDS.Channel - com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream@1dd1b4d8 Read 2880 bytes
 [HikariPool-1 connection adder] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48601) (PermissiveX509TrustManager): Trusting server certificate
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566479853; nextExpiration=1564566479853; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566506164; nextExpiration=1564566506164; keyCount=0; hasEvents=false; eval=false
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - Start expire sessions StandardManager at 1564566506252 sessioncount 0
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - End expire sessions StandardManager processingTime 0 expired sessions: 0
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566506853; nextExpiration=1564566506853; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566566220; nextExpiration=1564566566220; keyCount=0; hasEvents=false; eval=false
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - Start expire sessions StandardManager at 1564566566260 sessioncount 0
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - End expire sessions StandardManager processingTime 0 expired sessions: 0
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566506164; nextExpiration=1564566506164; keyCount=0; hasEvents=false; eval=false
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - Start expire sessions StandardManager at 1564566506252 sessioncount 0
 [ContainerBackgroundProcessor[StandardEngine[Tomcat]]] DEBUG o.a.catalina.session.ManagerBase - End expire sessions StandardManager processingTime 0 expired sessions: 0
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566506853; nextExpiration=1564566506853; keyCount=0; hasEvents=false; eval=false
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN false
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY 15,000
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48503): Closing inputStream...
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48503): Closing outputStream...
 [HikariPool-1 connection closer] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48503): Closing TCP socket...
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566655887; nextExpiration=1564566655887; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=6; now=1564566656240; nextExpiration=1564566656240; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=9; now=1564566734965; nextExpiration=1564566734965; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=9; now=1564566735952; nextExpiration=1564566735952; keyCount=0; hasEvents=false; eval=false
 [https-jsse-nio-8012-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=9; now=1564566735965; nextExpiration=1564566735965; keyCount=0; hasEvents=false; eval=false
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN false
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY 15,000
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - ENTRY
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48507): Closing inputStream...
 [HikariPool-1 connection closer] TRACE c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48507): Closing outputStream...
 [HikariPool-1 connection closer] DEBUG c.m.s.jdbc.internals.TDS.Channel - TDSChannel (ConnectionID:48507): Closing TCP socket...
 [HikariPool-1 connection closer] DEBUG c.m.sqlserver.jdbc.Connection - RETURN
 [https-jsse-nio-8012-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=9; now=1564566736952; nextExpiration=1564566736952; keyCount=0; hasEvents=false; eval=false

What must be wrong in this process? And why this sql connection logs above shows like closing a socket? and why did hikari suddenly dropping the connections and tomcat process also dies. Please help.

jxin19 commented 4 years ago

did u changed set maxLifetime?

satscreate commented 4 years ago

did u changed set maxLifetime?

I kept it as default every properties, as below,

HikariPool-1 - configuration: allowPoolSuspension.............false autoCommit......................true catalog.........................none connectionInitSql...............none connectionTestQuery.............none connectionTimeout...............30000 dataSource......................none dataSourceClassName.............none dataSourceJNDI..................none dataSourceProperties............{password=} driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver" healthCheckProperties...........{} healthCheckRegistry.............none idleTimeout.....................600000 initializationFailTimeout.......1 isolateInternalQueries..........false jdbcUrl.........................jdbc:sqlserver://:;databaseName=dbname leakDetectionThreshold..........0 maxLifetime.....................1800000 maximumPoolSize.................10 metricRegistry..................none metricsTrackerFactory...........none minimumIdle.....................10 password........................ poolName........................"HikariPool-1" readOnly........................false registerMbeans..................false scheduledExecutor...............none schema..........................none threadFactory...................internal transactionIsolation............default username........................"sampleusername" validationTimeout...............5000

brettwooldridge commented 3 years ago

Can you get a thread dump while the pool population is in the process of declining?