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 = [EMAIL PROTECTED]
| 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
_______________________________________________
jboss-user mailing list
[email protected]
https://lists.jboss.org/mailman/listinfo/jboss-user
