4 Replies Latest reply on Sep 10, 2003 4:11 AM by kv_moj

    Jboss3.2.1/MySql findAll() exceed tx timeout

      Hi,

      I have a CMP with around 60K records. I've configured findAll() to use a lazy-load strategy where only the id is loaded on the initial query. I then call getter methods only on a selected range (0 to 100 of 60000)of the proxies returned by findAll().
      This in turn loads the remaining columns only for the selected range.
      I tail the Jboss log and see the SQL being generated.

      All is well the first time (or after a long idle period) I call findAll - I get:

      select id from table;
      15/25 seconds - of no output on the tail
      then a bunch of sql which reads the selected range.

      This is how long I expected findAll to take returning the proxies and wish it would be the same for further calls.

      But on consequent calls to findAll - I get:
      select id from table;
      6/7 minutes - of no output on the tail (here I can see in the task manager that mysql is idle and Jboss has all the cycles)
      And of coarse by this time my transaction has timed out.

      I should add that I have tried various other optimization strategies and their effect is reflected in the first call to findAll and I belive I have the best configuration for my model.

      Also I have tried experimenting with transaction scope as I thought this problem might have something to do with the pre-load cache being invalidated when a new tx begins but I've not come up with a solution or anything which explains why on the first call to findAll everything is exactly as it should be and on further calls not.

      What is going on here.

      Thanks for any advice,
      kv.

        • 1. Re: Jboss3.2.1/MySql findAll() exceed tx timeout
          scoy

          What version of JBoss? I suspect 3.0.x, but my experience with 3.2.x is still a little on the low side.

          I've seen this behaviour in the 3.0.x read-ahead-cache. The 3.2.x has a different implementation, but I haven't had a chance to check for this behaviour in it yet.

          Steve Coy

          • 2. Re: Jboss3.2.1/MySql findAll() exceed tx timeout

            Hi Steve,

            I'm using version 2.3.1

            Also another interesting fact is that I have the app running on my windows dev machine as well as on the pre-prod server which is a linux box.
            I get exactly the same behavior on both which makes me think it's less likely to be a mysql config problem.

            I was wondering if when you encountered this on version 3.0.x, did you actually figure out why it was happening and/or any way to overcome it.
            This info could help me even though I'm using a later version.

            I'll keep a lookout on this thread and if you do get a chance to check for this problem on version 3.2.1 please update it with what you find. I will of coarse do the same.

            Thanks,
            kv.

            • 3. Re: Jboss3.2.1/MySql findAll() exceed tx timeout

              An update on this:

              I've now tested all the other finder methods and when ever they return large results (>50k entities) they behave exactly same as findAll.


              kv.

              • 4. Re: Jboss3.2.1/MySql findAll() exceed tx timeout

                OK,

                I run a profiler while I executed these queries and looks like the problem occurs in ReadAheadCache.addFinderResults.

                I looked at the source code for this class and I could see the method only executes when there's a read-ahead declaration.
                When I change <read-ahead>on-load</read-ahead> to <read-ahead>none</read-ahead> the method exits immediately and although the process of reading the required range is considerably slower (as there's no read-ahead), ReadAheadCache.addFinderResults no longer executes for 6/7 minutes so all in all this is a major improvement but it would be nice to know if there's a way to have read-ahead as well.

                Profiler info:

                org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.addFinderResults(ReadAheadCache.java:118)
                org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:207)
                org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:91)
                org.jboss.ejb.plugins.cmp.jdbc.JDBCFindEntitiesCommand.execute(JDBCFindEntitiesCommand.java:40)
                org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.findEntities(JDBCStoreManager.java:599)
                org.jboss.ejb.plugins.CMPPersistenceManager.findEntities(CMPPersistenceManager.java:324)
                org.jboss.resource.connectionmanager.CachedConnectionInterceptor.findEntities(CachedConnectionInterceptor.java:323)
                org.jboss.ejb.EntityContainer.findLocal(EntityContainer.java:603)
                sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:Native method)
                sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                java.lang.reflect.Method.invoke(Method.java:324)
                org.jboss.ejb.EntityContainer$ContainerInterceptor.invokeHome(EntityContainer.java:998)
                org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:88)
                org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invokeHome(EntitySynchronizationInterceptor.java:188)
                org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invokeHome(CachedConnectionInterceptor.java:215)
                org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:88)
                org.jboss.ejb.plugins.EntityInstanceInterceptor.invokeHome(EntityInstanceInterceptor.java:91)
                org.jboss.ejb.plugins.EntityLockInterceptor.invokeHome(EntityLockInterceptor.java:61)
                org.jboss.ejb.plugins.EntityCreationInterceptor.invokeHome(EntityCreationInterceptor.java:28)
                org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:88)
                org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:243)
                org.jboss.ejb.plugins.TxInterceptorCMT.invokeHome(TxInterceptorCMT.java:74)
                org.jboss.ejb.plugins.SecurityInterceptor.invokeHome(SecurityInterceptor.java:92)
                org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invokeHome(ProxyFactoryFinderInterceptor.java:93)
                org.jboss.ejb.EntityContainer.internalInvokeHome(EntityContainer.java:477)
                org.jboss.ejb.Container.invoke(Container.java:694)
                org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invokeHome(BaseLocalProxyFactory.java:272)
                org.jboss.ejb.plugins.local.LocalHomeProxy.invoke(LocalHomeProxy.java:110)
                $Proxy107.findAll(:Unknown line)



                CPU SAMPLES BEGIN (total = 75251) Wed Sep 10 10:57:03 2003
                rank self accum count trace method
                1 28.31% 28.31% 21301 803 java.net.SocketInputStream.socketRead0
                2 10.02% 38.33% 7541 521 java.net.PlainSocketImpl.socketAccept
                3 10.00% 48.32% 7522 347 java.net.PlainSocketImpl.socketAccept
                4 9.89% 58.22% 7445 544 java.net.PlainSocketImpl.socketAccept
                5 5.09% 63.31% 3834 343 java.net.PlainSocketImpl.socketAccept
                6 5.09% 68.40% 3827 361 java.net.PlainSocketImpl.socketAccept
                7 4.88% 73.28% 3672 704 java.net.PlainSocketImpl.socketAccept
                8 4.86% 78.14% 3657 775 java.net.PlainSocketImpl.socketAccept
                9 4.85% 82.98% 3646 847 java.net.PlainSocketImpl.socketAccept
                10 4.85% 87.83% 3646 849 java.net.PlainSocketImpl.socketAccept
                11 4.84% 92.66% 3639 850 java.net.PlainSocketImpl.socketAccept
                12 4.84% 97.50% 3639 848 java.net.PlainSocketImpl.socketAccept
                13 1.28% 98.78% 963 1522 java.net.SocketInputStream.socketRead0
                14 0.41% 99.19% 309 1385 java.net.SocketInputStream.socketRead0
                15 0.10% 99.29% 77 1744 java.util.AbstractList.hashCode
                16 0.05% 99.35% 41 532 java.lang.System.currentTimeMillis
                17 0.03% 99.37% 21 1299 java.lang.ClassLoader.defineClass0
                18 0.02% 99.39% 14 1750 java.util.AbstractList$Itr.next
                19 0.02% 99.41% 14 1085 sun.misc.Unsafe.defineClass
                20 0.02% 99.43% 12 1745 java.util.AbstractList.hashCode
                21 0.01% 99.44% 11 533 java.lang.Thread.setPriority0
                22 0.01% 99.45% 8 648 java.lang.ClassLoader.defineClass0
                23 0.01% 99.46% 8 1747 org.jboss.ejb.plugins.cmp.jdbc.ReadAheadCache.addFinderResults