Announcement Announcement Module
Collapse
No announcement yet.
Spring interceptors slowing down performance? Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Spring interceptors slowing down performance?

    Hi All,

    We have a Hibernate based application for which we use Spring to manage hibernate session/transaction.

    When i call the getHibernateTemplate.saveOrUpdate it takes in our case around 381 ms but the over all time taken by the test case when i call the DAO's save method is much higher.

    We've an object called SAPModule as below:

    Code:
    @javax.persistence.NamedQueries({
        @NamedQuery(name="SapModuleGetAllActive", queryString="select sapModule from SapModule sapModule where sapModule.active=1"),
        @NamedQuery(name="SapModuleGetAllInActive", queryString="select sapModule from SapModule sapModule where sapModule.active=0"),
        @NamedQuery(name="SapModuleFindByName", queryString="select sapModule from SapModule sapModule where sapModule.name like :name")
    })
    
    @Entity(/*access=AccessType.PROPERTY*/)
    
    @org.hibernate.annotations.Entity(selectBeforeUpdate = false, 
    		dynamicInsert = true, 
    		dynamicUpdate = true, 
    		optimisticLock = OptimisticLockType.NONE )
    		
    @javax.persistence.SequenceGenerator (name="SEQ_STORE", sequenceName="SAP_MODULE_SEQ")		
    
    @Table(name="SAP_MODULE")
    
    public class SapModule extends BaseAdminEntity {
    
    	private Set<ProductSapModule> productSapModule = new HashSet<ProductSapModule>&#40;&#41;;
    	
    	@OneToMany&#40;cascade=&#123;CascadeType.ALL&#125;,  fetch=FetchType.LAZY, mappedBy="sapModule"/*, targetEntity=com.apple.ist.espresso.admin.model.ProductSapModule.class*/&#41;
    	//@BatchSize&#40;size=5&#41;
    	public Set<ProductSapModule> getProductSapModule&#40;&#41; &#123;
    	    return productSapModule;
    	&#125;
    	public void setProductSapModule&#40;Set <ProductSapModule>productSapModule&#41; &#123;
    	    this.productSapModule = productSapModule;
    	
    	&#125; 
    &#125;
    
    @EmbeddableSuperclass
    public abstract class BaseAdminEntity  extends BaseAuditEntity  &#123;
        /**
         * Business Name of the Entity
         */
        protected String name;
    
        /**
         * Business description of the Entity
         */
        protected String description;
    
        /**
         * True if this entry is active. False otherwise.
         */
        private boolean isActive;
    
        /**
         * Primary Key for the Entity
         */
        
        private Long id;
        
        /*
        @Version
        @Column&#40;name="OPTLOCK"&#41;
        private int Version;
        */
    
       
        @Id&#40;generate=GeneratorType.SEQUENCE, generator="SEQ_STORE"&#41;
        //@javax.persistence.SequenceGenerator &#40;	name="SEQ_STORE", sequenceName="HIBERNATE_SEQ"&#41;
        @Column&#40;length=12&#41;
        @Length&#40;max=12&#41;
        public Long getId&#40;&#41; &#123;
            return id;
        &#125;
    
        /**
         * @param id The id to set.
         */
        public void setId&#40;Long id&#41; &#123;
            this.id = id;
        &#125;
    
     
        @Column&#40;name="NAME", nullable=false&#41;
        @Length&#40;max=64&#41; @NotNull
        public String getName&#40;&#41; &#123;
            return name;
        &#125;
    
        /**
         * @param name The name to set.
         */
        public void setName&#40;String name&#41; &#123;
            this.name = name;
        &#125;
    
     
        @Column&#40;name="DESCRIPTION", length =256, nullable=false&#41;
        //@Length&#40;max=256&#41;
        @NotNull
        public String getDescription&#40;&#41; &#123;
            return description;
        &#125;
    
        /**
         * @param description The description to set.
         */
        public void setDescription&#40;String description&#41; &#123;
            this.description = description;
        &#125;
    
     
        @Column&#40;name="IS_ACTIVE", nullable=false&#41;
        public boolean isActive&#40;&#41; &#123;
            return isActive;
        &#125;
    
        /**
         * @param isDeleted The isDeleted to set.
         */
        public void setActive&#40;boolean isActive&#41; &#123;
            this.isActive = isActive;
        &#125;
        
        /* &#40;non-Javadoc&#41;
         * @see java.lang.Object#toString&#40;&#41;
         */
        public String toString&#40;&#41; &#123;
            return this.getClass&#40;&#41;+" &#58; " + "name = "+this.getName&#40;&#41; + " , description = " + this.getDescription&#40;&#41; + " , Active = " + this.isActive&#40;&#41;;
        &#125;
        
        public boolean equals&#40;Object o&#41; &#123;
    		if &#40;this == o&#41; return true;
    		if &#40;!&#40;o instanceof SubStatus&#41;&#41; return false;
    
    		final SubStatus substatus = &#40;SubStatus&#41; o;
    
    		if &#40;!auditInfo.getCreatedDate&#40;&#41;.equals&#40;substatus.auditInfo.getCreatedDate&#40;&#41;&#41;&#41; return false;
    		if &#40;name != null ? !name.equals&#40;substatus.name&#41; &#58; substatus.name != null&#41; return false;
    
    		return true;
    	&#125;
    
    	public int hashCode&#40;&#41; &#123;
    		int result;
    		result = &#40;name != null ? name.hashCode&#40;&#41; &#58; 0&#41;;
    		result = 29 * result + auditInfo.getCreatedDate&#40;&#41;.hashCode&#40;&#41;;
    		return result;
    	&#125;
    
    	
        
    &#125;
    Here's our junit test case (just one test method)

    Code:
    public class SapModuleDAOTest extends DAOTestCase &#123;
    	
    	private String tableName = "SAPMODULE";
        private BaseAdminEntityDAO sapModuleDao = null; 
        private Long id=new Long&#40;"1"&#41;;
    
        public static void main&#40;String&#91;&#93; args&#41; &#123;
            junit.textui.TestRunner.run&#40;SapModuleDAOTest.class&#41;;
        &#125;
        
        public SapModuleDAOTest&#40;String name&#41; &#123;
            super&#40;name&#41;;
            sapModuleDao = &#40;BaseAdminEntityDAO&#41; ctx.getBean&#40;"baseAdminEntityDAO"&#41;;
        &#125;
        
        public final void testGetById&#40;&#41; throws Exception &#123;
           
        		Long id;
        		String name = "SapModule"+System.currentTimeMillis&#40;&#41;;
        		String description = "SapModule desc";
            	boolean active = true;
            
            	//create a POJO
            SapModule sapModule = new SapModule&#40;&#41;;
            sapModule.setName&#40;name&#41;;
            sapModule.setDescription&#40;description&#41;;
            sapModule.setActive&#40;active&#41;;
    
            //Save
            sapModuleDao.save&#40;sapModule&#41;;
            
            //Is the Local POJO fine ?
            id=sapModule.getId&#40;&#41;;
            long startGetById = System.currentTimeMillis&#40;&#41;;
        		SapModule sapModule1 = &#40;SapModule&#41; sapModuleDao.getById&#40;SapModule.class, id&#41;;
            long endGetById = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"***Time taken for  SapModuleGetById - " + &#40;endGetById-startGetById&#41;+ " ms"&#41;;
            Assert.assertNotNull&#40;"SapModule retrieved correctly", sapModule1&#41;;
        &#125;
         public final void testGetByInvalidId&#40;&#41; throws Exception &#123;
            Long testID = new Long&#40;"-1998"&#41;;
            SapModule sapModule = null;
            try &#123;
                sapModule = &#40;SapModule&#41; sapModuleDao.getById&#40;SapModule.class, testID&#41;;
                fail&#40;"Invalid behavior"&#41;;
            &#125; catch &#40;ObjectRetrievalFailureException ex&#41; &#123;&#125;
        &#125;
        
        public final void testAddSapModule&#40;&#41; &#123;
            //test attributes
            String name = "SapModule"+System.currentTimeMillis&#40;&#41;;
            String description = "Sap Module";
            boolean active = true;
            
            //create a POJO
            SapModule sapModule = new SapModule&#40;&#41;;
            sapModule.setName&#40;name&#41;;
            sapModule.setDescription&#40;description&#41;;
            sapModule.setActive&#40;active&#41;;
            
            //Save
            sapModuleDao.save&#40;sapModule&#41;;
            
            //Is the Local POJO fine ?
            assertTrue&#40;sapModule.getId&#40;&#41; != null&#41;;  
            assertTrue&#40;sapModule.getName&#40;&#41;.equals&#40;name&#41;&#41;;  
            assertTrue&#40;sapModule.getDescription&#40;&#41;.equals&#40;description&#41;&#41;;
            assertTrue&#40;sapModule.isActive&#40;&#41; == active&#41;;
            
            //OK, is the persisted entity fine ?
            SapModule storedSapModule = &#40;SapModule&#41; sapModuleDao.getById&#40;SapModule.class, sapModule.getId&#40;&#41;&#41;;
            Assert.assertNotNull&#40;"SapModule retrieved back correctly", storedSapModule&#41;;
            assertTrue&#40;sapModule.getId&#40;&#41;.equals&#40;storedSapModule.getId&#40;&#41;&#41;&#41;;  
            assertTrue&#40;sapModule.getName&#40;&#41;.equals&#40;storedSapModule.getName&#40;&#41;&#41;&#41;;  
            assertTrue&#40;sapModule.getDescription&#40;&#41;.equals&#40;storedSapModule.getDescription&#40;&#41;&#41;&#41;;
            assertTrue&#40;sapModule.isActive&#40;&#41; == storedSapModule.isActive&#40;&#41;&#41;;
        &#125;
    
        public final void testSaveSapModule&#40;&#41; throws Exception &#123;
        		Long id;
    		String name = "SapModule"+System.currentTimeMillis&#40;&#41;;
    		String description = "SapModule desc";
    		boolean active = true;
    		
    		//create a POJO
    	    SapModule sapModule = new SapModule&#40;&#41;;
    	    sapModule.setName&#40;name&#41;;
    	    sapModule.setDescription&#40;description&#41;;
    	    sapModule.setActive&#40;active&#41;;
    	    
    	    //Save
            long startSave = System.currentTimeMillis&#40;&#41;;
    	    sapModuleDao.save&#40;sapModule&#41;;
            long endSave = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"***Time taken for  SapModuleSave - " + &#40;endSave-startSave&#41;+ " ms"&#41;;
        
    	    //Is the Local POJO fine ?
    	    id=sapModule.getId&#40;&#41;;  
            sapModule = &#40;SapModule&#41; sapModuleDao.getById&#40;SapModule.class, id&#41;;
          
            //test attributes
            name = "SapModule"+System.currentTimeMillis&#40;&#41;;
            description = "SapModule description";
            active = false;
            
            //update the POJO
            sapModule.setName&#40;name&#41;;
            sapModule.setDescription&#40;description&#41;;
            sapModule.setActive&#40;active&#41;;
            sapModuleDao.save&#40;sapModule&#41;;
            
            //OK, is the persisted entity fine ?
            SapModule storedSapModule = &#40;SapModule&#41; sapModuleDao.getById&#40;SapModule.class, sapModule.getId&#40;&#41;&#41;;
            Assert.assertNotNull&#40;"sap Module retrieved back correctly", storedSapModule&#41;;
            assertTrue&#40;sapModule.getId&#40;&#41;.equals&#40;storedSapModule.getId&#40;&#41;&#41;&#41;;  
            assertTrue&#40;sapModule.getName&#40;&#41;.equals&#40;storedSapModule.getName&#40;&#41;&#41;&#41;;  
            assertTrue&#40;sapModule.getDescription&#40;&#41;.equals&#40;storedSapModule.getDescription&#40;&#41;&#41;&#41;;
            assertTrue&#40;sapModule.isActive&#40;&#41; == storedSapModule.isActive&#40;&#41;&#41;;
        &#125;
        
        public final void testGetAllActive&#40;&#41; &#123;
            long startActive = System.currentTimeMillis&#40;&#41;;
            Collection sapModules = sapModuleDao.getAllActive&#40;SapModule.class&#41;;
            long endActive = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Time taken for  SapModuleGetAllActive - " + &#40;endActive-startActive&#41;+ " ms"&#41;;
            Iterator sapModulesIterator = sapModules.iterator&#40;&#41;;
            while &#40;sapModulesIterator.hasNext&#40;&#41; == true&#41; &#123;
                SapModule sapModule = &#40;SapModule&#41; sapModulesIterator.next&#40;&#41;;
                Assert.assertTrue&#40;"Active verification", sapModule.isActive&#40;&#41;&#41;;
                System.out.println&#40;" ***SapModuleGetAllActive " + sapModule&#41;;
            &#125;
        &#125;
    
        public final void testGetAllInActive&#40;&#41; &#123;
            long startInActive = System.currentTimeMillis&#40;&#41;;
            Collection sapModules = sapModuleDao.getAllInActive&#40;SapModule.class&#41;;
            long endInActive = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Time taken for  SapModuleGetAllInActive - " + &#40;endInActive-startInActive&#41;+ " ms"&#41;;
            Iterator sapModulesIterator = sapModules.iterator&#40;&#41;;
            while &#40;sapModulesIterator.hasNext&#40;&#41; == true&#41; &#123;
                SapModule sapModule = &#40;SapModule&#41; sapModulesIterator.next&#40;&#41;;
                System.out.println&#40;" ***SapModuleGetAllInActive " + sapModule&#41;;
            &#125;
        &#125;
        
        public final void testFindByName&#40;&#41; throws Exception &#123;
            long startFindByName = System.currentTimeMillis&#40;&#41;;
            Collection sapModules = sapModuleDao.findByName&#40;SapModule.class,"SapModule11%"&#41;;
            long endFindByName = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Time taken for  SapModuleFindByName - " + &#40;endFindByName-startFindByName&#41;+ " ms"&#41;;
            Iterator sapModulesIterator = sapModules.iterator&#40;&#41;;
            while &#40;sapModulesIterator.hasNext&#40;&#41; == true&#41; &#123;
                SapModule sapModule = &#40;SapModule&#41; sapModulesIterator.next&#40;&#41;;
                System.out.println&#40;" ***SapModuleFindByName " + sapModule&#41;;
            &#125;
        &#125;
        
        public final void testFindByNamedQuery&#40;&#41; throws Exception &#123;
            long startFindByNamedQuery = System.currentTimeMillis&#40;&#41;;
            Collection sapModules = sapModuleDao.findByNamedQuery&#40;"SapModuleGetAllActive"&#41;;
            long endFindByNamedQuery = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Time taken for  Named-SapModuleGetAllActive - " + &#40;endFindByNamedQuery-startFindByNamedQuery&#41;+ " ms"&#41;;
            Iterator sapModulesIterator = sapModules.iterator&#40;&#41;;
            while &#40;sapModulesIterator.hasNext&#40;&#41; == true&#41; &#123;
                SapModule sapModule = &#40;SapModule&#41; sapModulesIterator.next&#40;&#41;;
                System.out.println&#40;" ***Named-SapModuleGetAllActive " + sapModule&#41;;
            &#125;
        &#125;
        
        public final void testFindByNamedQueryAndNamedParam&#40;&#41; throws Exception &#123;
            String &#91;&#93; params= new String&#91;1&#93;;
            String &#91;&#93; values= new String&#91;1&#93;;
            params&#91;0&#93; = "name";
            values&#91;0&#93; = "SapModule11%";
            long startFindByNamedQueryAndNamedParam = System.currentTimeMillis&#40;&#41;;
            Collection sapModules = sapModuleDao.findByNamedQueryAndNamedParam&#40;"SapModuleFindByName",params,values&#41;;
            long endFindByNamedQueryAndNamedParam = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Time taken for  NamedParam-SapModuleFindByName - " + &#40;endFindByNamedQueryAndNamedParam-startFindByNamedQueryAndNamedParam&#41;+ " ms"&#41;;
            Iterator sapModulesIterator = sapModules.iterator&#40;&#41;;
            while &#40;sapModulesIterator.hasNext&#40;&#41; == true&#41; &#123;
                SapModule sapModule = &#40;SapModule&#41; sapModulesIterator.next&#40;&#41;;
                System.out.println&#40;" ***NamedParam-SapModuleFindByName " + sapModule&#41;;
            &#125;
        &#125;
    Here's the DAO implementation:

    Code:
    public class HibernateBaseAdminEntityDAO extends HibernateDaoSupport implements
            BaseAdminEntityDAO &#123;
    
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#save&#40;java.lang.Object&#41;
         */
        public void save&#40;Object entity&#41; &#123;
       	System.out.println&#40;"entering SAVE..."&#41;;
        	    long startTime = System.currentTimeMillis&#40;&#41;;
            getHibernateTemplate&#40;&#41;.saveOrUpdate&#40;entity&#41;;
            long endTime = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Total time taken to SAVE&#58; " + &#40;endTime - startTime&#41; + " ms!!!"&#41;;
         	System.out.println&#40;"leaving SAVE..."&#41;;
        &#125;
    
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#getAllActive&#40;java.lang.Class&#41;
         */
        public List getAllActive&#40;Class entityClass&#41; &#123;
        	long startTime = System.currentTimeMillis&#40;&#41;;
            List list =  getHibernateTemplate&#40;&#41;.find&#40;"from SubStatus e where e.active = 1"&#41;;
            long endTime = System.currentTimeMillis&#40;&#41;;
            System.out.println&#40;"Total time taken by getAllActive&#58; " + &#40;endTime - startTime&#41; + " ms!!!"&#41;;
            return list;
        &#125;
        
        
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#getAllInActive&#40;java.lang.Class&#41;
         */
        public List getAllInActive&#40;Class entityClass&#41; &#123;
            return getHibernateTemplate&#40;&#41;.find&#40;"from " + entityClass.getName&#40;&#41; + " e where e.active = 0"&#41;;
        &#125;
        
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#getAll&#40;java.lang.Class&#41;
         */
        public List getAll&#40;Class entityClass&#41; &#123;
            return getHibernateTemplate&#40;&#41;.loadAll&#40;entityClass&#41;;
        &#125;
    
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#getById&#40;java.lang.Class, java.lang.Long&#41;
         */
        public Object getById&#40;Class entityClass, Long id&#41; &#123;
            BaseAdminEntity entity = &#40;BaseAdminEntity&#41; getHibernateTemplate&#40;&#41;.get&#40;entityClass, id&#41;;
            if &#40;entity == null&#41; &#123;
                throw new ObjectRetrievalFailureException&#40;entityClass, id&#41;;   
            &#125;
            return entity;
        &#125;
        
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#findByName&#40;java.lang.Class,java.lang.String&#41;
         */
        public List findByName&#40;Class entityClass,String name&#41; &#123;
            return getHibernateTemplate&#40;&#41;.find&#40;"from " + entityClass.getName&#40;&#41; + " e where e.name = ?", name&#41;;
         &#125;
        
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#findByNamedQuery&#40;java.lang.String&#41;
         */
        public List findByNamedQuery&#40;String queryName&#41; &#123;
            return getHibernateTemplate&#40;&#41;.findByNamedQuery&#40;queryName&#41;;
         &#125;
        
        /* &#40;non-Javadoc&#41;
         * @see com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO#findByNamedQueryAndNamedParam&#40;java.lang.String,java.lang.String &#91;&#93;,java.lang.Object &#91;&#93;&#41;
         */
        public List findByNamedQueryAndNamedParam&#40;String queryName,String &#91;&#93; params,Object &#91;&#93; values&#41; &#123;
            return getHibernateTemplate&#40;&#41;.findByNamedQueryAndNamedParam&#40;queryName,params,values&#41;;
         &#125;

    As you can see, i'm using System.currentTimeinMillis to get the time that getHibernateTemplate.saveOrUpdate takes in the DAO implementation.

    Our applicationContext.xml file looks like this (only the relevant portion)



    Code:
    <bean id="baseAdminEntityDAOTarget" class="com.apple.ist.espresso.admin.dao.hibernate.HibernateBaseAdminEntityDAO">
    		<property name="sessionFactory"><ref local="sessionFactory"/></property>
    	</bean>
    
    <bean id="baseAdminEntityDAO" class="org.springframework.aop.framework.ProxyFactoryBean"> 
     		<property name="proxyInterfaces"> 
     			<value>com.apple.ist.espresso.admin.dao.BaseAdminEntityDAO</value> 
     		</property> 
     		<property name="target"><ref local="baseAdminEntityDAOTarget"/>
    			<!-- <bean class="com.apple.ist.espresso.admin.dao.hibernate.HibernateBaseAdminEntityDAO">
    				<property name="sessionFactory"><ref local="sessionFactory"/></property>
    			</bean> -->
    		</property>
     		<property name="interceptorNames"> 
    			 <list> 
    				
    				<value>theLoggingBeforeAdvisor</value>  
    			<!--	<value>authorizationInterceptor</value> -->
               		<value>theLoggingAfterAdvisor</value>
               		<value>thePerformanceMonitorAdvisor</value>
               		<!--value>historyInterceptor</value-->
    			</list> 
     		</property> 
     	</bean>

    Our test case output is as follows:

    Code:
    In END of static initializer..
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    entering SAVE...
    Hibernate&#58; select SAP_MODULE_SEQ.nextval from dual
    Total time taken to SAVE&#58; 267 ms!!!
    leaving SAVE...
    Hibernate&#58; insert into SAP_MODULE &#40;CREATED_DATE, CREATED_BY_ID, CREATED_BY_NAME, MODIFIED_DATE, MODIFIED_BY_ID, MODIFIED_BY_NAME, NAME, IS_ACTIVE, DESCRIPTION, id&#41; values &#40;?, ?, ?, ?, ?, ?, ?, ?, ?, ?&#41;
    ***Time taken for  SapModuleGetById - 71 ms
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    Hibernate&#58; select sapmodule0_.id as id0_, sapmodule0_.CREATED_DATE as CREATED2_50_0_, sapmodule0_.CREATED_BY_ID as CREATED3_50_0_, sapmodule0_.CREATED_BY_NAME as CREATED4_50_0_, sapmodule0_.MODIFIED_DATE as MODIFIED5_50_0_, sapmodule0_.MODIFIED_BY_ID as MODIFIED6_50_0_, sapmodule0_.MODIFIED_BY_NAME as MODIFIED7_50_0_, sapmodule0_.NAME as NAME50_0_, sapmodule0_.IS_ACTIVE as IS9_50_0_, sapmodule0_.DESCRIPTION as DESCRIP10_50_0_ from SAP_MODULE sapmodule0_ where sapmodule0_.id=?
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    entering SAVE...
    Hibernate&#58; select SAP_MODULE_SEQ.nextval from dual
    Total time taken to SAVE&#58; 28 ms!!!
    leaving SAVE...
    Hibernate&#58; insert into SAP_MODULE &#40;CREATED_DATE, CREATED_BY_ID, CREATED_BY_NAME, MODIFIED_DATE, MODIFIED_BY_ID, MODIFIED_BY_NAME, NAME, IS_ACTIVE, DESCRIPTION, id&#41; values &#40;?, ?, ?, ?, ?, ?, ?, ?, ?, ?&#41;
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    entering SAVE...
    Hibernate&#58; select SAP_MODULE_SEQ.nextval from dual
    Total time taken to SAVE&#58; 30 ms!!!
    leaving SAVE...
    Hibernate&#58; insert into SAP_MODULE &#40;CREATED_DATE, CREATED_BY_ID, CREATED_BY_NAME, MODIFIED_DATE, MODIFIED_BY_ID, MODIFIED_BY_NAME, NAME, IS_ACTIVE, DESCRIPTION, id&#41; values &#40;?, ?, ?, ?, ?, ?, ?, ?, ?, ?&#41;
    ***Time taken for  SapModuleSave - 851 ms
    entering SAVE...
    Total time taken to SAVE&#58; 0 ms!!!
    leaving SAVE...
    In ONFlushDirty..
    Hibernate&#58; update SAP_MODULE set NAME=?, IS_ACTIVE=?, DESCRIPTION=? where id=?
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    Hibernate&#58; select substatus0_.id as id, substatus0_.CREATED_DATE as CREATED2_56_, substatus0_.CREATED_BY_ID as CREATED3_56_, substatus0_.CREATED_BY_NAME as CREATED4_56_, substatus0_.MODIFIED_DATE as MODIFIED5_56_, substatus0_.MODIFIED_BY_ID as MODIFIED6_56_, substatus0_.MODIFIED_BY_NAME as MODIFIED7_56_, substatus0_.NAME as NAME56_, substatus0_.IS_ACTIVE as IS9_56_, substatus0_.DESCRIPTION as DESCRIP10_56_ from SUBSTATUS substatus0_ where substatus0_.IS_ACTIVE=1
    Total time taken by getAllActive&#58; 476 ms!!!
    Time taken for  SapModuleGetAllActive - 1321 ms
    ESPRESSO_HOME&#58; ..
    current working dir&#58; /Users/manjulajayaraman/test4/JADE/jadecvs/NewEspresso/ServerDevelopment/Phase2
    Hibernate&#58; select sapmodule0_.id as id, sapmodule0_.CREATED_DATE as CREATED2_50_, sapmodule0_.CREATED_BY_ID as CREATED3_50_, sapmodule0_.CREATED_BY_NAME as CREATED4_50_, sapmodule0_.MODIFIED_DATE as MODIFIED5_50_, sapmodule0_.MODIFIED_BY_ID as MODIFIED6_50_, sapmodule0_.MODIFIED_BY_NAME as MODIFIED7_50_, sapmodule0_.NAME as NAME50_, sapmodule0_.IS_ACTIVE as IS9_50_, sapmodule0_.DESCRIPTION as DESCRIP10_50_ from SAP_MODULE sapmodule0_ where sapmodule0_.IS_ACTIVE=0
    Time taken for  SapModuleGetAllInActive - 868 ms

    As you can see, the time taken to execute DAO's save method is only 30ms for the testSaveSapModule method but the overall time take to just call the DAO's save method per the testSaveSapModule test case using the same System.currentTimeinMillis is 851 ms.

    Does that mean that the spring based interceptor using which i wrap my DAO is taking the rest of the time???

    Could someone please clarify this?

    Thanks for any input in advance!

  • #2
    as your logs show, the sql insert statement is occurring after the save method completes, this is normal befaviour where the hibernate session only gets flushed on transaction completion. Temporarily add getHibernateTemplate().flush() after your call to getHibernateTemplate().saveOrUpdate() and retime the test.

    Comment


    • #3
      As gcosgrave said Hibernate does not actually writes to the database when you actually want. To make your test even better add transactions into the mixt and see the overhead with transaction support (through Spring interceptor) and without it (no transaction at all).
      You'll be surpised. Also try to search the wiki and forums for some info - you'll get some good benchmarks and also some nice best practices for benchmarkings.

      Comment

      Working...
      X