10 Replies Latest reply on Aug 10, 2002 2:34 PM by Markus Menner

    CMP overhead

    Georg Schmid Newbie

      Environment: JB3.1.0alpha (but most likely the same with 3.0.1), Win2K/XP/Solaris, JDK1.4.0, Oracle8.1.7.0.0

      I have the following scenario:
      Client -> SLSB Remote/txn=required -> EB Local/txn=required

      In my application, when an entity bean instance is read from the store, it is converted to a value object by copying the entity bean properties, for example:
      private ValueObject copyAttributes(EntityLocal entity) {
      ...
      valueObject.setId( entity.getId() );
      valueObject.setName( entity.getName() );
      ...
      return valueObject;
      }
      Reading a list of entities is done by iterating over the a finder result and converting each object in turn.

      My assumption was, because the local interface is used here, that each of these operations is a simple assignment (or not much more).
      Setting the logging level for plugin and resource to TRACE I see for each of the property accesses above the following sequence of operations (in this case, getName()):

      2002-07-15 21:01:53,468 DEBUG [org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor] invokerBInding is null in ProxyFactoryFinder
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.LogInterceptor] Start method=getName
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] Current transaction in MI is TransactionImpl:XidImpl [FormatId=257, GlobalId=serenissima//26, BranchQual=]
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TX_REQUIRED for getName
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] Thread came in with tx TransactionImpl:XidImpl [FormatId=257, GlobalId=serenissima//26, BranchQual=]
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] Begin invoke, key=382
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] Begin invoke, key=382
      2002-07-15 21:01:53,468 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] old stack for key: ProxyTarget[org.jboss.ejb.plugins.cmp.bridge.EntityBridgeInvocationHandler@e142a5]
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] invoke called for ctx org.jboss.ejb.EntityEnterpriseContext@49494e, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=serenissima//26, BranchQual=]
      2002-07-15 21:01:53,468 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] register, ctx=org.jboss.ejb.EntityEnterpriseContext@49494e, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=serenissima//26, BranchQual=]
      2002-07-15 21:01:53,484 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] popped object: ProxyTarget[org.jboss.ejb.plugins.cmp.bridge.EntityBridgeInvocationHandler@e142a5]
      2002-07-15 21:01:53,484 TRACE [org.jboss.ejb.plugins.EntityInstanceInterceptor] End invoke, key=382, ctx=org.jboss.ejb.EntityEnterpriseContext@49494e
      2002-07-15 21:01:53,484 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] End invoke, key=382
      2002-07-15 21:01:53,484 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TxInterceptorCMT: In finally
      2002-07-15 21:01:53,484 TRACE [org.jboss.ejb.plugins.LogInterceptor] End method=getName

      In a test I am reading 1000 entities each having 10 properties, so this sequence is executed 10000 times.

      The effect on performance is quite disastrous (compared to raw JDBC):
      Reading 1000 entities takes about 20 seconds, while it takes less than 2 seconds reading them using JDBC directly, looping through the resultset and creating the value objects "manually".
      It should be noted that in the CMP scenario all data is preloaded with one single SELECT (pagesize=1000,on-find, default eager load-group) and then taken from the read-ahead cache.
      The time for executing the SELECT is almost neglectable. The test has been done with logging level=INFO, no logging output is generated while reading the entities.


      Is there a way to avoid this overhead when accessing EB
      properties through the local interface? Or is this mandated by the spec?

      Thanks in advance.
      Georg

        • 1. Re: CMP overhead
          Dain Sundstrom Master

          You should put the value class abstraction code in the bean implementation class. This code is also very data centric and tightly coupled to the bean implementation class already, so it is logically the correct place for the code.

          As a side note this code should be much faster (on order of 0.5 seconds). Have you used a profiler on the code? If so, what is hogging all of the time. My guess is it is my code, and not the interceptor stack because it can easily handle 20,000 invocations per sec on a 1 ghz machine.

          • 2. Re: CMP overhead
            Georg Schmid Newbie

            Dain,

            I'm thinking over your hint as where to put the code for creating the value object, it sounds reasonable enough (actually I changed some of my EBs accordingly during the time the forums were down, without impact on performance, though).

            Because all data is already in the cache, there are not too many places left (or not?) where the time could be spent.

            If you could give me a few hints where to start the search I'll be very willing to look into this.

            I tried profiling JBoss with the capabilities built into the JDK1.3/1.4, but I still need to figure out the best set of options, and how to interpret the outcome. Any hints (pointers) would be welcome. Also I started running into transaction timeouts, which made me stop my experiments .

            (BTW: my other concern is setFetchSize(), because I may have to access a database server over a network with > 100ms latency, see patch #581134).

            Cheers,
            Georg

            • 3. Re: CMP overhead
              Dain Sundstrom Master

              Wow that is a huge latency. I would bet that the setFetch size is the real problem. Another place is the ReadAheadCache. It had a big performance problem in 3.0, but has been fixed.

              The setFetchSize issue is in David Jenks' code so you will have to wait until he gets back next week.

              • 4. Re: CMP overhead
                Georg Schmid Newbie

                The DB is on your continent, I'm in Germany, that's the reason for the latency. It is real, no bugs or similar deficiencies are involved...

                I should have been more specific. The "setFetchSize() problem" is, that there is currently no possibility in JBoss to control it.

                I repeat the comment from the patch I submitted:

                - Begin of comment -

                "I added the new element <fetch-size> to the elements
                and in jbosscmp-jdbc.xml as well
                as to JDBCEntityMetaData and
                the JDBCEntityBridge.

                setFetchSize() is a standard method at least for
                Statement and PreparedStatement since JDBC2.0.

                In JDBCAbstractQueryCommand,
                JDBCLoadEntityCommand and
                JDBCLoadRelationCommand this value
                is used in a call to setFetchSize() on the
                PreparedStatement used to retrieve the rows
                from the database just after the statement has been
                created.

                The value controls the number of rows that are fetched
                from the database in each roundtrip.

                It may make sense to set the fetch size in other
                commands, too, but I don't know enough about the
                JBossCMP related commands to be sure.

                The effects on performance for a simple finder on a table
                with 8 attributes on Win2K, Oracle8.1.7 thin driver is:
                fetch size time in milliseconds to get 6000 entries
                1 6100
                10 1500 (this is the Oracle thin client drivers
                default setting)
                100 1150
                5000 1100"

                - End of comment -

                Cheers
                Georg

                • 5. Re: CMP overhead
                  Markus Menner Newbie

                  Dain, Georg,

                  I'm (doing and) facing exactly the same problem.

                  I have the impression, that something slows down the retrieval of attributes.

                  I case of the first access of an entity I can imagine, that this could be an issue of JDBC or the readahead cache.

                  But the second time you access an entity it will be cached by the container and the only SQL statement, which will be excuted, is the finder query to retrieve the needed primary keys, which in my case is fast enough.

                  JBoss (3.0.1) in my case runs on an Athlon XP1900.

                  I roughly summarized the time to retrieve each attribute (about 6) of a bunch of 1000 instances of a certain entity and got 1 second.

                  What can we do ?

                  Markus



                  • 6. Re: CMP overhead
                    Dain Sundstrom Master

                    The problem Georg is having is his database is in the US and he is in Germany. Becasue of the latencly involved he needs to get large chunks of data at a time. Do you have a similar setup? If not, you have a different issue.

                    • 7. Re: CMP overhead
                      Markus Menner Newbie

                      Dain,

                      shall I start a new (message) thread then ?

                      First of all, here is my configuration:

                      JBoss 3.0.1
                      Athlon XP 1900 (=1600 MHz) PC
                      Enough RAM (512 MB)
                      Windows XP
                      JDK 1.4.0_01


                      I'd like to explain what I tested yet:

                      I have created a simple CMP 2.0 EJB.

                      My test program retrieves a certain entity (local interface) by invoking findByPrimaryKey.

                      Then I start a (User)transaction (because the test code is outside the EJB).

                      Then I start a loop with 1000 iterations. In the loop I retrieve every attribute of the entity by invoking its getter method (there are 15 attributes).

                      At the end I print out the elapsed time. In average I get 600 msecs on my Athlon XP 1900.

                      Is this normal ?

                      When I simulate the same thing with a hand coded javabean it takes 30 msecs, even if I invoke the getters via a dynamic proxy and reflection.

                      So, what happens, when the attribute getters are invoked ?

                      I tried to use a profiler (JProfiler), but the method invocation tree stops at the JBoss dynamic proxy method handlers.

                      Do you have any idea, what's going on ?

                      Thanx
                      Markus

                      • 8. Re: CMP overhead
                        Markus Menner Newbie

                        Something has "eaten" my last posting, so once again:

                        My test cvonfiguration is:

                        JBoss 3.0.1
                        Athlon XP 1900 processor (=1600MHz)
                        Enough RAM (512MB)
                        Windows XP
                        JDK 1.4.0_01

                        I'll tell what I am doing in my test code:

                        I created a simple CMP 2.0 EJB.

                        I retriecve a certain instance of this EJB.

                        I start a transaction (the code is outside the EJB (a servlet)).

                        I record the begin of my time measuring.

                        I start a loop with 1000 iterations. In the loop I retrieve each of 15 attributes.

                        At the end I print the elapsed time. On my machine I get 600! msecs in average.

                        Is this normal ?

                        When I simulate the same thing with a hand coded javabean it takes 30 msecs, even if I invoke the getters via a dynamic proxy and reflection.

                        So, what happens, when the attribute getters are invoked ?

                        I tried to use a profiler (JProfiler), but the method invocation tree stops at the JBoss dynamic proxy method handlers.

                        Do you have any idea, what's going on ?

                        Thanx
                        Markus

                        • 9. Re: CMP overhead
                          Dain Sundstrom Master

                          I don't know what is going on, but I suggest you use OptimizeIT instead of JProbe. I have been told that OptimizeIt ships with a JBoss startup file.

                          • 10. Re: CMP overhead
                            Markus Menner Newbie

                            Dain,

                            thanks, I'll try OptimzeIt.

                            Can you provide any hint ?

                            Especially I would like to know, if my time measurments reflect the normal behaviour or not, because I would like to know, if it is worth to dive in the code.

                            What happens (roughly), when an attribute-getter is invoked on a local interface, considering that the EJB has been cached by the container and that there is a allready an active transaction (UserTransaction) ?

                            Possibly I can figure out the problem with your hints.

                            Thanx
                            Markus