[Persistence, JBoss/CMP, Hibernate, Database] - Problems with Postgres, Persistence, and large objects
by andydale
We currently have an JBoss application that receives a byte stream and persists it with hibernate EntityManager and then reads it from the db for further parsing before saving it again. When using the default Hypersonic datasource hibernate manages it without any problems, but when trying to use PostgreSQL as the datasource we run into problems, with the reading/retrieval of the initially persisted object for further parsing.
I have turned on all the logging in jboss for hibernate and the output is as so:
2006-07-25 14:42:40,615 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 11538313605
| 2006-07-25 14:42:40,616 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
| 2006-07-25 14:42:40,616 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
| 2006-07-25 14:42:40,622 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
| 2006-07-25 14:42:40,625 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
| 2006-07-25 14:42:40,625 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
| 2006-07-25 14:42:40,632 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
| 2006-07-25 14:42:40,632 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
| 2006-07-25 14:42:40,632 DEBUG [org.hibernate.SQL] select nextval ('hibernate_sequence')
| 2006-07-25 14:42:40,637 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 1
| 2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
| 2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
| 2006-07-25 14:42:40,637 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
| 2006-07-25 14:42:40,637 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 1, using strategy: org.hibernate.id.SequenceGenerator
| 2006-07-25 14:42:40,663 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
| 2006-07-25 14:42:40,664 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
| 2006-07-25 14:42:40,670 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 1 insertions, 0 updates, 0 deletions to 1 objects
| 2006-07-25 14:42:40,670 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
| 2006-07-25 14:42:40,673 DEBUG [org.hibernate.pretty.Printer] listing entities:
| 2006-07-25 14:42:40,675 DEBUG [org.hibernate.pretty.Printer] de.comsoft.cadas_ims.common.Messages.RawMessage{mID=1, mTli=null, mBuffer=81c4c1c1b0b0b8b3a0b0b5b0b9b4b68d8ac7c7a0ccd1d3c1d9ced9d8a0ccd1cdcfd9ced9d8a0ccd1d4dad9ced9d88d8ab0b5b0b9b4b6a0ccc9c9c1d9ced9d88d8a82a8c2b0b5b7b4afb0b3a0cecfd4c1cdce8d8ad1a9ccc9cdcdafd1cdd2ccc3afc9d6afcec2cfafc1afb0b0b0afb9b9b9afb4b5b4b0ceb0b0b9b4b2c5b0b0b18d8ac1a9ccc9cdc5a0c2a9b0b3b0b2b0b8b0b0b0b0a0c3a9b0b3b0b2b1b6b0b5b5b08d8ac4a9c6c5c2a0b0b8a0b0b0b0b1adb0b5b0b0a0b2b3b1b0adb0b5b5b0a0b1b4a0b2b3b5b0adb0b5b5b0a0c1cec4a0b1b6a0b0b0b5b0adb0b5b5b08d8ac5a9cdd3c7a0b0b1a0a0a0d2d7d9a0b1b1afb2b9a0c3ccd3c4a0c4d5c5a0d4cfa0d7c9d0a98d8a8b83, mChannel=AFTN, mReceptionDate=2006-07-25 14:42:40}
| 2006-07-25 14:42:40,677 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
| 2006-07-25 14:42:40,677 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
| 2006-07-25 14:42:40,678 DEBUG [org.hibernate.SQL] /* insert de.comsoft.cadas_ims.common.Messages.RawMessage */ insert into TRAFFIC_TBL (TRANSMISSION_CHANNEL, RECEPTION_DATE, BUFFER, TLI, mID) values (?, ?, ?, ?, ?)
| 2006-07-25 14:42:40,683 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
| 2006-07-25 14:42:40,687 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
| 2006-07-25 14:42:40,687 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
| 2006-07-25 14:42:40,688 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
| 2006-07-25 14:42:40,688 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
| 2006-07-25 14:42:40,688 INFO [STDOUT] written to database with PK = 1
| 2006-07-25 14:42:40,688 INFO [STDOUT] waiting for 10 seconds...
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Size: 289
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Version: 49
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Type: 49
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Id: 0000010ca5b57e9b0001
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Data Size: 273
| 2006-07-25 14:42:50,437 DEBUG [de.comsoft.cadas.mep.MEPRequestHandler] Data received: 0000010ca5b57e9b0001
| 2006-07-25 14:42:50,437 INFO [STDOUT] Received message [19309576] @ 1153831370437
| 2006-07-25 14:42:50,693 INFO [STDOUT] done
| 2006-07-25 14:42:50,695 INFO [STDOUT] JMS message ID = null
| 2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
| 2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
| 2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
| 2006-07-25 14:42:50,714 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
| 2006-07-25 14:42:50,715 DEBUG [org.hibernate.pretty.Printer] listing entities:
| 2006-07-25 14:42:50,715 DEBUG [org.hibernate.pretty.Printer] de.comsoft.cadas_ims.common.Messages.RawMessage{mID=1, mTli=null, mBuffer=81c4c1c1b0b0b8b3a0b0b5b0b9b4b68d8ac7c7a0ccd1d3c1d9ced9d8a0ccd1cdcfd9ced9d8a0ccd1d4dad9ced9d88d8ab0b5b0b9b4b6a0ccc9c9c1d9ced9d88d8a82a8c2b0b5b7b4afb0b3a0cecfd4c1cdce8d8ad1a9ccc9cdcdafd1cdd2ccc3afc9d6afcec2cfafc1afb0b0b0afb9b9b9afb4b5b4b0ceb0b0b9b4b2c5b0b0b18d8ac1a9ccc9cdc5a0c2a9b0b3b0b2b0b8b0b0b0b0a0c3a9b0b3b0b2b1b6b0b5b5b08d8ac4a9c6c5c2a0b0b8a0b0b0b0b1adb0b5b0b0a0b2b3b1b0adb0b5b5b0a0b1b4a0b2b3b5b0adb0b5b5b0a0c1cec4a0b1b6a0b0b0b5b0adb0b5b5b08d8ac5a9cdd3c7a0b0b1a0a0a0d2d7d9a0b1b1afb2b9a0c3ccd3c4a0c4d5c5a0d4cfa0d7c9d0a98d8a8b83, mChannel=AFTN, mReceptionDate=2006-07-25 14:42:40}
| 2006-07-25 14:42:50,715 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
| 2006-07-25 14:42:50,719 INFO [STDOUT]
|
| mParser = de.comsoft.cadas_ims.Parser.MessageParserImpl@fb7ac7
| 2006-07-25 14:42:50,720 INFO [STDOUT] MessageHandler::onMessage begin @ 1153831370720 for message with ID ID:3-11538313706951
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 11538313707
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
| 2006-07-25 14:42:50,720 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
| 2006-07-25 14:42:50,724 DEBUG [org.hibernate.loader.Loader] loading entity: [de.comsoft.cadas_ims.common.Messages.RawMessage#1]
| 2006-07-25 14:42:50,728 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
| 2006-07-25 14:42:50,728 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
| 2006-07-25 14:42:50,734 DEBUG [org.hibernate.SQL] /* load de.comsoft.cadas_ims.common.Messages.RawMessage */ select rawmessage0_.mID as mID0_0_, rawmessage0_.TRANSMISSION_CHANNEL as TRANSMIS2_0_0_, rawmessage0_.RECEPTION_DATE as RECEPTION3_0_0_, rawmessage0_.BUFFER as BUFFER0_0_, rawmessage0_.TLI as TLI0_0_ from TRAFFIC_TBL rawmessage0_ where rawmessage0_.mID=?
| 2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
| 2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
| 2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
| 2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
| 2006-07-25 14:42:50,737 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
| 2006-07-25 14:42:50,740 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
| 2006-07-25 14:42:50,740 DEBUG [org.hibernate.loader.Loader] done entity load
| 2006-07-25 14:42:50,740 INFO [STDOUT]
|
| rm is null, pKey is 1
| 2006-07-25 14:42:50,740 INFO [STDOUT] MessageHandler::onMessage end @ 1153831370740 for message with ID ID:3-11538313706951
| 2006-07-25 14:42:50,747 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
| 2006-07-25 14:42:50,748 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
| 2006-07-25 14:42:50,748 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
| 2006-07-25 14:42:50,784 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
| 2006-07-25 14:42:50,784 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
| 2006-07-25 14:42:50,784 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
The line "rm is null, pKey is 1" is a debug line. rm is the result of EntityManager.find() passing it the primary key (1 is the above case) of the already persisted object. I have a quick question about the hibernate logging, how do i display what the ? are in the perparedStatements ?
Currently the application is behaving like it is trying to read (SELECT) the data after it has been persisted, but it is not there, I have veryfied it is with the pgAdmin application, I also enabled full trace logging on PostgreSQL itself, and i can't see where the problems is, as commits take place at the correct time in my opinion.
My gut feeling is that this might have something to do with the fact that we are using the bytea datatype in postgres, and i know from personal experience that large objects can cause issues in postgres.
Can anyone offer my any adive on how to solve this problem ??
Thanks in advance,
Andy
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3960692#3960692
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=3960692
19 years, 9 months