Idle In transaction after select statement using Postgres and Hibernate(Grails)

Question

I am using Grails 1.3.7 connected to Postgres 8.4 We are running some functional tests of our application and we ran into a problem. After few minutes all of the connections we have to the database are In Transaction and requests are timing out. I've tried determining what is going on using query from Ghostwritten Insomnia and all I got were some Exclusive Locks and Access Share Locks. According to Postgres Docs they work together and there should be nothing special about them. Well nothing special apart from the fact they stay on until I restart Tomcat or kill connections. I've enabled logging and tried to analyze them as described by Depesz on his blog but I have found no long running statements. I was able to determine last statements of the connections which are Idle in transaction, and it was a simple select, what more - it was finished fine [at least so the logs say].

2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) LOG:  duration: 0.111 ms  parse <unnamed>: select questdefin0_.id as id23_0_, questdefin0_.version as version23_0_, questdefin0_.cev_from as cev3_23_0_, questdefin0_.cev_to as cev4_23_0_, questdefin0_.description as descript5_23_0_, questdefin0_.duration as duration23_0_, questdefin0_.level_from as level7_23_0_, questdefin0_.level_to as level8_23_0_, questdefin0_.name as name23_0_, questdefin0_.pack_id as pack10_23_0_, questdefin0_.type as type23_0_, questdefin0_.travel_zone_id as travel13_23_0_, questdefin0_.class as class23_0_ from quest_definition questdefin0_ where questdefin0_.id=$1
2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) LOG:  duration: 0.095 ms  bind <unnamed>: select questdefin0_.id as id23_0_, questdefin0_.version as version23_0_, questdefin0_.cev_from as cev3_23_0_, questdefin0_.cev_to as cev4_23_0_, questdefin0_.description as descript5_23_0_, questdefin0_.duration as duration23_0_, questdefin0_.level_from as level7_23_0_, questdefin0_.level_to as level8_23_0_, questdefin0_.name as name23_0_, questdefin0_.pack_id as pack10_23_0_, questdefin0_.type as type23_0_, questdefin0_.travel_zone_id as travel13_23_0_, questdefin0_.class as class23_0_ from quest_definition questdefin0_ where questdefin0_.id=$1
2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) DETAIL:  parameters: $1 = '17935'
2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) LOG:  execute <unnamed>: select questdefin0_.id as id23_0_, questdefin0_.version as version23_0_, questdefin0_.cev_from as cev3_23_0_, questdefin0_.cev_to as cev4_23_0_, questdefin0_.description as descript5_23_0_, questdefin0_.duration as duration23_0_, questdefin0_.level_from as level7_23_0_, questdefin0_.level_to as level8_23_0_, questdefin0_.name as name23_0_, questdefin0_.pack_id as pack10_23_0_, questdefin0_.type as type23_0_, questdefin0_.travel_zone_id as travel13_23_0_, questdefin0_.class as class23_0_ from quest_definition questdefin0_ where questdefin0_.id=$1
2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) DETAIL:  parameters: $1 = '17935'
2012-01-03 21:02:57.397 CET ogsuser@ogs 4294 127.0.0.1(34282) LOG:  duration: 0.052 ms

I went through the logfiles of postgres looking for other queries with id 17935 but I didn't find anything suspicious. And nothing at the same [or similar] time as this query.

I've checked all of the IDLE In Transaction connections and I have found that all of them had the same last statement executed as the last one. Most of them had different IDs, few had the same, but they were executed in a very different moment, so I doubt this is the root cause.

I've also checked logs on Tomcat. Nothing special there. The last thing done is the hibernate query and then nothing else.

I've checked connection pool settings, it checks the connection after release and when idle to be sure that connections are ok.

I've restarted tomcat and run the test again. After few minutes I ended up with all connections IDLE in transaction. This time different queries, again nothing I would consider weird. Just a simple select statement.

So.. now the question part. Is there anything obvious I am missing? Some easy fix I could apply, setting or something... I am not sure where should I go now with this, what is the next step I should take to solve it.

EDIT: To make things clear. This is a grails app deployed on tomcat. We are using controller actions as "REST like" endpoints. Integration and unit tests run fine. We are doing functional tests at the moment using Soapui and 5 threads running a simple scenario, simulating user behavior.

Answer 1

Ok.. so after 2 days of agony we have managed to figure this thing out. It seems that when using HSQLDB our settings were too limited to find this, that's why it only happened under Postgres. The issue was with bean pooling configured in spring. I am not sure what's wrong with it, since it's a simple configuration, basically copy & paste from spring documentation, but after changing the code to get the object bypassing pool everything seems fine.