13 Replies Latest reply on Dec 5, 2016 8:43 AM by ctomc

    Wildfly 10.1 - application sometimes leaks db connections at startup

    hans.christian.goranson

      Hi all!

       

      I have a problem where my application in Wildfly 10.1 sometime is leaking database connections.

       

      We recently updated Wildfly from 9 to 10.1 and started to experienced that our web application sometimes (randomly) leaked database connection after startup of the Wildfly server (or rather it seems that the some transaction are not ended so the connection is not returned to the pool).

      When we monitor the number of active connections in the connection pool for our XA datasource, we can see that it quite soon after startup of the Wildfly server, the active connections starts to increase rapidly.

      Our max Pool Size 800 and we will typically reach this after 10-15 min if we don't restarts the server again. Under normal condition, the number of active connections are typically around 30-40.

      Typically, we let the Wildlfy server start up, and then starts Apache so customer can reach our web application.

       

      When I enabled logging for org.jboss.jca, I could see that connection where taken out from the pool but never return and the callstack for all connections in the InUse pool had a last call

      originated from an remote EJB call. I couldn't see any issues while looking in our code from the caller of the method. The structure of our application is that we have quite big EAR file with the

      web application and other business logic plus a number of EAR files in the same Wildfly server. The communication between EAR files in the same server is done by remote EJB call where the EJB is

      looked up through the InitialContext. There is quite some load on the server right form the start when Apache is started.

       

      All our datasource are XADatasources, with the idle-timeout-minutes set to 5 and no flush strategy defined (so I guess it uses the default). We run Wildfy 10.1.0.Final

      Java 1.8.0_102, PostgreSQL 9.3.14, uses the provided Hibernate.

       

      Currently, our only workaround is to restart the Wildfly server until it behaves "normal". When it is started without any problem it, runs fine. We suspect that sometimes the transaction for a remote EJB call is not ended for some particular scenario during startup. Unfortunately, we can not reproduce it and we are running out of ideas how to proceed the investigation.

       

      Have anyone experienced the same issue or have any clue how to continue the investigation?

       

      Best regards

      Hans-Christian

        • 1. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
          ctomc

          who is connecting to your remote EJBs?

           

          Maybe you have some rouge client that is waiting for server to get up and than when it gets it starts processing "too much" of backlog requests at same time.

          once it is done load drops.

          This could describe behavior you are seeing.

          • 2. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
            hans.christian.goranson

            Thanks for the response.

            Yes, it could be a high load issue at startup. We have more or less  three types of scenarios for the EJB usage.

            • The web layer (we are using Struts) connects to the backend part with remote EJB
            • Some background services/jobs
            • Incoming WebService & REST calls could invoke a remote EJB
            • 3. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
              jaikiran

              From what I remember, the JCA layer had (has?) a feature where it would log the stacktrace of the caller which pulled out the connection from the pool for use but never returned. I think it's some config you have to set on the subsystem (datasource?) to get this stacktrace. Maybe that will tell you what piece of code might be triggering this issue.

              • 4. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                hans.christian.goranson

                Thanks, I have actually already enabled these logs and that show I found out that it was only different remote EJB calls causing the issue, but unfortunately I could get to the root cause by analyzing the callstack.

                Anyone else interested in how to enable these tracer you should do two things:

                • Enable TRACE level org.jboss.jca
                • Set the property ironjacamar.tracer.callstacks to true

                Then restart Wildlfy since there is an enable flag which is static and only read during startup (see more in this class org.jboss.jca.core.tracer.Tracer).

                Be a bit careful with this since the log is quite verbose and if there is a heavy load on the server, the log will soon fill up much space.

                • 5. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                  spatwary04

                  Hans,

                  we have the same issue.we migrated from jboss 4 to wildlfy10 .wildlfy10 has the same issue.i did a upgrade to 10.1 but still same issue. On client  side

                  we see two exceptions . This is is happening in the night.

                   

                  1. java.io.IOException: Channel Channel ID 91540975 (outbound) of Remoting connection 55b2fc25 to /172.17.11.199:1199 of endpoint "config-based-naming-client-endpoint" <7387261d> has been closed

                      at org.jboss.ejb.client.remoting.ChannelAssociation$1.handleClose(ChannelAssociation.java:123) [jboss-ejb-client-2.1.4.Final.jar:2.1.4.Final]

                      at org.jboss.ejb.client.remoting.ChannelAssociation$1.handleClose(ChannelAssociation.java:115) [jboss-ejb-client-2.1.4.Final.jar:2.1.4.Final]

                      at org.jboss.remoting3.spi.SpiUtils.safeHandleClose(SpiUtils.java:54)

                      at org.jboss.remoting3.spi.AbstractHandleableCloseable$CloseHandlerTask.run(AbstractHandleableCloseable.java:514)

                      at org.jboss.remoting3.spi.AbstractHandleableCloseable.runCloseTask(AbstractHandleableCloseable.java:419)

                      at org.jboss.remoting3.spi.AbstractHandleableCloseable.closeComplete(AbstractHandleableCloseable.java:290)

                      at org.jboss.remoting3.remote.RemoteConnectionChannel.closeReadsAndWrites(RemoteConnectionChannel.java:274)

                      at org.jboss.remoting3.remote.RemoteConnectionChannel.closeAction(RemoteConnectionChannel.java:534)

                      at org.jboss.remoting3.spi.AbstractHandleableCloseable.close(AbstractHandleableCloseable.java:154)

                      at org.jboss.ejb.client.remoting.RemotingConnectionEJBReceiver.disassociate(RemotingConnectionEJBReceiver.java:266) [jboss-ejb-client-2.1.4.Final.jar:2.1.4.Final]

                      at org.jboss.ejb.client.EJBClientContext.unregisterEJBReceiver(EJBClientContext.java:446) [jboss-ejb-client-2.1.4.Final.jar:2.1.4.Final]

                      at org.jboss.ejb.client.EJBClientContext.close(EJBClientContext.java:1295) [jboss-ejb-client-2.1.4.Final.jar:2.1.4.Final]

                      at org.jboss.naming.remote.client.ejb.RemoteNamingStoreEJBClientHandler$RemoteNamingEJBClientContextCloseTask.close(RemoteNamingStoreEJBClientHandler.java:118) [jboss-remote-naming-2.0.4.Final.jar:2.0.4.Final]

                      at org.jboss.naming.remote.client.RemoteContext.finalize(RemoteContext.java:299) [jboss-remote-naming-2.0.4.Final.jar:2.0.4.Final]

                      at java.lang.System$2.invokeFinalize(System.java:1267) [rt.jar:1.8.0_25]

                      at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:98) [rt.jar:1.8.0_25]

                      at java.lang.ref.Finalizer.access$100(Finalizer.java:34) [rt.jar:1.8.0_25]

                      at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:210) [rt.jar:1.8.0_25]

                   

                  2. javax.ejb.EJBTransactionRolledbackException: Transaction rolled back.

                  Caused by: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.

                      at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1212) [narayana-jts-idlj-5.3.3.Final.jar:5.3.3.Final (revision: c5912)]

                      at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [narayana-jts-idlj-5.3.3.Final.jar:5.3.3.Final (revision: c5912)]

                      at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)

                      at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:91) [wildfly-ejb3-10.1.0.Final.jar:10.1.0.Final]

                      ... 105 more

                   

                  On the server side we see :

                   

                  2016-10-22 02:15:58,415 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 32) WFLYEJB0153: Could not write out invocation success message to channel due to: java.io.IOException: WFLYEJB0422: Could not open message outputstream for writing to Channel

                      at org.jboss.as.ejb3.remote.protocol.versionone.TransactionRequestHandler.writeTxPrepareResponseMessage(TransactionRequestHandler.java:151)

                      at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionPrepareTask.manageTransaction(XidTransactionPrepareTask.java:79)

                      at org.jboss.as.ejb3.remote.protocol.versionone.XidTransactionPrepareTask.run(XidTransactionPrepareTask.java:58)

                      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_25]

                      at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_25]

                      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_25]

                      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_25]

                      at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_25]

                      at org.jboss.threads.JBossThread.run(JBossThread.java:320)

                  Caused by: org.jboss.remoting3.NotOpenException: Writes closed

                      at org.jboss.remoting3.remote.RemoteConnectionChannel.openOutboundMessage(RemoteConnectionChannel.java:115)

                      at org.jboss.remoting3.remote.RemoteConnectionChannel.writeMessage(RemoteConnectionChannel.java:307)

                      at org.jboss.as.ejb3.remote.protocol.versionone.ChannelAssociation.acquireChannelMessageOutputStream(ChannelAssociation.java:68)

                      at org.jboss.as.ejb3.remote.protocol.versionone.TransactionRequestHandler.writeTxPrepareResponseMessage(TransactionRequestHandler.java:149)

                      ... 8 more

                  • 6. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                    spatwary04

                    is there a way to release database connection in these type of scenarios??

                    • 7. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                      ctomc

                      shiva patwary wrote:

                       

                      Hans,

                      we have the same issue.

                       

                      No you don't!

                      From stacktraces you pasted, you have completely unrelated remote EJB issue.

                      so please do not hijack the this thread but create new one, where you should post details about your problem.

                      • 8. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                        spatwary04

                        Tomaz.

                        sorry i did not  mean to hijack the discussion. I did post another question.Below is the link with details. But it has the same behavior.

                        Wildfly10  Remote EJB calls to another EJB on another Wildlfy 10 instance leaking jdbc connections

                         

                        shiva

                        • 9. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                          hans.christian.goranson

                          I have narrowed down starting point to be when we populate some of hours caches at startup and we performs some fairly big SELECT queries.

                           

                          What we can see is that a transactions begin but never gets committed nor rollbacḱed eventhough the EJB is done and returned the data.

                           

                          In postgres, from the pg_stat_activity view, I can see that some the connections has entered the state 'ilde in transaction' and are stuck there:

                           

                          crm_jboss=> SELECT datname, pid, usename, waiting, state, (now()-query_start) AS since FROM pg_stat_activity WHERE state='idle in transaction' ORDER BY since LIMIT 100;

                            datname  |  pid  | usename | waiting |        state        |      since    

                          -----------+-------+---------+---------+---------------------+-----------------

                          crm_jboss | 23665 | crm    | f      | idle in transaction | 03:18:55.249932

                          crm_jboss | 22837 | crm    | f      | idle in transaction | 03:46:37.844577

                          crm_jboss | 21434 | crm    | f      | idle in transaction | 03:52:46.3773

                          crm_jboss | 21433 | crm    | f      | idle in transaction | 03:52:46.982128

                          crm_jboss | 21432 | crm    | f      | idle in transaction | 03:52:47.736266

                          crm_jboss | 21430 | crm    | f      | idle in transaction | 03:52:48.397539

                          crm_jboss | 21429 | crm    | f      | idle in transaction | 03:52:49.203085

                          crm_jboss | 21428 | crm    | f      | idle in transaction | 03:52:49.898564

                          crm_jboss | 21426 | crm    | f      | idle in transaction | 03:52:50.512907

                          crm_jboss | 21425 | crm    | f      | idle in transaction | 03:52:51.195411

                          crm_jboss | 21424 | crm    | f      | idle in transaction | 03:52:51.850833

                          crm_jboss | 21422 | crm    | f      | idle in transaction | 03:52:52.566735

                          crm_jboss | 21421 | crm    | f      | idle in transaction | 03:52:53.323215

                          crm_jboss | 21420 | crm    | f      | idle in transaction | 03:52:54.002455

                          crm_jboss | 21418 | crm    | f      | idle in transaction | 03:52:54.845609

                          (15 rows)

                           

                          And from the jboss.as.transactions MBean I can see that the numberOfInflightTransactions is the same as the aboww postgresql table.

                          Screenshot from JVisualvm on the transactions MBean

                          JVisualvm_screenshot.png

                           

                          There are no threads in blocked state from the thread dump. I have also taken a headdump but it is rather hard to find around in.

                           

                          The application runs fine and has received it data, the only problem is that the transaction has not been finished.

                           

                          Anyone familiar of:

                          - can Hibernate preventing the transaction to commit? if so, any hint where to start looking

                          - if it could be a problem where the Garbage Collector has not released a reference and hence blocking the commit

                          - other?

                           

                          BR

                          Hans-Christian

                          • 10. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                            jaikiran

                            I have narrowed down starting point to be when we populate some of hours caches at startup and we performs some fairly big SELECT queries.

                             

                            Please post that relevant code.

                            • 11. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                              hans.christian.goranson

                              I have attached the log "serverlog_2016.12.02.txt" with some of the server log.

                               

                              First, the thread "ServerService Thread Pool -- 140" starts to populate some caches and executes a couple of SQL queries. This is initialized in a HttpServlet class from a init method

                                (ServerService Thread Pool -- 140)     /* findCurrenciesByActive */ select

                               

                              Soon after there is an incoming HTTP request, thread "default task-86", that starts to execute another query. This is the one that never gets committed in postgres and I can see that the last part of the query is the one that is the last run query in postgres and the connection that is 'idle in transaction'.

                                (default task-6)     /* findOneProductByNumber */ select

                               

                              The scenario here is when I reproduced it, in production we wait longer before allowing incoming HTTP requests but we end up with the same state of the connections.

                              • 12. Re: Wildfly 10.1 - application sometimes leaks db connections at startup
                                jaikiran

                                Without seeing the relevant code from that servlet and that EJB, it's hard to say what's wrong and if there's some potential bug here.

                                 

                                If you won't be able to paste the relevant code, then perhaps you could try your application against the nightly builds of the master branch of WildFly  [1] and see if it's fixed there (I know of an issue which got fixed in there where the EJB invocation was allowed a bit early than it should be, but I don't know if it's even remotely related to what you are seeing).

                                 

                                 

                                [1] https://ci.wildfly.org/viewLog.html?buildTypeId=WF_Nightly&buildId=lastSuccessful&tab=artifacts  (you can use "Login as guest" when it asks for user/pass)