Why is the Hibernate query.list() slow?

Question

I am using Hibernate 4.1.6 and having issues with the speed that a list is built. I am running the following query.

public void doQuery(final Baz baz){
  final Query query = getSessionFactory().getCurrentSession().createQuery(
          "select c.id, foo.someValue from Foo as foo "+
          "join foo.a as a"+
          "join foo.b as b "+
          "join b.c as c "+
          "where baz=:baz"
          );
  query.setParameter("baz", baz);
  Long start=System.currentTimeMillis();
  final List<Object[]> list = query.list();
  Long end=System.currentTimeMillis();
  System.out.println((end-start));
}

I set hibernate debugging on to get the actual query that is sent to the database. I ran that query directly in the database and it returned 23,000 rows in 0.015 ms. So, I'm guessing the query is not the issue. The example above shows it takes ~ 32 seconds to create that list. Is there something that can be done to speed that up?

Update: I tried using the createSQLQuery() method using the hibernate debugging query and it ran just as slow as the createQuery() method.

Update: I tried using a stateless session but it ran just as slow.

Update: I outputted some statistics (setting the hibernate.generate_statistics flag to true) but nothing looks alarming to me:

Hibernate SessionFactory Statistics [
    Number of connection requests[4]
    Number of flushes done on the session (either by client code or by hibernate[3]
    The number of completed transactions (failed and successful).[3]
    The number of transactions completed without failure[3]
    The number of sessions your code has opened.[4]
    The number of sessions your code has closed.[3]
    Total number of queries executed.[4]
    Time of the slowest query executed.[28258]
    the number of collections fetched from the DB.[6]
    The number of collections loaded from the DB.[6]
    The number of collections that were rebuilt[0]
    The number of collections that were 'deleted' batch.[0]
    The number of collections that were updated batch.[0]
    The number of your objects deleted.[0]
    The number of your objects fetched.[1]
    The number of your objects actually loaded (fully populated).[204]
    The number of your objects inserted.[1]
    The number of your object updated.[0]
]

Hibernate SessionFactory Query Statistics [
    total hits on cache by this query[0]
    total misses on cache by this query[0]
    total number of objects put into cache by this query execution[0]
    Number of times this query has been invoked[1]
    average time for invoking this query.[28258]
    maximum time incurred by query execution[28258]
    minimum time incurred by query execution[28258]
    Number of rows returned over all invocations of this query[23303]
]

Update: I see the same slowness when doing a next() from a ScrollableResults from a native query. Note that I am doing nothing in the loop.

    ScrollableResults results = query.scroll();
    Long start=System.currentTimeMillis();
    while (results.next()) {
       //do nothing
    }
    Long end=System.currentTimeMillis();
    System.out.println((end-start));

Answer 1

I am not sure, but I am facing this problem in my current project.

In my case the problem is that hibernate uses cross join to do implicit joins, so (in my opinion) it takes time after fetching the data from database in order to construct the results (maybe using reflection).

My solution was to use inner join explicitly.

to your problem, I think that you may use inner join explicitly instead of just join.

Answer 2

We ran into a similar issue, dunno if it's related. Basically, since we were newing up new SessionFactorys once per query, it was doing queries like:

 select streamref0_.UUID as UUID145_, streamref0_.Tape_TapeId as Tape2_145_ from StreamRefToTape streamref0_ where streamref0_.UUID=?

You'll notice the large numbers in there. Turns out that it increments once per new session factory. Anyway, this was causing oracle to spend all its time doing a new plan for each query (it reported cpu was almost all in "hard parse" time generating new plans--I guess Oracle is slow to generate plans that it hasn't seen before?). The fix in this particular case was to just use the same factory instead of a new one each time. See also Hibernate produce different SQL for every query

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:2588723819082 explains hard parses, which are apparently bad.

Another possible fix is to use "raw sql" (jdbc) or possibly raw sql queries within hibernate, though that didn't seem to fix the problem in this particular case somehow...

Answer 3

I ran that query directly in the database and it returned 23,000 rows in 0.015 ms. So, I'm guessing the query is not the issue.

That may be premature, as query execution times depend on a lot more than the query text. Even if they queries are run on the same data, how do you know that the database used the same execution plan? How do you know that it gets the same amount of cache hits in its disk cache? For instance, hibernate uses prepared statements when talking to the database, but you probably didn't. In Oracle, execution plans are cached by query text, so a different query text means a freshly computed execution plan. Since the cached execution plan may have been formed based on different query parameters it may very well be different - and that can change execution times by orders of magnitude. Note that I am not saying that it is the database, but I wouldn't discount the possibility.

Therefore, the first thing you should do is measure whether the database, or something running in your JVM is wasting all that time. A simple way to do that is to watch the JVMs cpu consumption as the query is being executed. If it is significantly less than one thread, the JVM is waiting for something - presumably the database.

If it is the database, use the optimization tools of your database to capture the execution plan, and other relevant performance metrics.

If it is in the JVM, use a Profiler to pinpoint the performance bottleneck.

Answer 4

If the queries (with show_sql) don't seem to have a problem, then maybe it's in the code. Start up VisualVM (comes with the JDK as jvisualvm) and use its CPU profiler to find out which methods take the longest time.

Answer 5

I am not 100% certain on this answer, since tuning / optimization issues are always so difficult to pinpoint.

However, based on the fact that you turned on show_sql, extracted the query, and ran it directly against the database and saw sub-second results vs execution time through Hibernate Query, I am focusing on the manner in which Hibernate is constructing and hydrating objects that result from the query.list() call.

Here is another user who mentioned similar Query performance issues in Hibernate, and saw dramatic performance increases by adding full convenience constructors (constructors that accept a value for each field) in the POJO: Simple hibernate query returning very slowly

It sounds like they stumbled upon this fix, and there was not a clear understanding of why this worked. There was speculation regarding Hibernate having to use reflection to detect properties. I am curious myself and am planning to dig into the source code for Hibernate to better understand this when I have a chance. In the meantime, though, you may wish to look into adding these full constructors with parameters for all of your POJO class attributes and see if that makes a difference.

Please do let me know what you find, as I am very interested in Hibernate performance optimization. Thanks!