Add to Collections - Performance Issue

bozidardangubic · **Posted:** Sat Mar 08, 2008 10:34 pm

I am having a huge performance problem when adding an element to the collection. I have two objects, OverdueLog and OverdueLogEntry that are linked through one-to-many relationship. Mapping files are below.

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
>
    <class
        name="com.xxx.OverdueLog"
        table="OVERDUE_LOG"
        lazy="true"
        dynamic-update="true"
        dynamic-insert="true"
    >

        <id
            name="ID"
            column="ID"
            type="java.lang.Long"
        >
            <generator class="native">
              <param name="sequence">OVERDUE_LOG_SEQ</param>       
            </generator>
        </id>        

        <set
            name="logEntries"
            table="OVERDUE_LOG_ENTRY"
            lazy="true"
            cascade="all"
            sort="unsorted"
        >

            <key
                column="OVERDUE_LOG_ID"
            >
            </key>

            <one-to-many
                  class="com.jsi.fullcourt.domain.overdue.OverdueLogEntry"
            />

        </set>

        ....
</hibernate-mapping>



<?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
>
    <class
        name="com.xxx.domain.overdue.OverdueLogEntry"
        table="OVERDUE_LOG_ENTRY"
        lazy="true"
        dynamic-update="true"
        dynamic-insert="true"
    >

        <id
            name="ID"
            column="ID"
            type="java.lang.Long"
        >
            <generator class="native">
              <param name="sequence">OVERDUE_LOG_ENTRY_SEQ</param>       
            </generator>
        </id>
        
        <many-to-one
            name="defendant"
            class="com.xxx.domain.caserole.CaseRole"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="DEFENDANT_ID"
        />

        <set
            name="offenses"
            table="MM_OVERDUE_LOG_ENTRY_OFFENSE"
            lazy="true"
            cascade="none"
            sort="unsorted"
        >

            <key
                column="OVERDUE_LOG_ENTRY_ID"
            >
            </key>

            <many-to-many
                class="com.xxx.domain.caserole.Offense"
                column="OFFENSE_ID"
                outer-join="auto"
             />

        </set>
        
        <set
            name="bonds"
            table="MM_OVERDUE_LOG_ENTRY_BOND"
            lazy="true"
            cascade="none"
            sort="unsorted"
        >

            <key
                column="OVERDUE_LOG_ENTRY_ID"
            >
            </key>

            <many-to-many
                class="com.xxx.domain.accounting.bond.Bond"
                column="BOND_ID"
                outer-join="auto"
             />

        </set>
        
        <set name="victims"
           table="MM_OVERDUE_LOG_ENTRY_VICTIM"
            lazy="true"
            cascade="none"
            sort="unsorted">
            <key column="OVERDUE_LOG_ENTRY_ID"></key>
            <many-to-many 
               class="com.xxx.domain.caserole.CaseRole"
               column="VICTIM_ID"
               outer-join="auto"
            />
        </set>
        
        

        <many-to-one
            name="overdueStep"
            class="com.xxx.domain.overdue.OverdueStep"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="OVERDUE_STEP_ID"
        />

        <set
            name="commands"
            table="CmdBaseDOM"
            lazy="true"
            cascade="all-delete-orphan"
            sort="unsorted"
        >

            <key
                column="OVERDUE_LOG_ENTRY_ID"
            >
            </key>

            <one-to-many
                  class="com.xxx.domain.command.overdue.CmdOverdue"
            />

        </set>

        <many-to-one
            name="overdueFailure"
            class="com.xxx.domain.overdue.OverdueFailure"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="OVERDUE_FAILURE_ID"
        />

        <property
            name="worksheetOnly"
            type="boolean"
            update="true"
            insert="true"
            column="WORKSHEET_ONLY"
        />
         
        <many-to-one
            name="overdueLog"
            class="com.xxx.domain.overdue.OverdueLog"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="OVERDUE_LOG_ID"
        />

        <many-to-one
            name="resetByUser"
            class="com.xxx.domain.security.AppUser"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="RESET_USER_ID"
        />
        
        <property
            name="resetDate"
            type="timestamp"
            update="true"
            insert="true"
            column="RESET_DATE"
        />

        <many-to-one
            name="resetReason"
            class="com.xxx.domain.util.Type"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="RESET_REASON_TYPE_ID"
        />
        
        <many-to-one
            name="otherSentence"
            class="com.xxx.domain.caserole.OtherSentence"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="OTHER_SENTENCE_ID"
        />
        
        <many-to-one
            name="hearing"
            class="com.xxx.domain.scheduling.Hearing"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="HEARING_ID" />

        <property
            name="worksheetDueIncompleteAddress"
            type="boolean"
            update="true"
            insert="true"
            column="WORKSHEET_ADDRESS_INCOMPLETE"
        />

        <property
            name="worksheetDueOutstandingWarrant"
            type="boolean"
            update="true"
            insert="true"
            column="WORKSHEET_OUT_WARRANT"
        />
        
        <property 
           name="historyOnly"
           type="boolean"
           update="true"
           insert="true"
           column="HISTORY_ONLY"
        />

        <property
            name="multiCourtId"
            type="java.lang.Long"
            update="true"
            insert="true"
            column="MULTI_COURT_ID"
        />

        <property
            name="createdDate"
            type="timestamp"
            update="true"
            insert="true"
            column="CREATED_DATE"
        />

        <many-to-one
            name="createdBy"
            class="com.xxx.domain.security.AppUser"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="CREATED_BY_ID"
        />

        <property
            name="changedDate"
            type="timestamp"
            update="true"
            insert="true"
            column="CHANGED_DATE"
        />

        <many-to-one
            name="changedBy"
            class="com.xxx.domain.security.AppUser"
            cascade="none"
            outer-join="auto"
            update="true"
            insert="true"
            column="CHANGED_BY_ID"
        />

        <!--
            To add non XDoclet property mappings, create a file named
                hibernate-properties-OverdueLogEntry.xml
            containing the additional properties and place it in your merge dir.
        -->

        <filter name="securityFilter" condition="MULTI_COURT_ID IN (:securityFilterParam)" />
        </class>
        <filter-def name="securityFilter">
            <filter-param name="securityFilterParam" type="long" />
        </filter-def>

</hibernate-mapping>

As process is running inside a loop, an element is added to the collection and each time new element is added, the operation overdueLog.getOverdueLogEntries().add(overdueLogEntry) takes progressively longer to execute. After about 500 entries, this operation takes between 22 and 30 seconds!!! So something is happening while item is being added to the hibernate Set that is causing this operation to take this long (as I mentioned, starts off by running this in 10 milliseconds for the first, 172ms for 200th, 750ms for 300th and at about 400th starts to be very very very slow. if I let the process run when I get to about 700th entries, it takes more that one minute to add the item to the collection).

Any help would be much appreciated

bozidardangubic · **Posted:** Tue Mar 11, 2008 1:19 pm

Another kind request for any soul that has ever experienced anything like this - we may have to abandon Hibernate and go with something else which I would really hate to do at this point!

Thanks!

bozidardangubic · **Posted:** Tue Mar 11, 2008 1:21 pm

Another kind request for any soul that has ever experienced anything like this - we may have to abandon Hibernate and go with something else which I would really hate to do at this point!

Thanks!

llefevre · **Posted:** Tue Mar 11, 2008 7:12 pm

Can you copy/paste the equals() and hashCode() methods of your com.xxx.OverdueLog class?

bozidardangubic · **Posted:** Tue Mar 11, 2008 7:36 pm

llefevre wrote:

Can you copy/paste the equals() and hashCode() methods of your com.xxx.OverdueLog class?

Thanks for the Reply!!

hashCode() and equals() are not overriden.

also, as I mentioned, when elements are added to the HashSet there is no delay whatsoever but when they are added to the Hibernate's Set there is this unbelievable delay on just .add() operation. So I am at a loss...

Thanks again!

llefevre · **Posted:** Wed Mar 12, 2008 4:26 am

Can you add the crucial information which consists of the version of Hibernate you are using and the database specification also?

Okay, first things I can think of is:
- do you have enough memory? Try adding some Mb to see if your problem disappears
- did you take a look at the SQL queries ran against your RDBMS? Are they optimal?

bozidardangubic · **Posted:** Wed Mar 12, 2008 9:32 am

I was on 3.22 and moved to the latest production release with the same result. I have deployments on Oracle, MSSQL, MySQL, all with the same outcome.

llefevre wrote:

Okay, first things I can think of is:
- do you have enough memory? Try adding some Mb to see if your problem disappears

Not running out of memory, have 4Gb of which only 0.8Gb are being used during processing. We are talking about 500-800 objects, not very memory intensive.

llefevre wrote:

- did you take a look at the SQL queries ran against your RDBMS? Are they optimal?

no queries are running against the database, this slowdown is happening at the point when the element is getting added to the collection. this is a new element which is not persisted in the database yet. like...

Code:

A a = new A();
for (int i = 0; i<1000; i++) {
// tx started
a.getBs().add(new B()); // this call takes forever to execute...
// tx committed to save A
}

llefevre · **Posted:** Wed Mar 12, 2008 12:45 pm

Quote:

no queries are running against the database, this slowdown is happening at the point when the element is getting added to the collection. this is a new element which is not persisted in the database yet. like...

Code:

A a = new A();
for (int i = 0; i<1000; i++) {
// tx started
a.getBs().add(new B()); // this call takes forever to execute...
// tx committed to save A
}

Do you mean you are working outside of a session? I don't understand if you are working inside a transaction and your comment is just here to tell that or if you commented the transaction "begin" and "commit" instructions.

If you are working inside the transaction then try starting it outside thee loop and committing after the loop.

If not, it seems you are working in a session detached mode and I advise you to implement the equals() and hashCode() methods of the objects being added to a Set.

bozidardangubic · **Posted:** Wed Mar 12, 2008 12:58 pm

llefevre wrote:

Do you mean you are working outside of a session? I don't understand if you are working inside a transaction and your comment is just here to tell that or if you commented the transaction "begin" and "commit" instructions.

working inside the the session but committing data after each run. the log entry contains what was processed for a single run so transaction is committed after each run to ensure data integrity. before this implementation, everything was running inside the same transaction and that brought hibernate to its knees (large object graph inside a session was causing horrendous performance). I was really hoping someone would have known what the problem is with the Hibernate's Set but so you better understand what this process does....

a) query - get about 1,000 entities
b) clear the session
c) start the transaction
d) load the first entity
e) process it (this process performs large number of add/update/delete)
f) add element to the log (log contains links to information that was processed so that it can be reported, undone...)
g) commit the transaction
h) clear the session

and then from c) to h) again until all 1,000 are processed...

llefevre wrote:

If you are working inside the transaction then try starting it outside thee loop and committing after the loop.

already tried, hibernate performs extremely slow when there is a large object graph inside the session so we had to re-design to this. The process (that takes couple of minutes using JDBC only implementation) was taking 4+ hours with this implementation

llefevre wrote:

If not, it seems you are working in a session detached mode and I advise you to implement the equals() and hashCode() methods of the objects being added to a Set.

Not working in session detached mode. And just to point out that the problem definitely is not in equals() and hashCode() as the same operation on normal implementation of Set takes no time whatsoever. So to better explain

Code:

public class OverdueLog {

      private Set<OverdueLogEntry> logEntries; // this is mapped in hibernate
      private Set<OverdueLogEntry> testLogEntries; // this is just a plain 'ol Set

... // getters and setters

     public void addLogEntry(OverdueLogEntry entry) {
         getLogEntries().add(entry); 
     }

     public void addTestLogEntry(OverdueLogEntry entry) {
         getTestLogEntries().add(entry); 
     }

}

public class SomeOtherClass {

     public void process(...) {
            
           ... some processing code
           overdueLog.addLogEntry(entry); // this takes forever
           overdueLog.addTestLogEntry(entry); // takes 0ms 
     }

}

[/code]

VampBoy · **Posted:** Mon Mar 24, 2008 2:51 pm

Are your log entries loaded eagerly or lazily? If lazily then when you go to modify the collection it will end up loading the rest of the collection.

bozidardangubic · **Posted:** Mon Mar 24, 2008 2:54 pm

VampBoy wrote:

Are your log entries loaded eagerly or lazily? If lazily then when you go to modify the collection it will end up loading the rest of the collection.

eagerly loaded. if you follow the execution path you'll notice that each log entry is saved and new entry added afterwards so there is nothing to lazy load. I also have show-sql out, nothing is happening "database-related"

I had to give up on hibernate for this but I saved the original implementation to make sure we never try using hibernate for anything (even as simple) as this!