Database connections not closed after idle-timeout in wildfly Datasource
I have an application running under wildfly 8.1 The database connections used in the applications are taken from a Datasource defined in standalone.xml file.
Problem: I don't know why but the Connection from the Pool never goes Idle and are released. Eventually the Pool gets filled will all active Connection and application starts throwing javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/bo/datasource
At the same time when I look at the database, most of the Connections are shown to be idle. (Configuration and result output below)
I have been at this for a week now and have not been able to figure out root cause of this problem. I have also checked all places where a connection is created and have made sure that they are closed afterwards.
What are the other possible places I should be looking into? Or is this a bug (or known issues with Wildfly datasource)?
Wildfly datasource definition:
<subsystem xmlns="urn:jboss:domain:datasources:2.0">
<datasources>
<datasource jndi-name="java:/db/pool" pool-name="DBSource" enabled="true">
<connection-url>jdbc:postgresql://<IP>:5432/DB</connection-url>
<driver>postgres</driver>
<new-connection-sql>select 1</new-connection-sql>
<pool>
<min-pool-size>5</min-pool-size>
<max-pool-size>100</max-pool-size>
</pool>
<security>
<user-name>user</user-name>
<password>password</password>
</security>
<validation>
<check-valid-connection-sql>select 1</check-valid-connection-sql>
<background-validation>true</background-validation>
<background-validation-millis>60000</background-validation-millis>
</validation>
<timeout>
<idle-timeout-minutes>30</idle-timeout-minutes>
</timeout>
<statement>
<track-statements>true</track-statements>
</statement>
</datasource>
<drivers>
<driver name="h2" module="com.h2database.h2">
<xa-datasource-class>org.h2.jdbcx.JdbcDataSource</xa-datasource-class>
</driver>
<driver name="postgres" module="org.postgres">
<driver-class>org.postgresql.Driver</driver-class>
</driver>
</drivers>
</datasources>
</subsystem>
Wildfly datasource pool information:
Command:
/subsystem=datasources/data-source=DBSource/statistics=pool:read-resource(recursive=false,proxies=false,include-runtime=true,include-defaults=true)
Response:
{
"outcome" => "success",
"result" => {
"ActiveCount" => "98",
"AvailableCount" => "55",
"AverageBlockingTime" => "1",
"AverageCreationTime" => "125",
"AverageGetTime" => "27",
"BlockingFailureCount" => "0",
"CreatedCount" => "98",
"DestroyedCount" => "0",
"IdleCount" => "3",
"InUseCount" => "95",
"MaxCreationTime" => "1382",
"MaxGetTime" => "1382",
"MaxUsedCount" => "97",
"MaxWaitCount" => "0",
"MaxWaitTime" => "1",
"TimedOut" => "0",
"TotalBlockingTime" => "71",
"TotalCreationTime" => "12340",
"TotalGetTime" => "12696",
"WaitCount" => "0"
},
"response-headers" => {"process-state" => "reload-required"}
}
PostgreSQL Query Status:
Command:
SELECT datname, pid, usename, waiting, state, (now()-query_start) AS since, (now() - state_change) AS since2, (now() - backend_start) as since3, (now() - xact_start) as since4, query FROM pg_stat_activity ORDER BY datname, state, usename, waiting, query, since, pid;
Response:
datname | pid | usename | waiting | state | since | since2 | since3 | since4 |
---------------+------+------------+---------+---------------------+-----------------+------------------+-----------------+-----------------+-----------------------------------------------------------------------------------------------------------------------------------
BOIEDUDBV13R1 | 4871 | blueoptima | f | active | 00:00:00.176188 | 00:00:00.176179 | 01:37:21.045722 | 00:02:17.212346 | Query-1
BOIEDUDBV13R1 | 4568 | blueoptima | f | active | 00:18:33.035399 | 00:18:33.035395 | 04:25:11.916388 | 00:18:33.473355 | Query-2
BOIEDUDBV13R1 | 4564 | blueoptima | f | active | 00:10:10.599237 | 00:10:10.599232 | 04:25:11.943752 | 00:10:10.915048 | Query-3
BOIEDUDBV13R1 | 4498 | blueoptima | f | active | 00:03:25.861284 | 00:03:25.86128 | 05:09:51.735583 | 00:03:25.861823 | Query-4
BOIEDUDBV13R1 | 4535 | blueoptima | f | active | 00:01:16.612227 | 00:01:16.612222 | 04:34:01.668772 | 00:01:16.614149 | Query-5
BOIEDUDBV13R1 | 4534 | blueoptima | f | idle | 00:00:04.72429 | 00:00:04.683504 | 04:35:21.78966 | | COMMIT
BOIEDUDBV13R1 | 4519 | blueoptima | f | idle | 00:00:12.950041 | 00:00:12.913566 | 04:50:53.698877 | | COMMIT
BOIEDUDBV13R1 | 4438 | blueoptima | f | idle | 00:00:25.82585 | 00:00:25.81036 | 05:34:41.528853 | | COMMIT
BOIEDUDBV13R1 | 4425 | blueoptima | f | idle | 00:09:12.999537 | 00:09:12.9731 | 05:41:51.806148 | | COMMIT
BOIEDUDBV13R1 | 4488 | blueoptima | f | idle | 00:56:04.709316 | 00:56:04.686439 | 05:14:45.445165 | | COMMIT
BOIEDUDBV13R1 | 4501 | blueoptima | f | idle | 00:57:00.615919 | 00:57:00.61589 | 05:06:51.861328 | | COMMIT
BOIEDUDBV13R1 | 4466 | blueoptima | f | idle | 04:11:54.8669 | 04:11:54.516947 | 05:25:03.079741 | | COMMIT
BOIEDUDBV13R1 | 4419 | blueoptima | f | idle | 04:51:03.786294 | 04:51:03.749462 | 05:41:51.814577 | | COMMIT
BOIEDUDBV13R1 | 4340 | blueoptima | f | idle | 04:52:19.772533 | 04:52:19.720537 | 06:31:51.758733 | | COMMIT
BOIEDUDBV13R1 | 4502 | blueoptima | f | idle | 04:54:49.892553 | 04:54:49.85151 | 05:06:51.439101 | | COMMIT
BOIEDUDBV13R1 | 4406 | blueoptima | f | idle | 05:09:20.675009 | 05:09:20.655038 | 06:00:50.160594 | | COMMIT
BOIEDUDBV13R1 | 4489 | blueoptima | f | idle | 05:09:54.785706 | 05:09:54.751723 | 05:14:45.358108 | | COMMIT
BOIEDUDBV13R1 | 4449 | blueoptima | f | idle | 05:16:58.881682 | 05:16:58.88074 | 05:26:50.728973 | | COMMIT
BOIEDUDBV13R1 | 4450 | blueoptima | f | idle | 05:17:23.727614 | 05:17:23.726158 | 05:25:55.116657 | | COMMIT
BOIEDUDBV13R1 | 4465 | blueoptima | f | idle | 05:22:32.475769 | 05:22:32.470301 | 05:25:03.230671 | | COMMIT
BOIEDUDBV13R1 | 4421 | blueoptima | f | idle | 05:25:03.596961 | 05:25:03.596942 | 05:41:51.81487 | | COMMIT
BOIEDUDBV13R1 | 4451 | blueoptima | f | idle | 05:25:29.373092 | 05:25:29.364467 | 05:25:52.433709 | | COMMIT
BOIEDUDBV13R1 | 4448 | blueoptima | f | idle | 05:25:58.729039 | 05:25:58.724453 | 05:26:50.898318 | | COMMIT
BOIEDUDBV13R1 | 4423 | blueoptima | f | idle | 05:26:13.2656 | 05:26:13.263502 | 05:41:51.814528 | | COMMIT
BOIEDUDBV13R1 | 4426 | blueoptima | f | idle | 05:26:58.773981 | 05:26:58.765174 | 05:41:51.179333 | | COMMIT
BOIEDUDBV13R1 | 4415 | blueoptima | f | idle | 05:29:07.123798 | 05:29:07.115682 | 05:47:36.740939 | | COMMIT
BOIEDUDBV13R1 | 4394 | blueoptima | f | idle | 05:42:02.02632 | 05:42:01.994772 | 06:05:54.290575 | | COMMIT
BOIEDUDBV13R1 | 4416 | blueoptima | f | idle | 05:45:52.799303 | 05:45:52.793004 | 05:47:36.701474 | | COMMIT
BOIEDUDBV13R1 | 4408 | blueoptima | f | idle | 05:48:02.635413 | 05:48:02.630767 | 05:54:49.133404 | | COMMIT
BOIEDUDBV13R1 | 4410 | blueoptima | f | idle | 05:49:09.631417 | 05:49:09.624039 | 05:49:47.440347 | | COMMIT
BOIEDUDBV13R1 | 4392 | blueoptima | f | idle | 05:49:45.136111 | 05:49:45.124627 | 06:05:54.52666 | | COMMIT
BOIEDUDBV13R1 | 4411 | blueoptima | f | idle | 05:49:45.208436 | 05:49:45.207393 | 05:49:46.326729 | | COMMIT
BOIEDUDBV13R1 | 4399 | blueoptima | f | idle | 05:50:19.476105 | 05:50:19.465746 | 06:04:53.509647 | | COMMIT
BOIEDUDBV13R1 | 4383 | blueoptima | f | idle | 05:54:04.625364 | 05:54:04.56991 | 06:09:43.004602 | | COMMIT
BOIEDUDBV13R1 | 4382 | blueoptima | f | idle | 05:58:29.615594 | 05:58:29.608542 | 06:09:43.496538 | | COMMIT
BOIEDUDBV13R1 | 4404 | blueoptima | f | idle | 06:00:48.381014 | 06:00:48.379175 | 06:00:50.352202 | | COMMIT
BOIEDUDBV13R1 | 4393 | blueoptima | f | idle | 06:01:49.740445 | 06:01:49.733278 | 06:05:54.468595 | | COMMIT
BOIEDUDBV13R1 | 4379 | blueoptima | f | idle | 06:02:12.00668 | 06:02:12.004878 | 06:11:37.044413 | | COMMIT
BOIEDUDBV13R1 | 4396 | blueoptima | f | idle | 06:02:25.216415 | 06:02:25.202565 | 06:05:10.411017 | | COMMIT
BOIEDUDBV13R1 | 4390 | blueoptima | f | idle | 06:03:48.651868 | 06:03:48.647211 | 06:06:05.443 | | COMMIT
BOIEDUDBV13R1 | 4375 | blueoptima | f | idle | 06:04:51.760968 | 06:04:51.732155 | 06:11:37.545217 | | COMMIT
BOIEDUDBV13R1 | 4353 | blueoptima | f | idle | 06:04:53.302492 | 06:04:53.252345 | 06:25:54.61252 | | COMMIT
BOIEDUDBV13R1 | 4372 | blueoptima | f | idle | 06:05:08.158286 | 06:05:08.137553 | 06:11:49.797186 | | COMMIT
BOIEDUDBV13R1 | 4397 | blueoptima | f | idle | 06:05:08.578854 | 06:05:08.544941 | 06:05:10.298185 | | COMMIT
BOIEDUDBV13R1 | 4377 | blueoptima | f | idle | 06:08:34.443118 | 06:08:34.435299 | 06:11:37.432426 | | COMMIT
BOIEDUDBV13R1 | 4378 | blueoptima | f | idle | 06:11:35.00451 | 06:11:34.946687 | 06:11:37.293523 | | COMMIT
BOIEDUDBV13R1 | 4354 | blueoptima | f | idle | 06:12:01.816625 | 06:12:01.812458 | 06:25:50.247498 | | COMMIT
BOIEDUDBV13R1 | 4344 | blueoptima | f | idle | 06:21:56.439509 | 06:21:56.438739 | 06:31:30.8968 | | COMMIT
BOIEDUDBV13R1 | 4350 | blueoptima | f | idle | 06:22:20.125071 | 06:22:20.11839 | 06:29:37.465565 | | COMMIT
BOIEDUDBV13R1 | 4343 | blueoptima | f | idle | 06:25:59.198819 | 06:25:59.197962 | 06:31:30.901491 | | COMMIT
BOIEDUDBV13R1 | 4351 | blueoptima | f | idle | 06:27:23.950853 | 06:27:23.950081 | 06:29:37.456841 | | COMMIT
BOIEDUDBV13R1 | 4348 | blueoptima | f | idle | 06:27:36.13192 | 06:27:36.131014 | 06:29:37.513979 | | COMMIT
BOIEDUDBV13R1 | 4349 | blueoptima | f | idle | 06:27:42.332901 | 06:27:42.331326 | 06:29:37.491039 | | COMMIT
BOIEDUDBV13R1 | 4352 | blueoptima | f | idle | 06:27:54.031819 | 06:27:54.02966 | 06:29:37.265193 | | COMMIT
BOIEDUDBV13R1 | 4341 | blueoptima | f | idle | 06:28:14.444963 | 06:28:14.444105 | 06:31:31.858728 | | COMMIT
BOIEDUDBV13R1 | 4337 | blueoptima | f | idle | 06:29:20.216685 | 06:29:20.215749 | 06:33:13.450564 | | COMMIT
BOIEDUDBV13R1 | 4346 | blueoptima | f | idle | 06:29:28.524638 | 06:29:28.523906 | 06:30:51.904609 | | COMMIT
BOIEDUDBV13R1 | 4342 | blueoptima | f | idle | 06:29:58.433751 | 06:29:58.432939 | 06:31:31.204896 | | COMMIT
BOIEDUDBV13R1 | 4345 | blueoptima | f | idle | 06:30:28.819691 | 06:30:28.818747 | 06:31:26.849458 | | COMMIT
BOIEDUDBV13R1 | 4355 | blueoptima | f | idle | 06:07:48.953452 | 06:07:48.947655 | 06:25:50.216644 | | INSERT
BOIEDUDBV13R1 | 4409 | blueoptima | f | idle | 05:49:25.452863 | 05:49:25.435483 | 05:49:49.502884 | | INSERT-1
BOIEDUDBV13R1 | 4424 | blueoptima | f | idle | 05:35:44.413808 | 05:35:44.381036 | 05:41:51.814529 | | INSERT-2
BOIEDUDBV13R1 | 4398 | blueoptima | f | idle | 05:36:00.621836 | 05:36:00.598047 | 06:04:53.758915 | | INSERT-3
BOIEDUDBV13R1 | 4417 | blueoptima | f | idle | 05:46:18.096148 | 05:46:18.07272 | 05:47:36.576677 | | INSERT-4
BOIEDUDBV13R1 | 4395 | blueoptima | f | idle | 05:50:44.112353 | 05:50:44.074542 | 06:05:10.557776 | | INSERT-5
BOIEDUDBV13R1 | 4388 | blueoptima | f | idle | 06:05:57.843694 | 06:05:57.832724 | 06:06:06.177483 | | INSERT-6
BOIEDUDBV13R1 | 4339 | blueoptima | f | idle | 06:17:57.460712 | 06:17:57.459716 | 06:33:12.657432 | | INSERT-7
BOIEDUDBV13R1 | 4487 | blueoptima | f | idle | 00:00:15.552081 | 00:00:15.552035 | 05:15:49.047066 | | select 1
BOIEDUDBV13R1 | 4565 | blueoptima | f | idle | 00:00:15.553093 | 00:00:15.553037 | 04:25:11.942656 | | select 1
BOIEDUDBV13R1 | 4420 | blueoptima | f | idle | 00:00:15.554958 | 00:00:15.55493 | 05:41:51.814789 | | select 1
BOIEDUDBV13R1 | 4402 | blueoptima | f | idle | 02:16:15.871078 | 02:16:15.871048 | 06:00:52.663433 | | select 1
BOIEDUDBV13R1 | 4384 | blueoptima | f | idle | 05:38:17.430042 | 05:38:17.43002 | 06:09:42.969186 | | select 1
BOIEDUDBV13R1 | 4412 | blueoptima | f | idle | 05:46:47.263716 | 05:46:47.263518 | 05:49:45.575215 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4414 | blueoptima | f | idle | 05:49:41.773012 | 05:49:41.772712 | 05:49:45.435716 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4405 | blueoptima | f | idle | 05:51:32.2168 | 05:51:32.216636 | 06:00:50.160309 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4400 | blueoptima | f | idle | 05:52:44.966233 | 05:52:44.965626 | 06:02:28.601245 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4401 | blueoptima | f | idle | 06:01:07.430069 | 06:01:07.429643 | 06:02:28.599077 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4389 | blueoptima | f | idle | 06:05:52.187161 | 06:05:52.187081 | 06:06:05.801733 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4376 | blueoptima | f | idle | 06:06:04.447668 | 06:06:04.447527 | 06:11:37.448819 | | SELECT DISTINCT column FROM table
BOIEDUDBV13R1 | 4422 | blueoptima | f | idle | 04:48:59.446162 | 04:48:59.446103 | 05:41:51.814892 | | SELECT
BOIEDUDBV13R1 | 4385 | blueoptima | f | idle | 05:28:13.718473 | 05:28:13.643871 | 06:09:42.799857 | | SELECT
BOIEDUDBV13R1 | 4536 | blueoptima | f | idle | 04:29:42.4528 | 04:29:42.429103 | 04:34:01.664679 | | SELECT
BOIEDUDBV13R1 | 4381 | blueoptima | f | idle | 06:05:51.131506 | 06:05:51.131429 | 06:11:35.758195 | | SELECT
BOIEDUDBV13R1 | 4338 | blueoptima | f | idle | 06:28:31.658157 | 06:28:31.658105 | 06:33:12.953437 | | SELECT
BOIEDUDBV13R1 | 4566 | blueoptima | f | idle | 00:00:25.8479 | 00:00:25.835864 | 04:25:11.94033 | | UPDATE-1
BOIEDUDBV13R1 | 4391 | blueoptima | f | idle | 03:52:25.755736 | 03:52:25.73571 | 06:06:05.300207 | | UPDATE-2
BOIEDUDBV13R1 | 4512 | blueoptima | f | idle | 04:56:03.247543 | 04:56:03.232923 | 04:56:44.188961 | | UPDATE-3
BOIEDUDBV13R1 | 4511 | blueoptima | f | idle | 04:56:34.70146 | 04:56:34.691303 | 04:57:00.191291 | | UPDATE-4
BOIEDUDBV13R1 | 4347 | blueoptima | f | idle | 05:32:30.754975 | 05:32:30.732481 | 06:29:46.312612 | | UPDATE-5
BOIEDUDBV13R1 | 4439 | blueoptima | f | idle | 05:32:55.742867 | 05:32:55.741539 | 05:34:41.519884 | | UPDATE-6
BOIEDUDBV13R1 | 4407 | blueoptima | f | idle | 05:37:36.461115 | 05:37:36.451762 | 05:54:49.133383 | | UPDATE-7
BOIEDUDBV13R1 | 4371 | blueoptima | f | idle | 05:53:02.986092 | 05:53:02.830753 | 06:11:55.240785 | | UPDATE-8
BOIEDUDBV13R1 | 4403 | blueoptima | f | idle | 05:59:57.870442 | 05:59:57.865218 | 06:00:52.646267 | | UPDATE-9
BOIEDUDBV13R1 | 4356 | blueoptima | f | idle | 06:09:18.560294 | 06:09:18.559498 | 06:25:50.216061 | | UPDATE-10
BOIEDUDBV13R1 | 4380 | blueoptima | f | idle | 06:09:38.951985 | 06:09:38.924395 | 06:11:36.494018 | | UPDATE-11
BOIEDUDBV13R1 | 4863 | postgres | f | idle | 01:21:12.135105 | 01:21:12.052383 | 02:01:39.736693 | | select a
| | | | | | | | | ;
BOIEDUDBV13R1 | 4988 | postgres | f | idle | 00:11:16.272964 | 00:11:16.145621 | 00:13:26.234094 | | select b
| | | | | | | | |
BOIEDUDBV13R1 | 4437 | blueoptima | f | idle in transaction | 05:29:11.490837 | 05:29:11.490825 | 05:34:41.52984 | 05:29:11.490949 | select 1
BOIEDUDBV13R1 | 4413 | blueoptima | f | idle in transaction | 05:36:47.417173 | 05:36:47.417148 | 05:49:45.5742 | 05:36:47.417257 | select 1
BOIEDUDBV13R1 | 4567 | blueoptima | f | idle in transaction | 00:49:38.844059 | 00:49:38.844027 | 04:25:11.936358 | 00:49:40.950629 | Query
(100 rows)
Answer
It turns out that Hibernate was holding connection and not releasing them to the Pool. Irrespective of the fact that we are using thread local context. But after adding <property name="hibernate.connection.release_mode">after_transaction</property> to the hibernate config. The problem got solved.
PS: I still dont understand why we need to define this explicitly and why the auto release_mode would not release the connection once the session is closed.