2 Replies Latest reply on Feb 20, 2004 7:27 AM by sachinshah

    Probable Connection Pool Problem

    sachinshah

      Hi,

      I am using JBoss 2.4.3 with JRE 1.3. Usually everything works fine. But sometime all of the sudden system goes slow and client (Swing) feels the same. We have to restart the server and then only users can work peacefully. After analysis of the logs we found following.

      1) Initially everything works fine, there are usual application logs and connection pool's usual gave out returned statement with correct count of connection in use, in pool and max allowed

      2) Somewhere down the line, i don't know what triggers this, but server starts behaving abnormally. Will give you an example

      The last log had

      ------------- Log Start -------------
      [DefaultDS] Pool DefaultDS [3/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
      [DefaultDS] Pool DefaultDS [2/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
      [DefaultDS] No transaction right now.

      ------------- Log End -------------

      In the next log file i have following output

      ------------- Log Start -------------

      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@6ce6f
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@b2c55
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@92a2
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@2de78f
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@92313
      [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
      [Default]

      ------------- Log End -------------

      Observe it has jumped directly from 2 in use to 10 in use and even after giving out different connection objects it hasn't increased the count of in use connection.

      Even after this for sometime application works fine and even the logs is proper. But again after a mysterious event, which i don't know, server starts printing following and system goes slow.

      ------------- Log Start -------------

      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [6/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
      [DefaultDS] Pool DefaultDS [5/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
      [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@b2c55 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
      [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
      [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] Resource 'org.jboss.pool.jdbc.xa.wrapper.XAResourceImpl@4b7791' enlisted for 'org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218'.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
      [DefaultDS] No transaction right now.
      [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68

      ------------- Log End -------------

      Observe in the above logs there aren't any application logs. So i am wondering is it the server which is performing some operations on connection pool??? After conitnues logs like this application goes slow and we have to restart server.

      Another thing which i observed was in between of the series of above logs i noticed few exceptions like folllow

      ------------- Log Start -------------

      [Default] java.lang.NullPointerException
      [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.removeNode(LeastRecentlyUsedCache.java:241)
      [Default]
      [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.checkMaxSize(LeastRecentlyUsedCache.java:186)
      [Default]
      [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.addObject(LeastRecentlyUsedCache.java:158)
      [Default]
      [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.getObject(LeastRecentlyUsedCache.java:106)
      [Default]
      [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.useObject(LeastRecentlyUsedCache.java:35)
      [Default]
      [Default] at org.jboss.pool.jdbc.xa.wrapper.XAClientConnection.prepareStatement(XAClientConnection.java:167)
      [Default]
      [Default] at com.app.sample.fetchData(Unknown Source)
      [Default]
      [Default] at java.lang.reflect.Method.invoke(Native Method)
      [Default]
      [Default] at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:543)
      [Default]
      [Default] at org.jboss.ejb.plugins.TxInterceptorBMT.invoke(TxInterceptorBMT.java:276)
      [Default]
      [Default] at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:87)
      [Default]
      [Default] at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:128)
      [Default]
      [Default] at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:195)
      [Default]
      [Default] at org.jboss.ejb.StatelessSessionContainer.invoke(StatelessSessionContainer.java:286)
      [Default]
      [Default] at org.jboss.ejb.plugins.jrmp.server.JRMPContainerInvoker.invoke(JRMPContainerInvoker.java:395)
      [Default]
      [Default] at java.lang.reflect.Method.invoke(Native Method)
      [Default]
      [Default] at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
      [Default]
      [Default] at sun.rmi.transport.Transport$1.run(Unknown Source)
      [Default]
      [Default] at java.security.AccessController.doPrivileged(Native Method)
      [Default]
      [Default] at sun.rmi.transport.Transport.serviceCall(Unknown Source)
      [Default]
      [Default] at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
      [Default]
      [Default] at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
      [Default]
      [Default] at java.lang.Thread.run(Unknown Source)

      ------------- Log End -------------

      Has anyone faced similar problem. Any clue why this is happening. Any help appreciated.

      Thank you in advance

      Sachin

        • 1. Probable Connection Pool Problem
          sachinshah

          Hi,

          I am using JBoss 2.4.3 with JRE 1.3. Usually everything works fine. But sometime all of the sudden system goes slow and client (Swing) feels the same. We have to restart the server and then only users can work peacefully. After analysis of the logs we found following.

          1) Initially everything works fine, there are usual application logs and connection pool's usual gave out returned statement with correct count of connection in use, in pool and max allowed

          2) Somewhere down the line, i don't know what triggers this, but server starts behaving abnormally. Will give you an example

          The last log had

          ------------- Log Start -------------
          [DefaultDS] Pool DefaultDS [3/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
          [DefaultDS] Pool DefaultDS [2/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
          [DefaultDS] No transaction right now.

          ------------- Log End -------------

          In the next log file i have following output

          ------------- Log Start -------------

          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@6ce6f
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@b2c55
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@92a2
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@2de78f
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@92313
          [DefaultDS] Pool DefaultDS [10/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
          [Default]

          ------------- Log End -------------

          Observe it has jumped directly from 2 in use to 10 in use and even after giving out different connection objects it hasn't increased the count of in use connection.

          Even after this for sometime application works fine and even the logs is proper. But again after a mysterious event, which i don't know, server starts printing following and system goes slow.

          ------------- Log Start -------------

          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [6/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
          [DefaultDS] Pool DefaultDS [5/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
          [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@b2c55 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
          [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68
          [DefaultDS] Pool DefaultDS [4/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e to the pool.
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@75ba2e
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] Resource 'org.jboss.pool.jdbc.xa.wrapper.XAResourceImpl@4b7791' enlisted for 'org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218'.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] Pool DefaultDS [3/20/40] returned object org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218 to the pool.
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [4/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@28e218
          [DefaultDS] No transaction right now.
          [DefaultDS] Pool DefaultDS [5/20/40] gave out pooled object: org.jboss.pool.jdbc.xa.wrapper.XAConnectionImpl@7fed68

          ------------- Log End -------------

          Observe in the above logs there aren't any application logs. So i am wondering is it the server which is performing some operations on connection pool??? After conitnues logs like this application goes slow and we have to restart server.

          Another thing which i observed was in between of the series of above logs i noticed few exceptions like folllow

          ------------- Log Start -------------

          [Default] java.lang.NullPointerException
          [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.removeNode(LeastRecentlyUsedCache.java:241)
          [Default]
          [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.checkMaxSize(LeastRecentlyUsedCache.java:186)
          [Default]
          [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.addObject(LeastRecentlyUsedCache.java:158)
          [Default]
          [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.getObject(LeastRecentlyUsedCache.java:106)
          [Default]
          [Default] at org.jboss.pool.cache.LeastRecentlyUsedCache.useObject(LeastRecentlyUsedCache.java:35)
          [Default]
          [Default] at org.jboss.pool.jdbc.xa.wrapper.XAClientConnection.prepareStatement(XAClientConnection.java:167)
          [Default]
          [Default] at com.app.sample.fetchData(Unknown Source)
          [Default]
          [Default] at java.lang.reflect.Method.invoke(Native Method)
          [Default]
          [Default] at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:543)
          [Default]
          [Default] at org.jboss.ejb.plugins.TxInterceptorBMT.invoke(TxInterceptorBMT.java:276)
          [Default]
          [Default] at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:87)
          [Default]
          [Default] at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:128)
          [Default]
          [Default] at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:195)
          [Default]
          [Default] at org.jboss.ejb.StatelessSessionContainer.invoke(StatelessSessionContainer.java:286)
          [Default]
          [Default] at org.jboss.ejb.plugins.jrmp.server.JRMPContainerInvoker.invoke(JRMPContainerInvoker.java:395)
          [Default]
          [Default] at java.lang.reflect.Method.invoke(Native Method)
          [Default]
          [Default] at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
          [Default]
          [Default] at sun.rmi.transport.Transport$1.run(Unknown Source)
          [Default]
          [Default] at java.security.AccessController.doPrivileged(Native Method)
          [Default]
          [Default] at sun.rmi.transport.Transport.serviceCall(Unknown Source)
          [Default]
          [Default] at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
          [Default]
          [Default] at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
          [Default]
          [Default] at java.lang.Thread.run(Unknown Source)

          ------------- Log End -------------

          Has anyone faced similar problem. Any clue why this is happening. Any help appreciated.

          Thank you in advance

          Sachin

          • 2. Re: Probable Connection Pool Problem
            sachinshah

            Hi,

            Any luck on this. Hey i am facing this in production, please help.

            Thanks
            sachin