You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomee.apache.org by Emmanuel Touzery <em...@lit-transit.com> on 2021/01/19 10:05:03 UTC
connection pool: poisoned connection not being removed from pool
Hello,
we are seeing with our TOMEE setup that a connection that was
(potentially uncleanly) closed from the SQL server remains in the pool
for longer periods (instead of being closed+reopened), causing long-term
issues with the application, which we can only fix through a restart.
A scenario where we see this clearly are failovers: in that case
the currently open connections will become invalid, which the
application should realise quickly enough through the validation
queries, therefore quickly cleaning up the pool (trying to establish a
new connection would work, except in the first few hundreds of
milliseconds of the event). But that's not what we see. We also see
situation where something happens to the SQL server (for instance it's
restarted), or the connection from TOMEE to the SQL server is disrupted,
but the application never recovers until TOMEE is restarted.
Here is our resource, as defined in the tomee.xml:
<Resource id="jdbc/generic" type="javax.sql.DataSource">
jdbcDriver = org.postgresql.Driver
jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
userName = xxxxxx
password = xxxxxx
maxActive = 140
maxIdle = 20
validationQuery = select version();
testWhileIdle = true
testOnBorrow = true
testOnReturn = false
timeBetweenEvictionRuns = 10000 millisecond
removeAbandonedTimeout = 4400
removeAbandoned = true
maxWaitTime = 30000 millisecond
</Resource>
We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
upgraded from 5.2.12 recently, had the issue with that version too).
Is there anything else we should do to make sure that we properly
recover when something happens to some connections from the pool?
Thank you!
Emmanuel
PS: Some relevant sections of the stacktraces we're seeing for longer
period of times after the event:
Caused by: javax.persistence.PersistenceException:
org.hibernate.exception.JDBCConnectionException: could not prepare
statement
at
org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
at
org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
at org.hibernate.query.Query.getResultList(Query.java:165)
Caused by: org.postgresql.util.PSQLException: This connection
has been closed.
at
org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
at
org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
at
org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
at
jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
at com.sun.proxy.$Proxy257.prepareStatement(Unknown
Source)
at
jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
at
org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
at com.sun.proxy.$Proxy256.prepareStatement(Unknown
Source)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
... 88 more
Re: connection pool: poisoned connection not being removed from pool
Posted by Emmanuel Touzery <em...@lit-transit.com>.
Hello,
I have enabled also "logAbandoned" and I see some connections are
getting abandoned:
22-Jan-2021 10:55:34.306 WARNING [Tomcat JDBC Pool
Cleaner[54495403:1611312334268]]
org.apache.tomcat.jdbc.pool.ConnectionPool.abandon Connection has been
abandoned
PooledConnection[org.postgresql.jdbc.PgConnection@28094e6f]:java.lang.Exception
However right now I triggered the issue and no connections are
getting abandoned even after 12 minutes, and I can see that the
application won't recover until it's restarted.
Any suggestion?
Thank you,
Emmanuel
PS: the way i'm reading the "removeAbandoned" documentation, shouldn't
this setting be named "removeLongRunningConnections"?
On 22/01/2021 11:28, Emmanuel Touzery wrote:
> Hello,
>
> Note that also setting:
>
> removeAbandoned = true
> removeAbandonedTimeout = 60
>
> does not help. Even 6 minutes after the the disconnection, we keep
> getting "PooledConnection has already been closed." exceptions.
>
> Regards,
>
> Emmanuel
>
> On 22/01/2021 09:48, Emmanuel Touzery wrote:
>> Hello,
>>
>> if I understand you correctly, you're suggesting to remove these
>> settings:
>>
>> removeAbandoned = true
>> removeAbandonedTimeout = 4400
>>
>> I did that now, we don't really need them. Unfortunately I can
>> still reproduce the issue even after removing both settings.
>>
>> We are aware of the memory leak yes, we stumbled on it before a
>> released version of tomee fixed it, so we disabled bean validation.
>> We'll reenable it when we upgrade TOMEE.
>>
>> So that means for now we're still unsure what's causing this
>> issue for us :-(
>>
>> Thank you!
>>
>> Emmanuel
>>
>> On 19/01/2021 19:18, Kean Erickson wrote:
>>> Hi Emmanual, I believe that is how connections that were discarded
>>> due to
>>> removeAbandoned = true. In an ideal setup you shouldnt need that
>>> flag or
>>> its timeout, becaise the transactions should be too fast to go that
>>> long
>>>
>>> Also some versions before tomee 8.0.5 have a memory leak in the
>>> version of
>>> bval that is used. Not sure if 8.0.1 has that problem version but try
>>> updatng tomee to 8.0.5
>>>
>>> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
>>> emmanuel.touzery@lit-transit.com> wrote:
>>>
>>>> Hello,
>>>>
>>>> we are seeing with our TOMEE setup that a connection that was
>>>> (potentially uncleanly) closed from the SQL server remains in the pool
>>>> for longer periods (instead of being closed+reopened), causing
>>>> long-term
>>>> issues with the application, which we can only fix through a restart.
>>>>
>>>> A scenario where we see this clearly are failovers: in that case
>>>> the currently open connections will become invalid, which the
>>>> application should realise quickly enough through the validation
>>>> queries, therefore quickly cleaning up the pool (trying to establish a
>>>> new connection would work, except in the first few hundreds of
>>>> milliseconds of the event). But that's not what we see. We also see
>>>> situation where something happens to the SQL server (for instance it's
>>>> restarted), or the connection from TOMEE to the SQL server is
>>>> disrupted,
>>>> but the application never recovers until TOMEE is restarted.
>>>>
>>>> Here is our resource, as defined in the tomee.xml:
>>>>
>>>> <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>>> jdbcDriver = org.postgresql.Driver
>>>> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>>> userName = xxxxxx
>>>> password = xxxxxx
>>>> maxActive = 140
>>>> maxIdle = 20
>>>> validationQuery = select version();
>>>> testWhileIdle = true
>>>> testOnBorrow = true
>>>> testOnReturn = false
>>>> timeBetweenEvictionRuns = 10000 millisecond
>>>> removeAbandonedTimeout = 4400
>>>> removeAbandoned = true
>>>> maxWaitTime = 30000 millisecond
>>>> </Resource>
>>>>
>>>> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27
>>>> (we
>>>> upgraded from 5.2.12 recently, had the issue with that version too).
>>>>
>>>> Is there anything else we should do to make sure that we
>>>> properly
>>>> recover when something happens to some connections from the pool?
>>>>
>>>> Thank you!
>>>>
>>>> Emmanuel
>>>>
>>>> PS: Some relevant sections of the stacktraces we're seeing for longer
>>>> period of times after the event:
>>>>
>>>> Caused by: javax.persistence.PersistenceException:
>>>> org.hibernate.exception.JDBCConnectionException: could not prepare
>>>> statement
>>>> at
>>>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>>>
>>>>
>>>>
>>>> at
>>>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>>>
>>>>
>>>>
>>>> at
>>>> org.hibernate.query.Query.getResultList(Query.java:165)
>>>>
>>>>
>>>> Caused by: org.postgresql.util.PSQLException: This
>>>> connection
>>>> has been closed.
>>>> at
>>>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>>> at
>>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>>>
>>>> at
>>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>>>
>>>> at
>>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>> at
>>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>>
>>>>
>>>>
>>>> at
>>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>> at
>>>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>>>
>>>>
>>>>
>>>> at
>>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>>
>>>>
>>>>
>>>> at
>>>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>>>
>>>>
>>>>
>>>> at
>>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>>
>>>>
>>>>
>>>> at
>>>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>>>
>>>>
>>>>
>>>> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>>>> Source)
>>>> at
>>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>> at
>>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>>
>>>>
>>>>
>>>> at
>>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>> at
>>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>>>
>>>>
>>>>
>>>> at
>>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>>>
>>>>
>>>>
>>>> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>>>> Source)
>>>> at
>>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>>>
>>>>
>>>>
>>>> at
>>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>>>
>>>>
>>>>
>>>> ... 88 more
>>>>
>>>>
>>
>
Re: connection pool: poisoned connection not being removed from pool
Posted by Emmanuel Touzery <em...@lit-transit.com>.
Hello,
Note that also setting:
removeAbandoned = true
removeAbandonedTimeout = 60
does not help. Even 6 minutes after the the disconnection, we keep
getting "PooledConnection has already been closed." exceptions.
Regards,
Emmanuel
On 22/01/2021 09:48, Emmanuel Touzery wrote:
> Hello,
>
> if I understand you correctly, you're suggesting to remove these
> settings:
>
> removeAbandoned = true
> removeAbandonedTimeout = 4400
>
> I did that now, we don't really need them. Unfortunately I can
> still reproduce the issue even after removing both settings.
>
> We are aware of the memory leak yes, we stumbled on it before a
> released version of tomee fixed it, so we disabled bean validation.
> We'll reenable it when we upgrade TOMEE.
>
> So that means for now we're still unsure what's causing this issue
> for us :-(
>
> Thank you!
>
> Emmanuel
>
> On 19/01/2021 19:18, Kean Erickson wrote:
>> Hi Emmanual, I believe that is how connections that were discarded
>> due to
>> removeAbandoned = true. In an ideal setup you shouldnt need that flag or
>> its timeout, becaise the transactions should be too fast to go that long
>>
>> Also some versions before tomee 8.0.5 have a memory leak in the
>> version of
>> bval that is used. Not sure if 8.0.1 has that problem version but try
>> updatng tomee to 8.0.5
>>
>> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
>> emmanuel.touzery@lit-transit.com> wrote:
>>
>>> Hello,
>>>
>>> we are seeing with our TOMEE setup that a connection that was
>>> (potentially uncleanly) closed from the SQL server remains in the pool
>>> for longer periods (instead of being closed+reopened), causing
>>> long-term
>>> issues with the application, which we can only fix through a restart.
>>>
>>> A scenario where we see this clearly are failovers: in that case
>>> the currently open connections will become invalid, which the
>>> application should realise quickly enough through the validation
>>> queries, therefore quickly cleaning up the pool (trying to establish a
>>> new connection would work, except in the first few hundreds of
>>> milliseconds of the event). But that's not what we see. We also see
>>> situation where something happens to the SQL server (for instance it's
>>> restarted), or the connection from TOMEE to the SQL server is
>>> disrupted,
>>> but the application never recovers until TOMEE is restarted.
>>>
>>> Here is our resource, as defined in the tomee.xml:
>>>
>>> <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>> jdbcDriver = org.postgresql.Driver
>>> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>> userName = xxxxxx
>>> password = xxxxxx
>>> maxActive = 140
>>> maxIdle = 20
>>> validationQuery = select version();
>>> testWhileIdle = true
>>> testOnBorrow = true
>>> testOnReturn = false
>>> timeBetweenEvictionRuns = 10000 millisecond
>>> removeAbandonedTimeout = 4400
>>> removeAbandoned = true
>>> maxWaitTime = 30000 millisecond
>>> </Resource>
>>>
>>> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>>> upgraded from 5.2.12 recently, had the issue with that version too).
>>>
>>> Is there anything else we should do to make sure that we properly
>>> recover when something happens to some connections from the pool?
>>>
>>> Thank you!
>>>
>>> Emmanuel
>>>
>>> PS: Some relevant sections of the stacktraces we're seeing for longer
>>> period of times after the event:
>>>
>>> Caused by: javax.persistence.PersistenceException:
>>> org.hibernate.exception.JDBCConnectionException: could not prepare
>>> statement
>>> at
>>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>>
>>>
>>>
>>> at
>>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>>
>>>
>>>
>>> at
>>> org.hibernate.query.Query.getResultList(Query.java:165)
>>>
>>>
>>> Caused by: org.postgresql.util.PSQLException: This connection
>>> has been closed.
>>> at
>>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>> at
>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>>
>>> at
>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>>
>>> at
>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>> at
>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>
>>>
>>>
>>> at
>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>> at
>>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>>
>>>
>>>
>>> at
>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>
>>>
>>>
>>> at
>>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>>
>>>
>>>
>>> at
>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>
>>>
>>>
>>> at
>>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>>
>>>
>>>
>>> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>>> Source)
>>> at
>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>> at
>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>
>>>
>>>
>>> at
>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>> at
>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>>
>>>
>>>
>>> at
>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>>
>>>
>>>
>>> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>>> Source)
>>> at
>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>>
>>>
>>>
>>> at
>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>>
>>>
>>>
>>> ... 88 more
>>>
>>>
>
Re: connection pool: poisoned connection not being removed from pool
Posted by Emmanuel Touzery <em...@lit-transit.com>.
Hello,
if I understand you correctly, you're suggesting to remove these
settings:
removeAbandoned = true
removeAbandonedTimeout = 4400
I did that now, we don't really need them. Unfortunately I can
still reproduce the issue even after removing both settings.
We are aware of the memory leak yes, we stumbled on it before a
released version of tomee fixed it, so we disabled bean validation.
We'll reenable it when we upgrade TOMEE.
So that means for now we're still unsure what's causing this issue
for us :-(
Thank you!
Emmanuel
On 19/01/2021 19:18, Kean Erickson wrote:
> Hi Emmanual, I believe that is how connections that were discarded due to
> removeAbandoned = true. In an ideal setup you shouldnt need that flag or
> its timeout, becaise the transactions should be too fast to go that long
>
> Also some versions before tomee 8.0.5 have a memory leak in the version of
> bval that is used. Not sure if 8.0.1 has that problem version but try
> updatng tomee to 8.0.5
>
> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
> emmanuel.touzery@lit-transit.com> wrote:
>
>> Hello,
>>
>> we are seeing with our TOMEE setup that a connection that was
>> (potentially uncleanly) closed from the SQL server remains in the pool
>> for longer periods (instead of being closed+reopened), causing long-term
>> issues with the application, which we can only fix through a restart.
>>
>> A scenario where we see this clearly are failovers: in that case
>> the currently open connections will become invalid, which the
>> application should realise quickly enough through the validation
>> queries, therefore quickly cleaning up the pool (trying to establish a
>> new connection would work, except in the first few hundreds of
>> milliseconds of the event). But that's not what we see. We also see
>> situation where something happens to the SQL server (for instance it's
>> restarted), or the connection from TOMEE to the SQL server is disrupted,
>> but the application never recovers until TOMEE is restarted.
>>
>> Here is our resource, as defined in the tomee.xml:
>>
>> <Resource id="jdbc/generic" type="javax.sql.DataSource">
>> jdbcDriver = org.postgresql.Driver
>> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>> userName = xxxxxx
>> password = xxxxxx
>> maxActive = 140
>> maxIdle = 20
>> validationQuery = select version();
>> testWhileIdle = true
>> testOnBorrow = true
>> testOnReturn = false
>> timeBetweenEvictionRuns = 10000 millisecond
>> removeAbandonedTimeout = 4400
>> removeAbandoned = true
>> maxWaitTime = 30000 millisecond
>> </Resource>
>>
>> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>> upgraded from 5.2.12 recently, had the issue with that version too).
>>
>> Is there anything else we should do to make sure that we properly
>> recover when something happens to some connections from the pool?
>>
>> Thank you!
>>
>> Emmanuel
>>
>> PS: Some relevant sections of the stacktraces we're seeing for longer
>> period of times after the event:
>>
>> Caused by: javax.persistence.PersistenceException:
>> org.hibernate.exception.JDBCConnectionException: could not prepare
>> statement
>> at
>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>
>>
>> at
>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>
>>
>> at org.hibernate.query.Query.getResultList(Query.java:165)
>>
>>
>> Caused by: org.postgresql.util.PSQLException: This connection
>> has been closed.
>> at
>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>> at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>> at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>> at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>> at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>> at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>> at
>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>
>>
>> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>> Source)
>> at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>> at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>> at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>> at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>
>>
>> at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>
>>
>> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>> Source)
>> at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>
>>
>> at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>
>>
>> ... 88 more
>>
>>
Re: connection pool: poisoned connection not being removed from pool
Posted by Kean Erickson <ke...@gmail.com>.
Hi Emmanual, I believe that is how connections that were discarded due to
removeAbandoned = true. In an ideal setup you shouldnt need that flag or
its timeout, becaise the transactions should be too fast to go that long
Also some versions before tomee 8.0.5 have a memory leak in the version of
bval that is used. Not sure if 8.0.1 has that problem version but try
updatng tomee to 8.0.5
On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
emmanuel.touzery@lit-transit.com> wrote:
> Hello,
>
> we are seeing with our TOMEE setup that a connection that was
> (potentially uncleanly) closed from the SQL server remains in the pool
> for longer periods (instead of being closed+reopened), causing long-term
> issues with the application, which we can only fix through a restart.
>
> A scenario where we see this clearly are failovers: in that case
> the currently open connections will become invalid, which the
> application should realise quickly enough through the validation
> queries, therefore quickly cleaning up the pool (trying to establish a
> new connection would work, except in the first few hundreds of
> milliseconds of the event). But that's not what we see. We also see
> situation where something happens to the SQL server (for instance it's
> restarted), or the connection from TOMEE to the SQL server is disrupted,
> but the application never recovers until TOMEE is restarted.
>
> Here is our resource, as defined in the tomee.xml:
>
> <Resource id="jdbc/generic" type="javax.sql.DataSource">
> jdbcDriver = org.postgresql.Driver
> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
> userName = xxxxxx
> password = xxxxxx
> maxActive = 140
> maxIdle = 20
> validationQuery = select version();
> testWhileIdle = true
> testOnBorrow = true
> testOnReturn = false
> timeBetweenEvictionRuns = 10000 millisecond
> removeAbandonedTimeout = 4400
> removeAbandoned = true
> maxWaitTime = 30000 millisecond
> </Resource>
>
> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
> upgraded from 5.2.12 recently, had the issue with that version too).
>
> Is there anything else we should do to make sure that we properly
> recover when something happens to some connections from the pool?
>
> Thank you!
>
> Emmanuel
>
> PS: Some relevant sections of the stacktraces we're seeing for longer
> period of times after the event:
>
> Caused by: javax.persistence.PersistenceException:
> org.hibernate.exception.JDBCConnectionException: could not prepare
> statement
> at
> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>
>
> at
> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>
>
> at org.hibernate.query.Query.getResultList(Query.java:165)
>
>
> Caused by: org.postgresql.util.PSQLException: This connection
> has been closed.
> at
> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
> at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
> at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
> at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
> at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>
>
> at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
> at
> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>
>
> at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
> at
> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>
>
> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
> Source)
> at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
> at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>
>
> at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>
>
> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
> Source)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>
>
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>
>
> ... 88 more
>
>
Re: connection pool: poisoned connection not being removed from pool
Posted by Emmanuel Touzery <em...@lit-transit.com>.
Hello,
I have to say it's not necessarily about the failover. We can also
see this if there is something wrong with the connection to the server.
I believe including if the SQL server is restarted.
My understanding is that it's normal that there is an error, but I
would expect TOMEE to recover -- to stop handling to the application a
JDBC connection which is in fact closed and has shown itself in the past
to be invalid. Especially since we configure a validation query.
This is otherwise Enterprise DB 12. My understanding is that it's
mostly a rebranded Postgresql. We are using the normal postgresql
driver, although an older version (we didn't try a newer version,
assuming that's not related to the issue at hand). We're using the
postgresql jdbc driver version 42.1.4.
For the failover, we're using EFM:
https://www.enterprisedb.com/edb-docs/d/edb-postgres-failover-manager/user-guides/user-guide/3.7/using_efm_utility.html
There is a "virtual IP" that we connect to through JDBC, and it
links to one or the other true IP, over 3 EDB nodes.
We actually don't get an issue at every switchover. Even load
testing the app (with a relatively light load though), we need ~4
failovers to reproduce the issue. Meaning, an OK failover means that we
get JDBC errors during the failover, but then the application recovers.
A bad failover is when we keep getting errors long after the failover
finished. I think it's tied to whether we had a compromised connection
in the pool before the failover.
Thank you for the answer!
Emmanuel
On 19/01/2021 13:26, Jonathan Gallimore wrote:
> Sounds like you're using TomEE 8 and Postgres (can you specify the version
> of Postgres and the JDBC driver?)
>
> Can we get a bit more detail on the "failover" element - is this a failover
> to a secondary database node? Are the database nodes you connect to
> specified in the JDBC URI, or do you have a loadbalancer/proxy that is
> shifting the connections across?
>
> I'd like to reproduce and find out what's going on.
>
> Jon
>
> On Tue, Jan 19, 2021 at 10:05 AM Emmanuel Touzery <
> emmanuel.touzery@lit-transit.com> wrote:
>
>> Hello,
>>
>> we are seeing with our TOMEE setup that a connection that was
>> (potentially uncleanly) closed from the SQL server remains in the pool
>> for longer periods (instead of being closed+reopened), causing long-term
>> issues with the application, which we can only fix through a restart.
>>
>> A scenario where we see this clearly are failovers: in that case
>> the currently open connections will become invalid, which the
>> application should realise quickly enough through the validation
>> queries, therefore quickly cleaning up the pool (trying to establish a
>> new connection would work, except in the first few hundreds of
>> milliseconds of the event). But that's not what we see. We also see
>> situation where something happens to the SQL server (for instance it's
>> restarted), or the connection from TOMEE to the SQL server is disrupted,
>> but the application never recovers until TOMEE is restarted.
>>
>> Here is our resource, as defined in the tomee.xml:
>>
>> <Resource id="jdbc/generic" type="javax.sql.DataSource">
>> jdbcDriver = org.postgresql.Driver
>> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>> userName = xxxxxx
>> password = xxxxxx
>> maxActive = 140
>> maxIdle = 20
>> validationQuery = select version();
>> testWhileIdle = true
>> testOnBorrow = true
>> testOnReturn = false
>> timeBetweenEvictionRuns = 10000 millisecond
>> removeAbandonedTimeout = 4400
>> removeAbandoned = true
>> maxWaitTime = 30000 millisecond
>> </Resource>
>>
>> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>> upgraded from 5.2.12 recently, had the issue with that version too).
>>
>> Is there anything else we should do to make sure that we properly
>> recover when something happens to some connections from the pool?
>>
>> Thank you!
>>
>> Emmanuel
>>
>> PS: Some relevant sections of the stacktraces we're seeing for longer
>> period of times after the event:
>>
>> Caused by: javax.persistence.PersistenceException:
>> org.hibernate.exception.JDBCConnectionException: could not prepare
>> statement
>> at
>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>
>>
>> at
>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>
>>
>> at org.hibernate.query.Query.getResultList(Query.java:165)
>>
>>
>> Caused by: org.postgresql.util.PSQLException: This connection
>> has been closed.
>> at
>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>> at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>> at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>> at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>> at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>> at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>> at
>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>> at
>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>
>>
>> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>> Source)
>> at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>> at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>> at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>> at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>
>>
>> at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>
>>
>> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>> Source)
>> at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>
>>
>> at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>
>>
>> ... 88 more
>>
>>
Re: connection pool: poisoned connection not being removed from pool
Posted by Jonathan Gallimore <jo...@gmail.com>.
Sounds like you're using TomEE 8 and Postgres (can you specify the version
of Postgres and the JDBC driver?)
Can we get a bit more detail on the "failover" element - is this a failover
to a secondary database node? Are the database nodes you connect to
specified in the JDBC URI, or do you have a loadbalancer/proxy that is
shifting the connections across?
I'd like to reproduce and find out what's going on.
Jon
On Tue, Jan 19, 2021 at 10:05 AM Emmanuel Touzery <
emmanuel.touzery@lit-transit.com> wrote:
> Hello,
>
> we are seeing with our TOMEE setup that a connection that was
> (potentially uncleanly) closed from the SQL server remains in the pool
> for longer periods (instead of being closed+reopened), causing long-term
> issues with the application, which we can only fix through a restart.
>
> A scenario where we see this clearly are failovers: in that case
> the currently open connections will become invalid, which the
> application should realise quickly enough through the validation
> queries, therefore quickly cleaning up the pool (trying to establish a
> new connection would work, except in the first few hundreds of
> milliseconds of the event). But that's not what we see. We also see
> situation where something happens to the SQL server (for instance it's
> restarted), or the connection from TOMEE to the SQL server is disrupted,
> but the application never recovers until TOMEE is restarted.
>
> Here is our resource, as defined in the tomee.xml:
>
> <Resource id="jdbc/generic" type="javax.sql.DataSource">
> jdbcDriver = org.postgresql.Driver
> jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
> userName = xxxxxx
> password = xxxxxx
> maxActive = 140
> maxIdle = 20
> validationQuery = select version();
> testWhileIdle = true
> testOnBorrow = true
> testOnReturn = false
> timeBetweenEvictionRuns = 10000 millisecond
> removeAbandonedTimeout = 4400
> removeAbandoned = true
> maxWaitTime = 30000 millisecond
> </Resource>
>
> We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
> upgraded from 5.2.12 recently, had the issue with that version too).
>
> Is there anything else we should do to make sure that we properly
> recover when something happens to some connections from the pool?
>
> Thank you!
>
> Emmanuel
>
> PS: Some relevant sections of the stacktraces we're seeing for longer
> period of times after the event:
>
> Caused by: javax.persistence.PersistenceException:
> org.hibernate.exception.JDBCConnectionException: could not prepare
> statement
> at
> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>
>
> at
> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>
>
> at org.hibernate.query.Query.getResultList(Query.java:165)
>
>
> Caused by: org.postgresql.util.PSQLException: This connection
> has been closed.
> at
> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
> at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
> at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
> at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
> at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>
>
> at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
> at
> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>
>
> at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
> at
> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>
>
> at com.sun.proxy.$Proxy257.prepareStatement(Unknown
> Source)
> at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
> at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>
>
> at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>
>
> at com.sun.proxy.$Proxy256.prepareStatement(Unknown
> Source)
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>
>
> at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>
>
> ... 88 more
>
>