1 Reply Latest reply on Jul 26, 2006 10:18 AM by Andrew Dale

    Problems with Postgres, Persistence, and large objects

    Andrew Dale Newbie

      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

        • 1. Re: Problems with Postgres, Persistence, and large objects
          Andrew Dale Newbie

          I am still having this problem, but have been investigating it further. What i have found out is that if you call the EntityManager.find() method directly after you have just persisted the object in the same class then it manages to find the Entity in the database.

          The problem starts to happen when the you call the EntityManager.find() from within another class with the same persistence context (using the same persistence unit), it seems to return null 99.99% of the time. I have no idea if this due to the database being used as it works with a Hypersonic data source but not with postgres.

          Andy