Performance issue , 2 local String getXXX(32Byte) take 95 m
crowse Aug 4, 2004 7:52 AMHi,
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(); } }