2 Replies Latest reply on Aug 4, 2004 3:26 PM by crowse

    Performance issue , 2 local String getXXX(32Byte) take  95 m

    crowse Newbie

      Hi,
      I am having problems trying to materialize a list of 30000 key/value pairs off a MS SQL server using JBoss CMP.

      The log shows that the system spends 95% of its time in the 2 get methods (returning strings).

      I must be missing a configuration error in XDoclet or JBoss.

      The 'Raw' SQL server is capable of returning the result set in about 1 second.

      I can write PO JDBC but that increases my maintenance burden.

      Can anyone tell me what I am doing wrong?

      12:10:48,758 ERROR [STDERR] 04-Aug-2004 12:10:48 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:0ms getBean: 0ms getValue: 0ms put: 0ms ................ Loaded 0 in 646 ms
      12:12:23,828 ERROR [STDERR] 04-Aug-2004 12:12:23 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:648ms getBean: 1ms getValue: 95030ms put: 37ms ................ Loaded 1000 in 95716 ms
      12:13:59,149 ERROR [STDERR] 04-Aug-2004 12:13:59 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:651ms getBean: 2ms getValue: 190306ms put: 77ms ................ Loaded 2000 in 191036 ms
      12:15:34,018 ERROR [STDERR] 04-Aug-2004 12:15:34 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:661ms getBean: 5ms getValue: 285132ms put: 108ms ................ Loaded 3000 in 285906 ms
      12:17:09,052 ERROR [STDERR] 04-Aug-2004 12:17:09 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:666ms getBean: 8ms getValue: 380139ms put: 127ms ................ Loaded 4000 in 380940 ms
      12:18:44,065 ERROR [STDERR] 04-Aug-2004 12:18:44 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:669ms getBean: 9ms getValue: 475130ms put: 145ms ................ Loaded 5000 in 475953 ms
      12:20:18,744 ERROR [STDERR] 04-Aug-2004 12:20:18 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:683ms getBean: 10ms getValue: 569780ms put: 159ms ................ Loaded 6000 in 570632 ms
      12:21:53,426 ERROR [STDERR] 04-Aug-2004 12:21:53 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:691ms getBean: 10ms getValue: 664439ms put: 174ms ................ Loaded 7000 in 665314 ms
      12:23:27,820 ERROR [STDERR] 04-Aug-2004 12:23:27 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:698ms getBean: 13ms getValue: 758809ms put: 188ms ................ Loaded 8000 in 759708 ms
      12:25:02,600 ERROR [STDERR] 04-Aug-2004 12:25:02 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:703ms getBean: 15ms getValue: 853564ms put: 206ms ................ Loaded 9000 in 854488 ms
      12:26:37,204 ERROR [STDERR] 04-Aug-2004 12:26:37 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:707ms getBean: 17ms getValue: 948144ms put: 224ms ................ Loaded 10000 in 949092 ms
      12:28:11,657 ERROR [STDERR] 04-Aug-2004 12:28:11 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:713ms getBean: 21ms getValue: 1042566ms put: 245ms ................ Loaded 11000 in 1043545 ms
      12:29:45,852 ERROR [STDERR] 04-Aug-2004 12:29:45 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:716ms getBean: 25ms getValue: 1136736ms put: 263ms ................ Loaded 12000 in 1137740 ms
      12:31:20,152 ERROR [STDERR] 04-Aug-2004 12:31:20 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:723ms getBean: 27ms getValue: 1231011ms put: 279ms ................ Loaded 13000 in 1232040 ms
      12:32:57,038 ERROR [STDERR] 04-Aug-2004 12:32:57 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:727ms getBean: 28ms getValue: 1327882ms put: 288ms ................ Loaded 14000 in 1328925 ms
      12:34:30,165 ERROR [STDERR] 04-Aug-2004 12:34:30 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:736ms getBean: 30ms getValue: 1420974ms put: 313ms ................ Loaded 15000 in 1422053 ms
      12:36:07,270 ERROR [STDERR] 04-Aug-2004 12:36:07 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:741ms getBean: 30ms getValue: 1518054ms put: 332ms ................ Loaded 16000 in 1519158 ms
      12:37:44,429 ERROR [STDERR] 04-Aug-2004 12:37:44 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:745ms getBean: 32ms getValue: 1615191ms put: 349ms ................ Loaded 17000 in 1616317 ms
      12:39:19,519 ERROR [STDERR] 04-Aug-2004 12:39:19 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:746ms getBean: 33ms getValue: 1710267ms put: 361ms ................ Loaded 18000 in 1711407 ms
      12:39:27,113 ERROR [STDERR] 04-Aug-2004 12:39:27 natis.servlet.MSIxStateBeanListServlet reload
      INFO: MSIxStateBeanList.init() ....next:747ms getBean: 33ms getValue: 1717859ms put: 362ms ................ Loaded 18082 in 1719001 ms
      12:39:27,139 ERROR [STDERR] 04-Aug-2004 12:39:27 natis.servlet.Mf2NatisServlet build
      



      here is the code fragment
      
       MSIxStateBeanLocalHome home = (MSIxStateBeanLocalHome)
       initialContext.lookup(MSIxStateBeanLocalHome.JNDI_NAME);
       if (home==null) home=MSIxStateBeanUtil.getLocalHome();
      
       Collection c = home.findAll(); // findIndex();
       Iterator it = c.iterator();
      
       while (it.hasNext()) {
       if ((cnt % 1000) ==0) {
       logger.log(Level.INFO,"MSIxStateBeanList.init() ....next:" + times[0]
       + "ms getBean: " + times[1]
       + "ms getValue: " + times[2]
       + "ms put: " + times[3]
       + "ms ................ Loaded " + cnt
       + " in " + (System.currentTimeMillis()-t0) + " ms");
       }
       Object obj= it.next();
       ty=System.currentTimeMillis();
       times[0] += ty-tx;
       tx = ty;
      
       try {
       MSIxStateBeanLocal v = (MSIxStateBeanLocal) obj;
       // PortableRemoteObject.narrow(obj,MSIxStateBeanRemote.class);
       ty=System.currentTimeMillis();
       times[1] += ty-tx;
       tx = ty;
      
       // MSIxStateBeanValue vb = v.getValue(); // 96 sec/1000 on Oak
       String id = v.getId();
       String unit= v.getUnitN();
      
       ty=System.currentTimeMillis();
       times[2] += ty-tx;
       tx = ty;
       putStateBean(id, unit);
      
       ty=System.currentTimeMillis();
       times[3] += ty-tx;
       tx = ty;
      
       cnt++;
       } catch (Exception exc) {
       logger.log(Level.SEVERE,"servlet.MSIxStateBeanList.init() Exception : " ,exc);
       }
       }
      


      And the bean

      package tet.ejb;
      import java.io.UnsupportedEncodingException;
      import java.rmi.RemoteException;
      
      /*
      import java.text.NumberFormat;
      import java.text.DateFormat;
      import java.text.SimpleDateFormat;
      import java.util.Calendar;
      import java.util.Date;
      import java.util.logging.*;
      */
      
      import util.interfaces.Identifiable;
      import natis.interfaces.MSIxStateBeanValue;
      import javax.ejb.*;
      import util.ejb.BaseEntityBean;
      
      /** This is State Index
       * <UL>
       * <LI>Read only
       * <LI>Contains UnitN and ID of StateBeanMS</li>
       * </ul>
       *
       * @ejb.bean
       * name="MSIxStateBean"
       * jndi-name="ejb/mssql/MSIxStateBeanRemote"
       * local-jndi-name="ejb/MSIxStateBeanLocal"
       * view-type="both"
       * type="CMP"
       * cmp-version="2.x"
       * primkey-field="id"
       * business-interface="test.interfaces.MSIxStateBeanRemote"
       *
       * @ejb.facade type="stateless"
       * name="{0}Facade"
       * jndi-name="{0}Facade"
       * local-jndi-name="{0}LocalFacade"
       * view-type="both"
       * transaction-type="Container"
      
       * @ejb.home
       * local-class="test.interfaces.MSIxStateBeanLocalHome"
       * remote-class="test.interfaces.MSIxStateBeanRemoteHome"
       * @ejb.interface
       * local-class="test.interfaces.MSIxStateBeanLocal"
       * remote-class="test.interfaces.MSIxStateBeanRemote"
       *
       * @ejb.finder
       * signature="Collection findAll()"
       * role-name="Administrator"
       * transaction-type="NotSupported"
       * unchecked="true"
       *
       * @ejb.persistence
       * table-name="StateBeanMS_001"
       * read-only="true"
       *
       * @ejb.pk
       * generate="false"
       * unchecked="true"
       *
       * @jboss.ejb-external-ref-jndi
       * jndi-name="/UUIDKeyGeneratorFactory"
       * ref-name="comp:env/keygenerator"
       *
       * @jboss.create-table "false"
       * @jboss.remove-table "false"
       * @jboss.tuned-updates "${jboss.tuned.updates}"
       * @jboss.read-only "true"
       * @jboss.read-ahead strategy="on-find"
       * page-size="1000"
       *
       * @jboss.persistence
       * datasource="java:/MSSQLDS"
       * datasource-mapping="MS SQLSERVER2000"
       * table-name="StateBeanMS_001"
       * create-table="false"
       * remove-table-"false"
       * read-time-out="2000"
       * row-locking="false"
       * fetch-size="1000"
      
       * @ejb.security-identity
       * run-as="sa"
       *
       * @ejb.value-object
       * match="*"
       *
       * @version $Revision: 1.17 $
       * @author <a href="mailto:chris@forth.co.za@forthtree.co.za">Chris@forth.co.za</a>
       */
      public abstract class MSIxStateBean extends BaseEntityBean implements EntityBean, Identifiable {
      
       /**
       * @ejb.interface-method
       * view-type="both"
       * @ejb.value-object
       * exclude="true"
       * match="*"
       */
       public test.interfaces.MSIxStateBeanValue getValue() {
       MSIxStateBeanValue v = new MSIxStateBeanValue();
       v.setId(getId());
       v.setUnitN(getUnitN());
       return v;
       }
      
       /**
       * Id of this StateBean. This is not remote since the primary key can be extracted by other means.
       *
       * @ejb.pk-field
       * class="java.lang.String"
       * @ejb.interface-method
       *
       * @ejb.persistence column-name="StateBean_id"
       * @ejb.permission
       * role-name="Administrator"
       * @jboss.method-attributes read-only="true"
       *
       */
       public abstract String getId();
      
       /**
       * @ejb.value-object
       * exclude="false"
       * match="*"
       */
      
       public abstract void setId(String id);
      
       /**
       * @ejb.permission
       * role-name="Administrator"
       * @ejb.value-object
       * exclude="false"
       * match="*"
       * @ejb.persistence
       * column-name="unitN"
       * sql-type="varchar(255)"
       * @ejb.interface-method
       * view-type="both"
       *
       * @jboss.method-attributes read-only="true"
       */
       public abstract String getUnitN();
      
       /**
       * @ejb.value-object
       * exclude="false"
       * match="*"
       *
       * @jboss.method-attributes read-only="true"
       */
       public abstract void setUnitN(String modelJob);
      
       public void ejbStore() throws EJBException {
       }
      
       /**
       * This is to get the unknown primary key. We just get the primary key
       * from the entity context and cast it to the "known" class.
       *
       * @ejb.interface-method
       * view-type="both"
       *
       * @jboss.method-attributes read-only="true"
       */
       public String getGeneratedPrimaryKey() {
       return (String) entityContext.getPrimaryKey();
       }
      }
      



        • 1. Re: Performance issue , 2 local String getXXX(32Byte) take
          jamesstrachan Newbie

          If we take out the timing code, what you are doing is :-


          For each entry in index {
           Get entity bean for index
           Get ID
           Get value
           }
          



          Getting the entity bean involves network I/O, and also requires that the server works to create the Entity Bean and to load its data from the database.

          Getting the ID is another operation and also requires the server to activate the EJB.

          Getting the value is another operation across the network and requires another activation on the EJB.

          Each of the three operations has to go through the server layers that deal with security, transaction management etc., and then, as it's CMP, check whether any data has been changed and should be written back to the DB.

          If you are using commit options B or C, the server may also be reloading the entity bean from the database on each method call.

          So the server is really doing quite well to average 30 milliseconds for each operation.

          You can get some improvement by using the getValue() method that you have already written. That will eliminate one network call for each iteration.

          In order to solve the problem, you will need to remove the multiple calls from client to server.

          I attach a method from a stateless session bean that locates EJB's from within the server, extracts data and then returns a List of Data Transfer objects to the client.

           /**
           * This method retrieves a list of all Sequences from which the user
           * can select. These are obtained from the underlying Entity Beans.
           * <p>
           * The findAll method returns a collection of proxies which can be converted
           * to SequenceNumberRemote objects. The data from these is then unpacked
           * to create SequenceNumberSummary objects.
           * <p>
           * We could avoid this work by returning the Collection of proxies to
           * the Client, which would then call methods on the proxies to get data from
           * the Entity Beans. This would greatly increase the number of network calls
           * and the volume of network trafic. So it's worth writing a few lines of
           * code to aid efficiency.
           * @return ArrayList of SequenceNumberSummary objects.
           * @throws RemoteException
           * @throws FinderException
           */
           public ArrayList getSummary() throws RemoteException, FinderException {
          
           Collection workingSet;
           SequenceNumberRemote tempBean;
           SequenceNumberSummary temp;
           ArrayList result = new ArrayList();
          
           logger.info( "getSummary" );
          
           try {
           workingSet = getHome().findAll();
           }
           catch ( NamingException ne ) {
           logger.error( ne.getMessage(), ne );
           throw new RemoteException( "Name lookup failed" );
           }
          
           Iterator it = workingSet.iterator();
          
           // Work through the list of proxies building a SequenceNumberSummary
           // object for each entry in the Collection. Add the object to the ArrayList.
           while( it.hasNext() ) {
           tempBean = (SequenceNumberRemote) it.next();
           temp = new SequenceNumberSummary();
           temp.setSequenceId( tempBean.getSequenceControl().getSequenceId() );
           temp.setSequenceDescription( tempBean.getSequenceControl().getSequenceDescription() );
           temp.setLastUsedValue( tempBean.getLastUsedNumber() );
           result.add( temp );
           }
          
           return result;
          
           }
          
          

          This should work better as the network I/O is greatly reduced, and the reads from the entity bean are now local. JBoss will also optimise these calls to pass-by-reference instead of pass-by-value.

          This solution may still not be fast enough as the server has to create and juggle 30,000 instances of the Entity Beans. You may need, as you have already guessed, to use JDBC directly to get acceptable performance.

          James Strachan


          • 2. Re: Performance issue , 2 local String getXXX(32Byte) take
            crowse Newbie

            Hi James,
            Thanks for the tips and explanation, they help greatly.

            As you have noticed, I have already tried both the value bean and SLSB approaches with limited improvement in performance. I even had a method that packed the strings together with a pipe | separator. Yes it was faster but less flexible and maintainable.

            I really would have thought that the read-only tags should turn off a lot of the intermediate layer locking, dirty bit etc. Security, I would have thought, would only happen once at the query or 'record' level, a R/O bean could then be returned in toto.

            I have implemented the JDBC route, and have no performace problems. there (the Action completes in seconds).

            Many thanks, anyway, I now wont go barking up the wrong tree.


            Chris