Simple hibernate query returning very slowly

Question

I have the following hibernate query:

Query query = session.createQuery("from MyHibernateClass");
List<MyHibernateClass> result = query.list();// executes in 7000ms

When logging the sql being executed in MySQL I see

select 
  myhibernat0_.myFirstColumn as myfirstcolumn92_, 
  myhibernat0_.mySecondColumn as mysecondcolumn92_, 
  myhibernat0_.mythirdcolumn as mythirdcolumn92_, 
  myhibernat0_.myFourthColumn as myfourthcolumn92_ 
from MyHibernateClass myhibernat0_ 
where (1=1);

When measurering the java code in the jvm on a small dataset of 3500 rows in MyHibernateClass database table this takes about 7000ms.

If I on the otherhand uses direct jdbc as follows:

Statement statement = session.connection().createStatement();
ResultSet rs = statement.executeQuery("select * from MyHibernateClass");// 7ms
List<MyHibernateClass> result = convert(rs);// executes in 20ms

I see the same sql going into the database but now the time spend in the java code in the jvm is 7ms.

The MyHibernateClass is a simple java bean class with getters and setters, I use no special resulttransformers as can be seen in the example. I only need a read-only instance of the class, and it doesn't need to be attached to the hibernate session.

I would rather like to use the hibernate version but cannot accept the execution times.

Added information: After adding hibernate logging I see

[2011-07-07 14:26:26,643]DEBUG [main] [logid: ] - 
  org.hibernate.jdbc.AbstractBatcher.logOpenResults(AbstractBatcher.java:426) - 
  about to open ResultSet (open ResultSets: 0, globally: 0)

followed by 3500 of the following log statements

[2011-07-07 14:26:26,649]DEBUG [main] [logid: ] - 
  org.hibernate.loader.Loader.getRow(Loader.java:1197) - 
  result row: EntityKey[com.mycom.MyHibernateClass#1]

followed by 3500 log statements like

[2011-07-07 14:27:06,789]DEBUG [main] [logid: ] - 
  org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:130) - 
  resolving associations for [com.mycom.MyHibernateClass#1]
[2011-07-07 14:27:06,792]DEBUG [main] [logid: ] - 
  org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:226) - 
  done materializing entity [com.mycom.MyHibernateClass#1]

What does this mean?

What is Hibernate doing in the first implementation, how can I find out?

Answer 1

Adding a constructor with all attributes of the class did the trick, now the execution times are 70ms for the hibernate query. Previously the class only had a default constructor without arguments and a constructor with the entity id argument.

Answer 2

I know this is an old question but here is what fixed it for me...

In your hibernate.cfg.xml make sure you have the correct !DOCTYPE... it should be as follows:

<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD 3.0//EN" "http://www.hibernate.org/dtd/hibernate-configuration-3.0.dtd">

Answer 3

If you utilize Log4j in your application you can set a variety of different logging options specific to Hibernate to get a better picture of what is going on behind the scenes in Hibernate.

http://docs.jboss.org/hibernate/core/3.3/reference/en/html/session-configuration.html#configuration-logging

My guess is that this is the typical initial load time that occurs when first calling an HQL query in an application. Subsequent HQL queries should be noticeably and considerably faster after this first one.

Answer 4

It took me 10 seconds to execute a simple select all query before I found out that DOCTYPE tag is written wrongly in hibernate.cfg.xml and *mapping object*.hbm.class

Make sure that hibernate.cfg.xml start with

<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD 3.0//EN" "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">

And mapping xml.class with

<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN" "http://www.hibernate.org/dtd/hibernate-mapping-3.0.dtd">

Now it took me 1-2 seconds to execute any queries.

Answer 5

I had an incident where my application was always using every row in the result set of a query. I found a 40-fold increase in speed by setting my fetch size using the setFetchSize method below. (The performance improvement includes the addition of the count query.)

    Long count = getStoreCount(customerId);

    Query query = session.getNamedQuery("hqlGetStoresByCustomerId")
            .setString("i_customerid",customerId)
            .setFetchSize(count.intValue());

Be careful while doing this; my data set had about 100 rows, and it was scoped to a the life of a web request. If you have larger data sets, you will be eating Java Heap for the duration of the existence of that data, prior to returning it to the Java Heap.

Answer 6

Based on the new information I felt I should provide another answer. The difference looks like that you have a one-to-many association specified for a List or Set property in your bean.

You are probably specifying that lazy=false which will turn off lazy loading. With lazy loading turned off it will fetch every associated record for every MyHibernateClass entity and this is why it is taking so long to execute.

Try setting lazy=true and this will perform much faster and then only retrieve the associated entities when explicitly requesting them from the entity.