Simple hibernate query returning very slowly

Trym picture Trym · Jul 7, 2011 · Viewed 54.4k times · Source

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

Trym picture Trym · Jul 8, 2011

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.