9:02 a.m.
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#...
Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...