Hibernate performance with simple table

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Hi. I am building a query that contains a LIKE cause via the Criteria api. The query runs quickly (1 or 2 seconds) in SqlDeveloper. The same query takes 8-9 seconds when I run a test case with Hibernate. After I turn on debug, I see the pojo instances getting loaded, and then I get a bunch of TwoPhaseLoad messages indicating that associations are being resolved for each result row (see below - Messages are a PARTIAL excerpt from log; there are many more rows returned).

What I don't understand is that the mapping file only contains primitive types, with absolutely no links/foreign keys to any external tables. It has a straight column-to-attribute mapping for approx. 12 columns. Why is the extra processing taking place to resolve associations? I even set lazy=true in the mapping file, but no change. The same slow query performance exists when I port the code to JBoss and utilize a c3p0 connection pool. Can anybody suggest what could be happening here?

Thanks!

Hibernate version:

3.2

Name and version of the database you are using:

Oracle 10g

Debug level Hibernate log excerpt:

11:34:20,965 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082967]
11:34:20,976 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082968]
11:34:20,977 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082915]
11:34:20,978 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082916]
11:34:20,980 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082917]
11:34:20,981 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082921]
11:34:20,983 DEBUG Loader:1173 - result row: EntityKey[mypackage.MyEntity#26082922]
11:34:20,984 DEBUG AbstractBatcher:389 - about to close ResultSet (open ResultSets: 1, globally: 1)
11:34:20,984 DEBUG AbstractBatcher:374 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:34:20,987 DEBUG TwoPhaseLoad:107 - resolving associations for [mypackage.MyEntity#26082967]
11:34:20,991 DEBUG TwoPhaseLoad:206 - done materializing entity [mypackage.MyEntity#26082967]
11:34:20,993 DEBUG TwoPhaseLoad:107 - resolving associations for [mypackage.MyEntity#26082968]
11:34:20,994 DEBUG TwoPhaseLoad:206 - done materializing entity [mypackage.MyEntity#26082968]
11:34:20,994 DEBUG TwoPhaseLoad:107 - resolving associations for [mypackage.MyEntity#26082915]

mmerder · **Posted:** Tue Jan 27, 2009 1:07 pm

I think, 'TwoPhaseLoad:107 - resolving associations for...' only says, that hibernate now starts to resolve associations, but as there are none, it's done quickly.

How many rows does your query return? Maybe it's just the creation (hydration) of the objects, which takes so long.

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Thanks for responding.

There may be a 100 or more rows returned, but I have even tried limiting the number to 50, 30, 20, etc with setMaxResults(). The performance is still incredibly slow, even when limiting the number of results, in comparison to the standalone SQL query.

mmerder · **Posted:** Tue Jan 27, 2009 3:38 pm

This really seems to be very slow. Could you provide your mapping?

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Sure. Thanks for taking a look...

Code:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
    <class name="mypackage.MyTable" mutable="false" lazy="true" table="mytable@myschema">
    <!-- Specify primary key. This is required to run Hibernate queries with criteria. -->
            <id name="pkey" type="big_decimal">
                <column name="PKEY" precision="22" scale="0" />
            </id>
            <property name="dbcolumn1" type="string">
                <column name="DBCOL1" length="50" />
            </property>
            <property name="dbcolumn2" type="string">
                <column name="DBCOL2" length="30" />
            </property>
            <property name="dbcolumn3" type="string">
                <column name="DBCOL3" length="100" />
            </property>
            <property name="dbcolumn4" type="string">
                <column name="DBCOL4" length="60" />
            </property>
            <property name="dbcolumn5" type="string">
                <column name="DBCOL5" length="45" />
            </property>
            <property name="dbcolumn6" type="string">
                <column name="DBCOL6" length="2" />
            </property>
            <property name="dbcolumn7" type="string">
                <column name="DBCOL7" length="40" />
            </property>
            <property name="dbcolumn8" type="string">
                <column name="DBCOL8" length="10" />
            </property>
            <property name="dbcolumn9" type="string">
                <column name="DBCOL9" length="10" />
            </property>
            <property name="dbcolumn10" type="java.lang.Long">
                <column name="DBCOL10" precision="15" scale="0" />
            </property>
            <property name="dbcolumn11" type="java.lang.Long">
                <column name="DBCOL11" precision="15" scale="0" />
            </property>
            <property name="dbcolumn12" type="java.lang.Long">
                <column name="DBCOL12" precision="15" scale="0" />
            </property>
            <property name="dbcolumn13" type="string">
                <column name="DBCOL13" length="100" />
            </property>
            <property name="dbcolumn14" type="string">
                <column name="DBCOL14" length="40" />
            </property>
            <property name="dbcolumn15" type="string">
                <column name="DBCOL15" length="10" />
            </property>
            <property name="dbcolumn16" type="string">
                <column name="DBCOL16" length="30" />
            </property>
            <property name="dbcolumn17" type="java.lang.Long">
                <column name="DBCOL17" precision="15" scale="0" />
            </property>
            <property name="dbcolumn18" type="java.lang.Long">
                <column name="DBCOL18" precision="15" scale="0" />
            </property>
            <property name="dbcolumn19" type="string">
                <column name="DBCOL19" length="7" />
            </property>
            <property name="dbcolumn20" type="string">
                <column name="DBCOL20" length="7" />
            </property>
            <property name="dbcolumn21" type="string">
                <column name="DBCOL21" length="30" />
            </property>
            <property name="dbcolumn22" type="string">
                <column name="DBCOL22" length="30" />
            </property>
    </class>
</hibernate-mapping>

nordborg · **Posted:** Tue Jan 27, 2009 6:51 pm

The log output doesn't seem to indicate what is taking so long. In the example you show it seems to process 7 rows in just about 20 milliseconds. Add some more for the TwoPhaseLoad and we would arrive at about half a second to load 100 rows. So it seems unlikely that the loading of the result set and creation of entity objects is the source of the problem. Have you found any other place in the log with operations that seem to use up a lot of time?

And just to be sure... You have excluded the startup phase of Hibernate when you measure the time? Eg. the building of a Configuration and SessionFactory. This usually takes several seconds (depends a lot on the number of classes you have mapped).

pkleindl · **Joined:** Thu Jan 08, 2009 3:48 pm **Posts:** 168

How long does a get() with a known ID take?
Maybe the object creation takes the bigger amount of the time...

mmerder · **Posted:** Wed Jan 28, 2009 4:40 am

The mapping seems to be ok. Could you also post the code, where you measure the time it takes hibernate to execute?

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Thank you all for your responses. I decided to step back and simplify everything. I wanted to see how long the actual query execution takes with Hibernate, and compare that with straight JDBC. I created two test cases. I grabbed the SQL statement that Hibernate generated, and created a second JDBC test case to execute it. The timestamps for the two queries are listed below. As you can see, the Hibernate query alone (let's set aside the instance loading time for now) takes 9 seconds. This is consistent if I run it multiple times... The JDBC query takes under a second. In both test cases, I am only bringing back 5 rows.

Based on these results, what would you do to go about determining where the bottleneck is in relation to the *query execution* (forget about result set processing for now)? i.e) What could cause the query execution time to be so different between the two test cases? I am using the exact same JDBC driver for both.

I want to break the problem down, so I am trying to focus on the query time, and worry about the result set processing time later...

Thanks again.

Hibernate:

08:55:51,904 DEBUG SQL:401 - select * from ( select
Hibernate: select * from ( select
08:56:00,349 DEBUG AbstractBatcher:382 - about to open ResultSet (open ResultSets: 0, globally: 0)

Straight JDBC:

11:18:28,293 DEBUG TestJdbcQueryPerformance:50 - Executing query...
11:18:29,090 DEBUG TestJdbcQueryPerformance:50 - Query execution completed. Processing result set...

pkleindl · **Joined:** Thu Jan 08, 2009 3:48 pm **Posts:** 168

The "select * from ( select " looks like you are using setMaxResults, are you using any LEFT JOIN FETCH on an association too?

setMaxResults + fetch on collection doesn't work an causes hibernate to page in memory

also as asked above, your whole code would be interesting if you include Factory-Setup in your calculation or not

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Sure. Here is the relevant factory setup/query code, and no, there are no associations, (as you can see from the mapping file) and I am not using LEFT JOIN FETCH.

Thanks again for taking a look.

Factory setup code (InitSessionFactory class):

Code:

private static org.hibernate.SessionFactory sessionFactory = null;
...
public static SessionFactory getInstance(String configFile) 
{
      if(configFile != null){
         HIBERNATE_CONFIG_FILE = configFile;
      }

      if (sessionFactory == null) {
         log.info("sessionfactory is null, initialize it!");
         initSessionFactory();
         return sessionFactory;
      } else {
         return sessionFactory;
      }
   }

   public Session getCurrentSession() 
   {
      return sessionFactory.openSession();
   }

   private static synchronized void initSessionFactory() 
   {

      String CONFIG_FILE_LOCATION = HIBERNATE_CONFIG_FILE;
      if (sessionFactory == null) {
         try {
            cfg.configure(CONFIG_FILE_LOCATION);
            String sessionFactoryJndiName = cfg
                  .getProperty(Environment.SESSION_FACTORY_NAME);
            log.info("SessionFactory JNDI Name: " + sessionFactoryJndiName);

            if (sessionFactoryJndiName != null) {
               cfg.buildSessionFactory();
               log.debug("get a jndi session factory");
               sessionFactory = (SessionFactory) (new InitialContext())
                     .lookup(sessionFactoryJndiName);
            } else {
               log.debug("classic factory");
               sessionFactory = cfg.buildSessionFactory();
               sessionFactory.openSession();
            }

         } catch (Exception e) {
               System.err.println("%%%% Error Creating HibernateSessionFactory %%%%");
            e.printStackTrace();
            throw new HibernateException(
                  "Could not initialize the Hibernate configuration");
         }
      }
   }

Query execution code (Takes 9 seconds for select statement to execute):

Code:

SessionFactory sessionFactory = null;
Session session = null;
Transaction tx = null;
boolean outcome = false;
      
int maxResults = 5;
      
try 
{ 

sessionFactory = InitSessionFactory.getInstance(ConfigUtility.getDatabaseConfigFileName());
            
session = sessionFactory.getCurrentSession();
tx = session.beginTransaction();
            
Criteria crit = session.createCriteria(MyTable.class);
          
crit.add(Restrictions.eq("dbcolumn6", "value6"));
crit.add(Restrictions.eq("dbcolumn1", "value1"));
crit.add(Restrictions.like("dbcolumn3", "%" + "value3" + "%"));

crit.setFirstResult(0);
crit.setMaxResults(maxResults);
          
List<MyTable> results =  crit.list();
            
HibernateUtil.commit(tx);
HibernateUtil.close(session);

outcome = (results != null && !(results.isEmpty()) && (results.get(0) != null));

 } 
       
catch (Exception e) 
{
          e.printStackTrace();
}
        
assertEquals(true,outcome);
}

pkleindl · **Joined:** Thu Jan 08, 2009 3:48 pm **Posts:** 168

To take just the time the query execution takes you should do something like

Code:

long b = Calendar.getInstance().getTimeInMillis();
List<MyTable> results =  crit.list();
System.out.println("done in "+(Calendar.getInstance().getTimeInMillis()-b)+" ms");

Does this take 9 seconds or everything including the factory setup?

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Thanks. I put the timestamp in, and got back:

done in 9060 ms

This is consistent with the duration of the select statement:

13:27:29,893 DEBUG SQL:401 - select * from ( select
Hibernate: select * from ( select
13:27:38,718 DEBUG AbstractBatcher:382 -

Question is, what could be causing this discrepancy in the duration of the JDBC query execution time and the Hibernate query execution time? Unless Hibernate is doing some post-processing after the query, and is not logging any messages during that processing.

pkleindl · **Joined:** Thu Jan 08, 2009 3:48 pm **Posts:** 168

fascinating :o/

How long does Session.get() take when you call it with a single known ID?

If you take the generated Query and execute it manually it is fast right?

Not sure if this can happen with any number datatype but do you pass the ID as big_decimal to the query? If not specified otherwise those are long usually for our apps...
I just know that search performance can go down on string fields if you dont search as string, even if the string only contains numbers... i hope it is understanable what i mean

AceFrehley · **Joined:** Tue Jan 27, 2009 12:43 pm **Posts:** 16

Hmmm. The Session.get() takes nearly two seconds:

15:28:07,041 INFO TestPATassSessionGetPerformance:67 - done in 1732 ms

Also, the column type for the PK of this table in the database is "NUMBER" (with a NOT NULL constraint), so I believe that BigDecimal is the correct java type translation (Hibernate Tools created the mapping, so I would assume so). I also tried with a completely different table that also has a large number of rows in it, and this table's PK type is "long" instead of "number". That lookup with Session.get() also took 1.6 seconds. This is strange as the select is now going against the primary key. I even removed InitSessionFactory from the mix, and replaced it entirely. Now I am actually doing the following in place of InitSessionFactory, just to simplify as much as possible.

Code:

Configuration cfg = new Configuration();
cfg.configure();
           
sessionFactory = cfg.buildSessionFactory();         
session = sessionFactory.getCurrentSession();

...

There is definitely a strange performance issue with *any* select that takes place...