Oracle very strange behaviour in AbstractBatcher

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

Dear,

I noticed Hibernate was doing very poor with large resultsets. After a long debugging session including the hibernate source I came to the following rather bizar conclusion.
In our application we have mapped 151 tables using Hibernate and 15 views. The views are mapped 1 object per view (one on one, no relationship whatsoever).
In certain cases we have to retrieve +5000 records from the database. The strange thing is when the code comes into the AbstractBatcher class and performs the following code

Code:

public ResultSet getResultSet(PreparedStatement ps) throws SQLException {
      ResultSet rs = ps.executeQuery();

It takes +10 seconds to do this. It's only the first result of the row, the processing hereafter again is fast.

Now if I remove all the other mappings and only keep the mapping for this view and redo the same unit test the same code runs in less than 2 seconds. If I inspect the prepared statement they are of the same Oracle objects.

We are using Oracle 10G with the ojdbc14.jar and the oracle.jdbc.OracleDriver as driver.

As both these tests were done as unit tests an no other stuff was transfered over this connection I am somewhat puzzled as why this is happening.
I don't know if this is a

Quote:

Hibernate Bug

or something Oracle related but it does strike me that this only happens when I include the other mapping files!!!

Anybody got a clue ?

pepelnm · **Posted:** Fri Jun 09, 2006 1:35 pm

Code:

ResultSet rs = ps.executeQuery();

does not execute Hibernate code, it executes code from the JDBC driver.

Is there a more recent driver?

max · **Posted:** Fri Jun 09, 2006 2:21 pm

so am i, but if it is in executeQuery then either

a) the db driver is doing something ineffective

b) the db is doing something.

How to find out which of these two ? Put a profiler against it ;)

yes, you will need to read the profiler docs this time.

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

pepelnm wrote:

Code:

ResultSet rs = ps.executeQuery();

does not execute Hibernate code, it executes code from the JDBC driver.

Is there a more recent driver?

I know this doesn't execute hibernate code, but if I only enable one mapping it's fast. If I enable them all it is SLOW, so hibernate must be doing something, and another bizar thing is, if I retrieve the connection object from the hibernate API, write the prepared statement myself and provide the given parameters it's fast. So Hibernate is definetely doing something!!!!
Ok, it's in Oracle's driver, and I'll post this in their forum as well, but Hibernate is maybe configuring something it shouldn't do???

I'll check for a more recent driver, but you have to admit it's a bizare phenomenon and Hibernate has something to do with it!

pepelnm · **Posted:** Sat Jun 10, 2006 11:55 am

I you modify your test and do the same query twice or thrice, is the time of the second and the third query so long?

damnhandy · **Posted:** Sat Jun 10, 2006 12:29 pm

Fix,

Can you post your hibernate.cfg.xml, the mappings involved, a sample JUnit that you're executing that includes the interaction withe session? Also, are you running with logging enabled? If not, enable logging and set the following appenders to these levels:

Code:

org.hibernate.SQL=debug
org.hibernate.type=debug
org.hibernate.event.def=trace

Please include that log in your response. Because this log will be fairly large, please only include 1 run of the test. Also, are you using the L2 cache with this test case?

Ryan-

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

pepelnm wrote:

I you modify your test and do the same query twice or thrice, is the time of the second and the third query so long?

Yes it takes approximately the same time with twice or thrice queries shortly after another.

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

damnhandy wrote:

Fix,

Can you post your hibernate.cfg.xml, the mappings involved, a sample JUnit that you're executing that includes the interaction withe session? Also, are you running with logging enabled? If not, enable logging and set the following appenders to these levels:

Code:

org.hibernate.SQL=debug
org.hibernate.type=debug
org.hibernate.event.def=trace

Please include that log in your response. Because this log will be fairly large, please only include 1 run of the test. Also, are you using the L2 cache with this test case?

Ryan-

Code:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD 3.0//EN" "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">

<hibernate-configuration> 
  <session-factory>
 <!-- 
     <property name="hibernate.c3p0.acquire_increment">1</property> 
   <property name="hibernate.c3p0.idle_test_period">10000</property> 
   <property name="hibernate.c3p0.max_size">30</property> 
   <property name="hibernate.c3p0.max_statements">0</property> 
   <property name="hibernate.c3p0.min_size">10</property> 
   <property name="hibernate.c3p0.timeout">10000</property>
-->
   <!-- this character enable the utf8 inserting into the database  -->
    <property name="hibernate.connection.defaultNChar">true</property>
    <property name="hibernate.connection.driver_class">oracle.jdbc.OracleDriver</property>
    <property name="hibernate.connection.password">user</property>
    <property name="hibernate.connection.pool_size">15</property>
    <property name="hibernate.connection.username">pwd</property>
    <property name="hibernate.dialect">org.hibernate.dialect.Oracle9Dialect</property>
    <property name="hibernate.transaction.factory_class">org.hibernate.transaction.JDBCTransactionFactory</property>
    <property name="hibernate.cache.use_query_cache">false</property>
    <property name="hibernate.generate_statistics">false</property>

Code:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN" "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">

<hibernate-mapping schema="TEST" package="com.test"> 
  <class name="TaskDoneView" table="v_task_done" optimistic-lock="none" lazy="false"> 
    <composite-id name="id" class="com.test.TaskDoneView$Id">
      <key-property name="itemId" type="integer">
        <column name="item_id" not-null="true"/>
      </key-property>
      <key-property name="messageId" type="integer">
        <column name="msg_id" not-null="true"/>
      </key-property>
      <key-property name="taskId" type="integer">
        <column name="task_id" not-null="true"/>
      </key-property>
    </composite-id>
    <property name="itemLabel" type="string" column="item_label" length="13" not-null="true"/>
    <property name="messageOriginCountry" type="string" column="msg_item_orig_country" length="2" not-null="true"/>
    <property name="messageDestinationCountry" type="string" column="msg_item_dest_country" length="2" not-null="true"/>
    <property name="creationDate" type="java.util.Date" column="msg_creation_dt" not-null="true"/>
    <property name="taskDescription" type="string" column="task_description" not-null="true"/>
    <property name="requestAuthor" type="string" column="req_author" not-null="true"/>
    <property name="replyAuthor" type="string" column="rep_author"  not-null="true"/>
    <property name="originPartnerId" type="integer" column="rep_orig_partner_id" length="4" not-null="true"/>
    <property name="originPartnerName" type="string" column="rep_orig_partner_short_name" length="8" not-null="true"/>
    <property name="originCallCentreId" type="integer" column="rep_orig_cc_id" length="4" not-null="true"/>
    <property name="originCallCentreName" type="string" column="rep_orig_cc_short_name" length="8" not-null="true"/>
    <property name="destinationPartnerId" type="integer" column="rep_dest_partner_id" length="4" not-null="true"/>
    <property name="destinationPartnerName" type="string" column="rep_dest_partner_short_name" length="8" not-null="true"/>
    <property name="destinationCallCentreId" type="integer" column="rep_dest_cc_id" length="4" not-null="true"/>
    <property name="destinationCallCentreName" type="string" column="rep_dest_cc_short_name" length="8" not-null="true"/>
    <property name="readYN" type="string" column="rep_read_yn" length="1" not-null="true"/>
  </class>
</hibernate-mapping>

Code:

Session session = HibernateUtils.getSession();
         StringBuffer queryString = new StringBuffer("from TaskDoneView as a where a.destinationPartnerId = :partner and a.creationDate > :now");
         if(customQuery==null){
            queryString.append(" order by a.creationDate desc");
         }
         Query query = session.createQuery(queryString.toString());
         query.setInteger("partner",partner.getId().intValue());
         query.setDate("now",super.getRepliesOffset());
         List l = query.list();

That's it. If I run the code that takes so long, I get a debug file of +20 MB, so I'm not gonna paste it in here.

It would be nice however if somebody could just tell me what Hibernate exactly does on the driver class when you create mapping files. It has to do something otherwise my simple testcase with this code ,this mapping and Hibernate.cfg.xlm would also be slow, no?!
For now I've pulled the connection object from hibernate and create my own preparedstatement and now it's working (fast). So I'm happy for now :)

damnhandy · **Posted:** Mon Jun 12, 2006 8:57 am

Quote:

It would be nice however if somebody could just tell me what Hibernate exactly does on the driver class when you create mapping files.

Nothing :) Hibernate does nothing with the connection in regards to your mapping files. The reason I suggested looking at your logs is that if you have a configuration issues, Hibernate could be issuing a multiple SQL queries. Since you're executing 1 HQL query, you should see just 1 generated SQL statement. Since you have no relationships defined here, there shouldn't be an other SQL involved here. If you're seeing multiple SQL statements, that's where you should focus your attention. Also, debugging the generated SQL will be easier if you add these properties:

Code:

<property name="hibernate.format_sql">true</property>
<property name="hibernate.use_sql_comments">true</property>

Ryan-

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

Quote:

Nothing :) Hibernate does nothing with the connection in regards to your mapping files. The reason I suggested looking at your logs is that if you have a configuration issues, Hibernate could be issuing a multiple SQL queries. Since you're executing 1 HQL query, you should see just 1 generated SQL statement. Since you have no relationships defined here, there shouldn't be an other SQL involved here. If you're seeing multiple SQL statements, that's where you should focus your attention. Also, debugging the generated SQL will be easier if you add these properties:

Code:

<property name="hibernate.format_sql">true</property>
<property name="hibernate.use_sql_comments">true</property>

Ryan-

I'm seeing only 1 sql query (the one I based my custom jdbc implementation of the DAO on, and because I'm stepping through the Hibernate Source code I can say that only 1 select is executed as I have debugged it to the preparedstatement level. This statement has one select statement inside, so no multiple queries are issued!!

And Hibernate has to do do somehting, otherwise how could you explain that exactly the same mapping, exactly the same hibernate cfg (with the other mappings commented out), exactly the same code works fast, but putting the other mappings back in place makes the PreparedStatement slow.

Can anybody tell me what happens when you have UTF8 and NVARCHAR fields in your mapping files? Does this configure your Oracle connection somewhat else ?
What's also strange is that this slow retrieval only seems to happen when there is a lot of data (+5000 records) if the list is only 300 records the response time is acceptable.

vitalir · **Joined:** Tue May 24, 2005 11:25 am **Posts:** 16

fix,

you may want to take a look on this one if you are open about your tool set.

Regards,
vitalir

max · **Posted:** Mon Jun 12, 2006 5:20 pm

vitalir - I have put comments regarding your solution on that other forum posting.

...and afaik changing the framework is not the solution here since it seem to be some "weird" driver bug that can be triggered by any usage - incl. other frameworks.

vitalir · **Joined:** Tue May 24, 2005 11:25 am **Posts:** 16

max wrote:

...and afaik changing the framework is not the solution here since it seem to be some "weird" driver bug that can be triggered by any usage - incl. other frameworks.

Agreed - if it's on the driver - a new framework won't help. It just seemed to be unclear whether it's the case..
Vitaly

fix · **Joined:** Wed Nov 23, 2005 12:55 pm **Posts:** 23

I do agree that the problem isn't a Hibernate one, but something has to have changed using all the mappings. Because at the moment I'm creating my own PreparedStatement from the Hibernate retrieved Connection object and that doesn't have the issues.
And I'm not changing to another framework, btw we are using Oracle 10g, something I wouldn't call legacy! :)
Besides if I would have to switch to another framework then Hibernate, I would prolly choose spring or ibatis as persistency framework. But as I already mentioned, I'm quite pleased with Hiberante, I've used it in more projects and this is the first real issue I have with it.
Even the dotnet version works quite well, although the Set object isn't supported and you have to pull some tricks to get the Collection out of the framework.

But afterall, maybe my own custom PreparedStatement is the best option. The list that it generates is only for viewing purposes and has to be really fast. If you see, retrievel of +5000 records takes 1.x second and the response is flushed in 1.x seconds also. That's good enough at the moment, further improvements have to be done on the ERD level. And besides, the only have to wait these seconds on update of the view, otherwise everything is stored in memory (and yes this is a good option as we have 8 gig of ram in our machine!!)

max · **Posted:** Tue Jun 13, 2006 10:20 am

any possibility you could check it with another driver (e.g. datadirect) or even another db ?