Query performance problem

dho · **Joined:** Tue Aug 24, 2004 2:26 pm **Posts:** 6

Hibernate version: 2.1.6

Mapping documents:
Department:

Code:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
   "-//Hibernate/Hibernate Mapping DTD//EN"
   "http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>
    <class name="com.paymentone.hibernate.prototype.Department" table="department">
        <id name="id" type="string" unsaved-value="null">
            <generator class="uuid.string">                
            </generator>
        </id>
        <timestamp
        column="timestamp"
        name="timestamp"
        unsaved-value="null"/>        
        <property name="name" type="string"/>                        
        <bag name="employees" table="employee" lazy="true" inverse="true" cascade="all">
           <key column="dept"/>
           <one-to-many class="com.paymentone.hibernate.prototype.Employee"/>
        </bag>
    </class>
</hibernate-mapping>

Employee:

Code:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping
    PUBLIC "-//Hibernate/Hibernate Mapping DTD//EN"
    "http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>

    <class name="com.paymentone.hibernate.prototype.Employee" table="employee">
        <id name="id" type="string" unsaved-value="null">
            <generator class="uuid.string">                
            </generator>
        </id>

        <property name="name" type="string"/>
        
        <property name="salary" type="float"/>        
        <many-to-one name="dept" class="com.paymentone.hibernate.prototype.Department"/>
    </class>        

</hibernate-mapping>

Code between sessionFactory.openSession() and session.close():

Code:

Session s = HibernateUtil.currentSession();
        try {
            List depts = s.find("from Department");  
            return depts;
        } finally {
            HibernateUtil.closeSession();
        }

Full stack trace of any exception that occurs:
NA

Name and version of the database you are using:
Oracle 9.2.0.4

Debug level Hibernate log excerpt:

I am trying to compare the performance of the above code with pure JDBC code as that looks like the following:

Code:

public List queryDepartmentsJDBC(Connection conn) throws Exception{
        PreparedStatement pstmt = null;
        ResultSet rs = null;
        try {
            pstmt = conn.prepareStatement("select id, name, timestamp from department");
            rs = pstmt.executeQuery();
            List list = new ArrayList();                      
            while (rs.next()) {
                Department dept = new Department();
                dept.setId(rs.getString(1));
                dept.setName(rs.getString(2));
                dept.setTimestamp(rs.getTimestamp(3));
                dept.setEmployees(new ArrayList());
                list.add(dept);
            }
            return list;
        } finally {
            if (pstmt != null) {
                pstmt.close();                
            }
        }
            
    }

For some reason, the query performance for using PreparedStatement is about 3.5 to 4 times better than Hibernate. This is a simple query with no join conditions, did I do something wrong or is that just the overhead of hibernate?

The JDBC driver I am using is: oracle thin 9.2.0.4, and the jdk version is: 1.4.2_03.

Thanks in advance for your help.

mveitas · **Posted:** Tue Aug 24, 2004 2:43 pm

Post the generated Hibernate SQL.

dho · **Joined:** Tue Aug 24, 2004 2:26 pm **Posts:** 6

Thanks for the response:

The query is as follows after turning on show_sql:

Code:

select department0_.id as id, department0_.timestamp as timestamp, department0_.name as name from department department0_

dho · **Joined:** Tue Aug 24, 2004 2:26 pm **Posts:** 6

The extreme slowness may have been caused by missing log4j.properties in my classpath. However, after putting it in, hibernate is still 30-40% slower than JDBC. Again, did I do something wrong or is there any obvious thing that I missed?

Thanks for your help.

The hibernate.cfg.xml file is as follows:

Code:

<?xml version='1.0' encoding='utf-8'?>
<!DOCTYPE hibernate-configuration
    PUBLIC "-//Hibernate/Hibernate Configuration DTD//EN"
    "http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd">

<hibernate-configuration>
   <session-factory>
      <!-- <property name="connection.datasource">java:comp/env/jdbc/quickstart</property> -->
      <property name="show_sql">false</property>
      <property name="dialect">
         net.sf.hibernate.dialect.Oracle9Dialect
      </property>
      <property name="dialect">
         net.sf.hibernate.dialect.OracleDialect
      </property>
      <property name="hibernate.connection.driver_class">
         oracle.jdbc.driver.OracleDriver
      </property>
      <property name="hibernate.connection.username">dho</property>
      <property name="hibernate.connection.password">dho</property>
      <property name="hibernate.connection.url">
         jdbc:oracle:thin:@xxxx:1521:xxx
      </property>
      
      <!-- configuration pool via c3p0--> 
      
      <property name="c3p0.acquire_increment">1</property> 
      <property name="c3p0.idle_test_period">100</property>            
      <property name="c3p0.min_size">0</property> 
      <property name="c3p0.max_size">10</property> 
      <property name="c3p0.max_statements">100</property> 
      <property name="c3p0.timeout">0</property> 
         
      
      <!-- Mapping files -->
      <mapping resource="Cat.hbm.xml" />
      <mapping resource="Employee.hbm.xml" />
      <mapping resource="Department.hbm.xml" />
      <mapping resource="Project.hbm.xml" />
      <mapping resource="HiloTest.hbm.xml" />
      <mapping resource="HiloTest1.hbm.xml" />
      <mapping resource="SequenceHiloTest.hbm.xml" />
      <mapping resource="UUIDTest.hbm.xml" />
   </session-factory>
</hibernate-configuration>

mveitas · **Posted:** Tue Aug 24, 2004 5:18 pm

How are you timing the results? Via System.currentTimeMillis()?

dho · **Joined:** Tue Aug 24, 2004 2:26 pm **Posts:** 6

Yes. What would be a more correct way to do the timing?

mojarrell · **Posted:** Wed Aug 25, 2004 10:28 am

dho wrote:

Yes. What would be a more correct way to do the timing?

I don't know if it's more correct, but I created my own log4j logger with:

Code:

private Logger lgr = Logger.getLogger("com.paymentone.prototype.Prototype");

I use a log4j.properties that looks like this:

Code:

log4j.rootLogger = info, default

# uncomment this section to turn on console output
log4j.appender.default = org.apache.log4j.ConsoleAppender
log4j.appender.default.layout = org.apache.log4j.TTCCLayout
log4j.appender.default.layout.DateFormat = ABSOLUTE

This will give me time to the millisecond in my log output on the console. Then I put log statements before and after each query like so:

Code:

    prototype.lgr.info("before queryDepartmentsHibernate");
    hibernateList = prototype.queryDepartmentsHibernate();
    prototype.lgr.info("after queryDepartmentsHibernate");
    prototype.lgr.info("before queryDepartmentsJDBC");
    jdbcList = prototype.queryDepartmentsJDBC();
    prototype.lgr.info("after queryDepartmentsJDBC");

Here's the log output:

Code:

18:58,976 [main] INFO com.paymentone.prototype.Prototype - before queryDepartmentsHibernate
18:59,211 [main] INFO com.paymentone.prototype.Prototype - after queryDepartmentsHibernate
18:59,211 [main] INFO com.paymentone.prototype.Prototype - before queryDepartmentsJDBC
18:59,273 [main] INFO com.paymentone.prototype.Prototype - after queryDepartmentsJDBC

so both queryies ran in less than a second with 271 departments in my table.

The JDBC was a little faster, but all we did was run a query. If all you're going to do is run a query, then maybe straight JDBC would be the way to go.

But let's say we were going to print out employees by department, and while we were doing that we were going to increase each employee's salary by 10% (because we're feeling generous today<g>) and then print out the new salary. Then the code (for hibernate) would look something like this:

Code:

  public void editEmployeesHibernate() throws Exception {
    Session session = sessionFactory.openSession();
    lgr.info("starting edit");
    Transaction t = session.beginTransaction();
    Iterator deptIterator = session.iterate("from Department");
    while (deptIterator.hasNext()) {
      Department dept = (Department) deptIterator.next();
      lgr.info(dept.getName());
      Bag employees = dept.getEmployees();
      Iterator empIterator = employees.iterator();
      while (empIterator.hasNext()) {
        Employee emp = (Employee) empIterator.next();
        lgr.info("\t" + emp.getName() + " " + emp.getSalary());
        emp.setSalary(emp.getSalary()*1.1f);
        session.save(emp);
        lgr.info("\t New Salary: " + emp.getSalary());
      }
    }
    t.commit();
    session.close();
    lgr.info("ending edit");
  }

This runs in 6 seconds. I would do a comparison JDBC, but I don't even want to think about what the JDBC code would look like to do the same thing... that's why I'm using Hibernate<g>.

mojarrell · **Posted:** Wed Aug 25, 2004 10:31 am

I forgot to say: That's 271 departments and 851 employees.

dho · **Joined:** Tue Aug 24, 2004 2:26 pm **Posts:** 6

Thanks for the responses!