java - Hibernate is 1000 times slower than sql query

Question

I have this setup

@Table(name ="A")
EntityA {
    Long ID;
    List<EntityB> children;
}

@Table(name ="B")
EntityB {
    Long ID;
    EntityA parent;
    EntityC grandchild;
}

@Table(name ="C")
EntityC {
    Long ID;
}

The SQL query is this (I omitted irrelevant details):

select top 300 from A where ... and ID in (select parent from B where ... and grandchild in (select ID from C where ...)) order by ...

The sql query in direct database or through Hibernate (3.5) SQL runs 1000 faster than using Criteria or HQL to express this.

The SQL generated is identical from HQL and Criteria and the SQL I posted there.

[EDIT]: Correction - the sql was not identical. I didn't try the Hibernate style parameter setting on the management studio side because I did not realize this until later - see my answer.

If I separate out the subqueries into separate queries, then it is fast again.

I tried

• removing all mappings of child, parent, ect.. and just use Long Id references - same thing, so its not a fetching, lazy,eager related.
• using joins instead of subqueries, and got the same slow behaviour with all combinations of fetching and loading.
• setting a projection on ID instead of retrieving entities, so there is no object conversion - still slow

I looked at Hibernate code and it is doing something astounding. It has a loop through all 300 results that end up hitting the database.

private List doQuery(
        final SessionImplementor session,
        final QueryParameters queryParameters,
        final boolean returnProxies) throws SQLException, HibernateException {

    final RowSelection selection = queryParameters.getRowSelection();
    final int maxRows = hasMaxRows( selection ) ?
            selection.getMaxRows().intValue() :
            Integer.MAX_VALUE;

    final int entitySpan = getEntityPersisters().length;

    final ArrayList hydratedObjects = entitySpan == 0 ? null : new ArrayList( entitySpan * 10 );
    final PreparedStatement st = prepareQueryStatement( queryParameters, false, session );
    final ResultSet rs = getResultSet( st, queryParameters.hasAutoDiscoverScalarTypes(), queryParameters.isCallable(), selection, session );

// would be great to move all this below here into another method that could also be used
// from the new scrolling stuff.
//
// Would need to change the way the max-row stuff is handled (i.e. behind an interface) so
// that I could do the control breaking at the means to know when to stop

    final EntityKey optionalObjectKey = getOptionalObjectKey( queryParameters, session );
    final LockMode[] lockModesArray = getLockModes( queryParameters.getLockOptions() );
    final boolean createSubselects = isSubselectLoadingEnabled();
    final List subselectResultKeys = createSubselects ? new ArrayList() : null;
    final List results = new ArrayList();

    try {

        handleEmptyCollections( queryParameters.getCollectionKeys(), rs, session );

        EntityKey[] keys = new EntityKey[entitySpan]; //we can reuse it for each row

        if ( log.isTraceEnabled() ) log.trace( "processing result set" );

        int count;
        for ( count = 0; count < maxRows && rs.next(); count++ ) {

            if ( log.isTraceEnabled() ) log.debug("result set row: " + count);

            Object result = getRowFromResultSet( 
                    rs,
                    session,
                    queryParameters,
                    lockModesArray,
                    optionalObjectKey,
                    hydratedObjects,
                    keys,
                    returnProxies 
            );
            results.add( result );

            if ( createSubselects ) {
                subselectResultKeys.add(keys);
                keys = new EntityKey[entitySpan]; //can't reuse in this case
            }

        }

        if ( log.isTraceEnabled() ) {
            log.trace( "done processing result set (" + count + " rows)" );
        }

    }
    finally {
        session.getBatcher().closeQueryStatement( st, rs );
    }

    initializeEntitiesAndCollections( hydratedObjects, rs, session, queryParameters.isReadOnly( session ) );

    if ( createSubselects ) createSubselects( subselectResultKeys, queryParameters, session );

    return results; //getResultList(results);

}

In this code

final ResultSet rs = getResultSet( st, queryParameters.hasAutoDiscoverScalarTypes(), queryParameters.isCallable(), selection, session );

it hits the database with the full SQL, but there are no results collected anywhere.

Then it proceeds to go through this loop

for ( count = 0; count < maxRows && rs.next(); count++ ) {

Where for every one of the expected 300 results, it ends up hitting the database to get the actual result.

This seems insane, since it should already have all the results after 1 query. Hibernate logs do not show any additional SQL being issued during all that time.

Anyone have any insight? The only option I have is to go to native SQL query through Hibernate.

Answer 1

I finally managed to get to the bottom of this. The problem was being caused by Hibernate setting the parameters separately from the actual SQL query that involved subqueries. So native SQL or not, the performance will be slow if this is done. For example this will be slow:

String sql = some sql that has named parameter = :value
SQLQuery sqlQuery = session.createSQLQuery(sql);
sqlQuery.setParameter ("value", someValue);
List<Object[]> list = (List<Object[]>)sqlQuery.list();

And this will be fast

String sql = some native sql where parameter = 'actualValue'
SQLQuery sqlQuery = session.createSQLQuery(sql);
List<Object[]> list = (List<Object[]>)sqlQuery.list();

It seems that for some reason with letting Hibernate take care of the parameters it ends up getting stuck in the resultSet fetching. This is probably because the underlying query on the database is taking much longer being parameterized. I ended up writing the equivalent of Hibernate Criteria and Restrictions code that sets the parameters directly as above.