-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Projects » Search, Validator, Shards

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 2 posts ] 
  Previous topic | Next topic 
Author Message
laura_a
 Post subject: Generating id's for large collections
PostPosted: Mon Sep 29, 2008 8:00 am 
Newbie

Joined: Tue Nov 20, 2007 4:57 am
Posts: 7
The problem is that saving large collections of messages takes a very very long time. It takes aproximately 25 minutes to save 50.000 messages using the webapp. Most of this (around 23 minutes), when debugging is enabled, seems to be lost while generating ids. I've tried to manually generate ids for mesages but it takes the same, except the id-generating debug output is replaced by selects.

There's something very wrong I'm doing here, but I can't place my finger on it. Surely persisting 50.000 elements should not take this long.

Sessions and transactions are created automatically by spring.

The code below works as follows: the user uploads a file. This file is parsed and the set of messages is created. The message list which contains the large set of messages is persisted to the database. The persisted message list, together with the set are given to a separate thread which performs the message save. Ideally the separate thread should not exist, but since it takes so long to persist anything that is over 10.000 rows, this was a temporary middle way out.


Hibernate version:
Hibernate version: 3.2.5GA
Hibernate entity manager: 3.3.1.ga

Mapping documents:
Code:
@Entity
@Table(name = "message_lists")
public class MessageList implements Serializable {
    @Id @GeneratedValue(strategy = GenerationType.SEQUENCE)   
    protected Long id;
@OneToMany(cascade = {CascadeType.ALL},fetch = FetchType.LAZY)
    protected Set<Message> messages;
// some other fields
}

@Entity
@Table(name = "messages")
public class Message implements Serializable {
   
    @Id @GeneratedValue(strategy = GenerationType.SEQUENCE)
    protected Long id;
    // some other fields


The annotations are actually on the getters, I've moved them just for this post

Code between sessionFactory.openSession() and session.close():
Code:
   
    public T save(T object) {
        return this.entityManager.merge(object);
    }

Full stack trace of any exception that occurs:

Name and version of the database you are using:
Postgres, 8.3.1

The generated SQL (show_sql=true):
Code:
DEBUG [14:53:35,053] [Thread-2] MessageListSavingUtils.run(56) | Starting to save list
DEBUG [14:53:35,137] [Thread-2] SessionImpl.<init>(220) | opened session at timestamp: 5008135025201152
DEBUG [14:53:35,138] [Thread-2] JDBCTransaction.begin(54) | begin
DEBUG [14:53:35,138] [Thread-2] ConnectionManager.openConnection(421) | opening JDBC connection
DEBUG [14:53:35,138] [Thread-2] JDBCTransaction.begin(59) | current autocommit status: true
DEBUG [14:53:35,139] [Thread-2] JDBCTransaction.begin(62) | disabling autocommit
DEBUG [14:53:35,139] [Thread-2] Loader.loadEntity(1852) | loading entity: [[].model.MessageList#10]
DEBUG [14:53:35,140] [Thread-2] AbstractBatcher.logOpenPreparedStatement(366) | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [14:53:35,140] [Thread-2] SQL.log(401) | select messagelis0_.id as id5_1_, messagelis0_.message as message5_1_, messages1_.message_lists_id as message1_3_, message2_.id as messages2_3_, message2_.id as id2_0_, message2_.destination_number as destinat2_2_0_, message2_.message as message2_0_, message2_.message_status as message4_2_0_ from message_lists messagelis0_ left outer join message_lists_messages messages1_ on messagelis0_.id=messages1_.message_lists_id left outer join messages message2_ on messages1_.messages_id=message2_.id where messagelis0_.id=?
DEBUG [14:53:35,143] [Thread-2] AbstractBatcher.logOpenResults(382) | about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG [14:53:35,144] [Thread-2] Loader.getRow(1173) | result row: null, EntityKey[[].model.MessageList#10]
DEBUG [14:53:35,144] [Thread-2] Loader.readCollectionElement(1018) | result set contains (possibly empty) collection: [[].model.MessageList.messages#10]
DEBUG [14:53:35,145] [Thread-2] AbstractBatcher.logCloseResults(389) | about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG [14:53:35,145] [Thread-2] AbstractBatcher.logClosePreparedStatement(374) | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [14:53:35,146] [Thread-2] TwoPhaseLoad.initializeEntity(107) | resolving associations for [[].model.MessageList#10]
DEBUG [14:53:35,146] [Thread-2] TwoPhaseLoad.initializeEntity(206) | done materializing entity [[].model.MessageList#10]
DEBUG [14:53:35,147] [Thread-2] CollectionLoadContext.endLoadingCollections(217) | 1 collections were found in result set for role: [].model.MessageList.messages
DEBUG [14:53:35,147] [Thread-2] CollectionLoadContext.endLoadingCollection(260) | collection fully initialized: [[].model.MessageList.messages#10]
DEBUG [14:53:35,148] [Thread-2] CollectionLoadContext.endLoadingCollections(226) | 1 collections initialized for role: [].model.MessageList.messages
DEBUG [14:53:35,148] [Thread-2] StatefulPersistenceContext.initializeNonLazyCollections(790) | initializing non-lazy collections
DEBUG [14:53:35,149] [Thread-2] Loader.loadEntity(1883) | done entity load
DEBUG [14:53:35,149] [Thread-2] AbstractBatcher.logOpenPreparedStatement(366) | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [14:53:35,150] [Thread-2] SQL.log(401) | select nextval ('hibernate_sequence')
DEBUG [14:53:35,151] [Thread-2] SequenceGenerator.generate(82) | Sequence identifier generated: 4
DEBUG [14:53:35,152] [Thread-2] AbstractBatcher.logClosePreparedStatement(374) | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [14:53:35,152] [Thread-2] SequenceHiLoGenerator.generate(62) | new hi value: 4
DEBUG [14:53:35,153] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 40, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,154] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 41, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,155] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 42, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,157] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 43, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,158] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 44, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,159] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 45, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,160] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 46, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,160] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 47, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,162] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 48, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,163] [Thread-2] AbstractSaveEventListener.saveWithGeneratedId(112) | generated identifier: 49, using strategy: org.hibernate.id.SequenceHiLoGenerator
DEBUG [14:53:35,165] [Thread-2] JDBCTransaction.commit(103) | commit
DEBUG [14:53:35,165] [Thread-2] AbstractFlushingEventListener.prepareEntityFlushes(111) | processing flush-time cascades
DEBUG [14:53:35,167] [Thread-2] AbstractFlushingEventListener.prepareCollectionFlushes(154) | dirty checking collections
DEBUG [14:53:35,167] [Thread-2] CollectionEntry.preFlush(177) | Collection dirty: [[].model.MessageList.messages#10]
DEBUG [14:53:35,168] [Thread-2] Collections.processReachableCollection(176) | Collection found: [[].model.MessageList.messages#10], was: [[].model.MessageList.messages#10] (initialized)
DEBUG [14:53:35,171] [Thread-2] AbstractFlushingEventListener.flushEverythingToExecutions(85) | Flushed: 10 insertions, 0 updates, 0 deletions to 11 objects
DEBUG [14:53:35,172] [Thread-2] AbstractFlushingEventListener.flushEverythingToExecutions(91) | Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
DEBUG [14:53:35,172] [Thread-2] Printer.toString(83) | listing entities:
DEBUG [14:53:35,173] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 9, id=45, messageStatus=SCHEDULED, destinationNumber=087879174}
DEBUG [14:53:35,173] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 7, id=44, messageStatus=SCHEDULED, destinationNumber=087879172}
DEBUG [14:53:35,173] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 2, id=43, messageStatus=SCHEDULED, destinationNumber=087879167}
DEBUG [14:53:35,174] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 0, id=42, messageStatus=SCHEDULED, destinationNumber=087879165}
DEBUG [14:53:35,174] [Thread-2] Printer.toString(90) | [].model.MessageList{message=, id=10, messages=[[].model.Message#43, [].model.Message#44, [].model.Message#45, [].model.Message#41, [].model.Message#40, [].model.Message#46, [].model.Message#47,[].model.Message#49, [].model.Message#42, [].model.Message#48]}
DEBUG [14:53:35,174] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 3, id=41, messageStatus=SCHEDULED, destinationNumber=087879168}
DEBUG [14:53:35,175] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 5, id=40, messageStatus=SCHEDULED, destinationNumber=087879170}
DEBUG [14:53:35,175] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 6, id=49, messageStatus=SCHEDULED, destinationNumber=087879171}
DEBUG [14:53:35,175] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 4, id=48, messageStatus=SCHEDULED, destinationNumber=087879169}
DEBUG [14:53:35,176] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 1, id=47, messageStatus=SCHEDULED, destinationNumber=087879166}
DEBUG [14:53:35,176] [Thread-2] Printer.toString(90) | [].model.Message{message=Test message 8, id=46, messageStatus=SCHEDULED, destinationNumber=087879173}
DEBUG [14:53:35,176] [Thread-2] AbstractBatcher.logOpenPreparedStatement(366) | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [14:53:35,177] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,177] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,178] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,178] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,179] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,179] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,179] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,180] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,180] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,180] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,181] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,181] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,181] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,182] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,182] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,183] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,183] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,183] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,184] [Thread-2] SQL.log(401) | insert into messages (destination_number, message, message_status, id) values (?, ?, ?, ?)
DEBUG [14:53:35,184] [Thread-2] AbstractBatcher.doExecuteBatch(44) | Executing batch size: 10
DEBUG [14:53:35,186] [Thread-2] AbstractBatcher.logClosePreparedStatement(374) | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [14:53:35,187] [Thread-2] AbstractCollectionPersister.deleteRows(1204) | Deleting rows of collection: [[].model.MessageList.messages#10]
DEBUG [14:53:35,187] [Thread-2] AbstractCollectionPersister.deleteRows(1287) | no rows to delete
DEBUG [14:53:35,188] [Thread-2] AbstractCollectionPersister.insertRows(1313) | Inserting rows of collection: [[].model.MessageList.messages#10]
DEBUG [14:53:35,188] [Thread-2] AbstractBatcher.logOpenPreparedStatement(366) | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [14:53:35,188] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,189] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,189] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,190] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,190] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,190] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,191] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,191] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,191] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,192] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,192] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,192] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,193] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,193] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,193] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,194] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,194] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,194] [Thread-2] AbstractBatcher.prepareBatchStatement(226) | reusing prepared statement
DEBUG [14:53:35,194] [Thread-2] SQL.log(401) | insert into message_lists_messages (message_lists_id, messages_id) values (?, ?)
DEBUG [14:53:35,195] [Thread-2] AbstractCollectionPersister.insertRows(1390) | done inserting rows: 10 inserted
DEBUG [14:53:35,195] [Thread-2] AbstractBatcher.doExecuteBatch(44) | Executing batch size: 10
DEBUG [14:53:35,198] [Thread-2] AbstractBatcher.logClosePreparedStatement(374) | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [14:53:35,199] [Thread-2] JDBCTransaction.toggleAutoCommit(193) | re-enabling autocommit
DEBUG [14:53:35,200] [Thread-2] JDBCTransaction.commit(116) | committed JDBC Connection
DEBUG [14:53:35,200] [Thread-2] ConnectionManager.aggressiveRelease(404) | aggressively releasing JDBC connection
DEBUG [14:53:35,200] [Thread-2] ConnectionManager.closeConnection(441) | releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG [14:53:35,201] [Thread-2] MessageListSavingUtils.run(58) | Done saving list



Problems with Session and transaction handling?
Top
 Profile  
 
hardy.ferentschik
 Post subject:
PostPosted: Thu Oct 02, 2008 4:25 am 
Hibernate Team
Hibernate Team

Joined: Thu Apr 05, 2007 5:52 am
Posts: 1689
Location: Sweden
Hi,

shouldn't it be enough to just persist the message list since you have a cascade all on the association to the messages? Also, do you always just call object merge? That doesn't seem to be right.

Maybe I misunderstand your usecase. Can you post the actual code where you persist the list and messages?

--Hardy
Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 2 posts ] 

Board index » Projects » Search, Validator, Shards

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
cron
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.