Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

idleTimeout property not working as expected #683

Closed
ehtashamulhaq opened this issue Jul 22, 2016 · 9 comments
Closed

idleTimeout property not working as expected #683

ehtashamulhaq opened this issue Jul 22, 2016 · 9 comments

Comments

@ehtashamulhaq
Copy link

We have following configuration for HikariCP 2.4.7 in our application. ["maximumPoolSize: 30", "minimumIdle: 10" and "idleTimeout: 600000"] The smart network device between our database and application sever have setting TCP idle timeout 15 minutes (900000ms). When our app stays idle (with nobody making requests) during the night, I expect Hikari to close each connection after 10 minutes (+30 sec) after the connection's last request, after the last connection being closed create a new one (and hold it in the pool), and then close and re-create this idle connection every 10 minutes.
The fact is that after an idle period on my app, I see (uppon the next request) the following exception and very long delay in getConnection() method:

WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@5345e00c failed alive test with exception IO Error: Socket read timed out.

Removing following lines from the HikariPool class fixed the issue.

628:               int removable = idleList.size() - config.getMinimumIdle();
629:               if (removable > 0) {
638:                        if (--removable == 0) {
639:                           break; // keep min idle cons
640:                        }
644:               }

Kindly fix this issue either this way or provide some additional configuration property to refresh the minimum idle connections on idleTimeout.

@nitincchauhan
Copy link
Contributor

@ehtashamulhaq Try setting maxLifetime to 15 seconds less than 'device time out' (885000)

@nitincchauhan
Copy link
Contributor

Also, please specify (approx) duration for 'very long delay in getConnection() method'

@ehtashamulhaq
Copy link
Author

aprox 190-200 sec delay. Here is the logs snippet.

16 Jul 2016;03:29:08.078http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@30085296 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:29:27.017http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@158c2b1a failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:29:45.955http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@2561c303 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:30:04.893http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@75ba3115 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:30:23.816http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@67d2d6e5 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:30:42.786http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@798809d9 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:31:01.724http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@746bafe2 failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:31:20.663http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@758f1c1f failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:31:39.617http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@268b4e9d failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:31:58.555http-nio-80-exec-17WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@5345e00c failed alive test with exception IO Error: Socket read timed out
16 Jul 2016;03:32:00.567http-nio-80-exec-17WARN
**********************.HttpRequestTimerFilter /login.do took 191443 ms (or 191.443 seconds!) to process.
*

@nitincchauhan
Copy link
Contributor

If you can turn log level to debug, its not chatty, will give more insight

@ehtashamulhaq
Copy link
Author

19 Jul 2016;09:20:46.729http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:20:46.729http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:20:46.745http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:21:05.543http-nio-80-exec-5WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@7c023fc4 failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:05.543Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@7c023fc4: (connection evicted or dead)
19 Jul 2016;09:21:05.558http-nio-80-exec-5DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.558http-nio-80-exec-5DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.558http-nio-80-exec-5DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.574http-nio-80-exec-8WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@5eb84459 failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:05.574Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@5eb84459: (connection evicted or dead)
19 Jul 2016;09:21:05.574http-nio-80-exec-5DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.589http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.589http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.589http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.605http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.605http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.605http-nio-80-exec-8DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.605http-nio-80-exec-8WARN******************.HttpRequestTimerFilter /secure/versionInformation/doExecute.do?took 19001 ms (or 19.001 seconds!) to process.
19 Jul 2016;09:21:05.652http-nio-80-exec-5DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.667http-nio-80-exec-5WARN**
**********************HttpRequestTimerFilter /secure/versionInformation/doExecute.do? took 19094 ms (or 19.094 seconds!) to process.
19 Jul 2016;09:21:05.699http-nio-80-exec-11WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@4e7471f failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:05.699http-nio-80-exec-6WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@7f1f06d failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:05.699Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@4e7471f: (connection evicted or dead)
19 Jul 2016;09:21:05.699Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@7f1f06d: (connection evicted or dead)
19 Jul 2016;09:21:05.699http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.699http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.699http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.699http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:21:05.699http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:21:05.714http-nio-80-exec-35WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@176592d1 failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:05.714Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@176592d1: (connection evicted or dead)
19 Jul 2016;09:21:05.714http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:21:05.714http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.714http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.714http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.714http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.730http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.730http-nio-80-exec-6DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@7f66acb
19 Jul 2016;09:21:05.730http-nio-80-exec-6WARNcom.nms.webapp.framework.filters.HttpRequestTimerFilter /secure/versionInformation/doExecute.do?CSRF%5FTOKEN=NJVU6UUQF9ZQPYZ1JFM2ZU63M3XK7JV8&operation=getMilestoneTapeouts took 19001 ms (or 19.001 seconds!) to process.
19 Jul 2016;09:21:05.730http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:05.745http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@1d6e9895
19 Jul 2016;09:21:05.745http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@1d6e9895
19 Jul 2016;09:21:05.761http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.761http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.777http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.777http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@1d6e9895
19 Jul 2016;09:21:05.792http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.792http-nio-80-exec-35DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:05.792http-nio-80-exec-35WARNcom.nms.webapp.framework.filters.HttpRequestTimerFilter /secure/versionInformation/doExecute.do?CSRF%5FTOKEN=NJVU6UUQF9ZQPYZ1JFM2ZU63M3XK7JV8&isSpinsFromMilestones=false&operation=getDCVersionTapeouts took 19032 ms (or 19.032 seconds!) to process.
19 Jul 2016;09:21:05.792http-nio-80-exec-11DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@1d6e9895
19 Jul 2016;09:21:05.792http-nio-80-exec-11WARNcom.nms.webapp.framework.filters.HttpRequestTimerFilter /secure/versionInformation/doExecute.do?operation=getAllProcessLibraries&CSRF%5FTOKEN=NJVU6UUQF9ZQPYZ1JFM2ZU63M3XK7JV8 took 19032 ms (or 19.032 seconds!) to process.
19 Jul 2016;09:21:12.219Hikari housekeeper (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolBefore cleanup pool HikariPool-0 stats (total=5, active=1, idle=4, waiting=0)
19 Jul 2016;09:21:12.219Hikari housekeeper (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolAfter cleanup pool HikariPool-0 stats (total=5, active=1, idle=4, waiting=0)
19 Jul 2016;09:21:12.313Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@3dfb57f6
19 Jul 2016;09:21:12.407Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@3b56b256
19 Jul 2016;09:21:12.500Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@38d64a89
19 Jul 2016;09:21:12.594Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@7cb78585
19 Jul 2016;09:21:12.687Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@749f1eba
19 Jul 2016;09:21:12.781Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolHikariPool-0 - Added connection oracle.jdbc.driver.T4CConnection@7a9a8126
19 Jul 2016;09:21:12.781Hikari connection adder (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.HikariPoolAfter adding pool HikariPool-0 stats (total=11, active=1, idle=10, waiting=0)
19 Jul 2016;09:21:16.868http-nio-80-exec-14WARNcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Connection oracle.jdbc.driver.T4CConnection@41f57e06 failed alive test with exception IO Error: Socket read timed out
19 Jul 2016;09:21:16.868Hikari connection closer (pool HikariPool-0)DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Closing connection oracle.jdbc.driver.T4CConnection@41f57e06: (connection evicted or dead)
19 Jul 2016;09:21:16.868http-nio-80-exec-14DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:26.961http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:26.961http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:26.961http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:26.977http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:26.993http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.008http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.008http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.008http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.008http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.024http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.071http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:27.102http-nio-80-exec-18DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@2c419e28
19 Jul 2016;09:21:28.147http-nio-80-exec-17DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.147http-nio-80-exec-17DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.397http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.397http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.397http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.412http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.412http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.428http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.443http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0
19 Jul 2016;09:21:28.443http-nio-80-exec-27DEBUGcom.zaxxer.hikari.pool.PoolBaseHikariPool-0 - Reset (nothing) on connection oracle.jdbc.driver.T4CConnection@79775aa0

@ehtashamulhaq
Copy link
Author

Here is another logs snippet from some previous logs with debug level. I would not able to provide the latest because we fixed this issue by removing the code mentioned above and now its working fine.

@ehtashamulhaq
Copy link
Author

The issue is the idleTimeout occur on our networking device and close the connection but the Hikari not close the connection with specified idleTimeout. The setting maxLifetime to 15 seconds less than 'device time out' wil also solve the problem but it will make negative performance impact when there is much load on application. It will un-necessary close valid connections and recreate them during peak work hours.

@nitincchauhan
Copy link
Contributor

It seems log is not from HikariCP 2.4.7
Thread name changed but it shows: Hikari connection closer (pool HikariPool-0)

Do you set maxLifetime = 0 ?

@brettwooldridge
Copy link
Owner

brettwooldridge commented Jul 22, 2016

@ehtashamulhaq First, this behavior was changed for #379.

Second, setting the maxLifetime to 15 minutes will absolutely not affect performance in any measurable way. If you can measure it, I would like to see before/after metrics that rise above statistical noise.

When you configure a maxLifetime of 15 minutes that is not a "hard limit". HikariCP injects a 2.5% variation into individual connection maximum lifespans. With a lifespan of 15 minutes this amounts to 22.5 seconds variation. So, some connections might retire at 14m38s, others at 14m53s, etc.

After several "generations" the random variation causes the lifespan distribution to spread evenly (statistically) across the 15 minute interval, so that on average 1 connection is retired and replaced every 90s (in the background).

Again, if you can measure a negative impact that is above statistical noise, we would be interested in seeing those measurements.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants