-->
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 » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 2
  [ 25 posts ]  Go to page 1, 2  Next
  Previous topic | Next topic 
Author Message
sean
 Post subject: Unexpected Cached Query Results
PostPosted: Thu Jun 24, 2004 9:39 pm 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Running Hibernate 2.1.2 and now 2.1.4 over Interbase 6.0.1/Interclient 2.01, defining mappings with XDoclet...

All save, update, and delete operations are working just fine...defining named queries in XDoclet, some with named bindings...initial query works just fine, object is fully loaded and properly initialized...

Secondary process then updates database...subsequent query does not pick up the new data, instead returns what appears to be cached version loaded before...not only are the contents stale but the object reference is the originally loaded instance...

Appears to be caching (which in many other scenarios would be a great thing)...so, disabled query caching in hibernater.properties with:
Code:
   hibernate.cache.use_query_cache false

and confirmed by casting the factory instance down and verifying a false result from:
Code:
   SessionFactoryImpl.isQueryCacheEnabled()


Still seeing the problem...

Thought it might be the second level object cache implementation, so implemented a custom NullCache and NullCacheProvider that always return null from a get...
Code:
   hibernate.cache.provider_class mypkg.NullCacheProvider

logging calls into the cache confirm that the cache always misses...

Still seeing the problem...

Attempted to dump any cached data in the factory with:
Code:
   factory.evictQueries();
   factory.evict(Profile.class);

Played around with opening and closing the session between queries...tried locking the returned instance for upgrade...clearly running out of ideas...tried invoking related (but presumable not yet cached) query that returns the same database row...tried using .find(sql) rather than named query...

Still seeing the problem...

Finally, released the factory and reinstantiated it...only then did the new data get loaded correctly...though this is obviously not a production solution...

I believe there is something about caching at the factory/VM level that I don't understand, but need a little guidance...any help would be appreciated...
Top
 Profile  
 
sean
 Post subject:
PostPosted: Fri Jun 25, 2004 8:55 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
I should also add that I verified that it is neither the database nor the driver that is caching by writing a straight JDBC test...

I tested both reuising the prepared statement and connection as well as destroying and recreating them...and in both cases, the results always reflected the proper "fresh" data from the database...
Top
 Profile  
 
sean
 Post subject:
PostPosted: Fri Jun 25, 2004 4:06 pm 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Still no responses?

Let me offer some updated research...I was able to determine that its not just cached objects, but in fact cached results of any kind, even empty results, that are cached...

If the query first returns no rows and an external process then inserts a row, Hibernate will never see that row...subsequent queries continue to return empty result sets...

This seemed to suggest the results set object itself was being cached...however, using a debugger, I was able to confirm that the prepared statement, result set, and iterator instances are unique instances each time through the query loop...

This is getting awfully close to the driver code, but as I previously mentioned a straight JDBC example on that driver does recognize the updates...is Hibernate doing something in the configuration that instructs the driver to cache result sets?

I'd greatly appreciate any replies...
Top
 Profile  
 
gavin
 Post subject:
PostPosted: Fri Jun 25, 2004 4:14 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 12:50 pm
Posts: 5130
Location: Melbourne, Australia
Sounds like you are not committing your transactions, or something like that.
Top
 Profile  
 
sean
 Post subject:
PostPosted: Fri Jun 25, 2004 4:22 pm 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Not committed by the external process?...no they are definitely committed...I can confirm this using yet a third process (isql)...

Further, you'll recall that in my Hibernate process, if I destroy the SessionFactory and recreate it within my query loop it correctly picks up the database changes...

So there is something in the SessionFactory that is caching the data somehow...as previously mentioned recreating sessions doesn't fix it, evicting the caches doesn't fix it, only destroying the SessionFactory...

Also recall that with straight JDBC over the same driver, both reusing statements and connections and recreating them, I see the data updates correctly...
Top
 Profile  
 
gavin
 Post subject:
PostPosted: Fri Jun 25, 2004 4:32 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 12:50 pm
Posts: 5130
Location: Melbourne, Australia
Negative. Hibernate does not cache anything unless explicitly told to. You are mistaken.

What does the HIbernate log show?
Top
 Profile  
 
sean
 Post subject:
PostPosted: Fri Jun 25, 2004 4:48 pm 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
I can only hope I've just misconfigured it...

I've gone ahead and created a very stripped down test case...this will be long, but I'll include the details here...

Here's the hibernate.properties...
Code:
### Query Language ###
hibernate.query.substitutions true 1, false 0, yes 'Y', no 'N'

### Platforms ###
hibernate.dialect net.sf.hibernate.dialect.InterbaseDialect
hibernate.connection.username sysdba
hibernate.connection.password masterkey
hibernate.connection.driver_class interbase.interclient.Driver
hibernate.connection.url jdbc:interbase://localhost:3060/C:/Test/test.fdb

### Hibernate Connection Pool ###
hibernate.connection.pool_size 1

### Miscellaneous Settings ###
hibernate.statement_cache.size 0
hibernate.show_sql true
hibernate.jdbc.batch_size 0
hibernate.jdbc.use_streams_for_binary true
hibernate.max_fetch_depth 1

### Second-level Cache ###
hibernate.cache.use_query_cache false
hibernate.cache.provider_class com.NullCacheProvider


Here's the persistent object class with XDoclet markup...
Code:
package com;
/**
* @hibernate.class table="PROFILE"
* @hibernate.query name="Profile.findProfileByName"
*                  query="select p
*                         from Profile as p
*                         where p.name = :name"
*/
public class Profile {
   private Integer id;
   private String name;
   private Integer revision;
   /**
    * @hibernate.id generator-class="native"
    *               type="int"
    *               length="10"
    * @hibernate.column name="ID"
    *                   sql-type="INTEGER"
    */
   protected Integer getId() {
      return id;
   }
   private void setId(Integer id) {
      this.id = id;
   }
   /**
    * @hibernate.property
    * @hibernate.column name="NAME"
    *                   not-null="true"
    *                   length="10"
    *                   unique="true"
    */
   public String getName() {
      return name;
   }
   public void setName(String name) {
      this.name = name;
   }
   /**
    * @hibernate.property
    * @hibernate.column name="REVISION"
    */
   public Integer getRevision() {
      return revision;
   }
   public void setRevision(Integer revision) {
      this.revision = revision;
   }
}


Here's the test class (you may notice the other three test options that all work correctly)...

Code:
package com;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Iterator;

import net.sf.hibernate.HibernateException;
import net.sf.hibernate.Query;
import net.sf.hibernate.Session;
import net.sf.hibernate.SessionFactory;
import net.sf.hibernate.cfg.Configuration;

public class Test {
   public static void main(String[] args) {
      // select a test model
      testHibernateNamedQueryWithFactoryReuse();
//      testHibernateNamedQueryWithFactoryRecreation();
//      testJDBCWithConnectionReuse();
//      testJDBCWithConnectionRecreation();
   }
   private static void testHibernateNamedQueryWithFactoryReuse() {
      // *** THIS DOES NOT CORRECTLY REFRESH FROM THE DATABASE
      try {
         // create hibernate configuration
         Configuration config = new Configuration();
         // add hibernate supported types
         config.addClass(Profile.class);
         // create session factory singleton
         SessionFactory factory = config.buildSessionFactory();
         while (true) {
            Session session = factory.openSession();
            // find using named query
            Query query = session.getNamedQuery("Profile.findProfileByName");
            query.setParameter("name", "foo");
            dump(query.iterate());
            try {
               Thread.sleep(1000);
            } catch (InterruptedException e) {
               e.printStackTrace();
            }
            session.close();
         }
      } catch (HibernateException ex) {
         // this is a fatal error for the datastore
         throw new RuntimeException("Failed to configured Hibernate session.", ex);
      }
   }
   private static void testHibernateNamedQueryWithFactoryRecreation() {
      // *** this correctly refreshes from the database
      try {
         // create hibernate configuration
         Configuration config = new Configuration();
         // add hibernate supported types
         config.addClass(Profile.class);
         while (true) {
            // create session factory singleton
            SessionFactory factory = config.buildSessionFactory();
            Session session = factory.openSession();
            // find using named query
            Query query = session.getNamedQuery("Profile.findProfileByName");
            query.setParameter("name", "foo");
            dump(query.iterate());
            try {
               Thread.sleep(1000);
            } catch (InterruptedException e) {
               e.printStackTrace();
            }
            session.close();
         }
      } catch (HibernateException ex) {
         // this is a fatal error for the datastore
         throw new RuntimeException("Failed to configured Hibernate session.", ex);
      }
   }
   private static void dump(Iterator result) {
      while (result.hasNext()) {
         Profile p = (Profile)result.next();
         System.out.println(p);
         System.out.println(" Revision: "+p.getRevision());
      }
   }
   private static void testJDBCWithConnectionReuse() {
      // *** this correctly refreshes from the database
      Connection conn = null;
      Statement stmt = null;
      try {
         String url = "jdbc:interbase://localhost:3060/C:/Test/test.fdb";
         Class.forName("interbase.interclient.Driver");
         conn = DriverManager.getConnection(url, "sysdba", "masterkey");
         stmt = conn.createStatement();
      } catch (Exception e1) {
         e1.printStackTrace();
      }
      while (true) {
         try {
            ResultSet rs = stmt.executeQuery("select revision from PROFILE where name='foo'");
            while (rs.next()) {
               System.out.println(" Revision: " + rs.getInt(1));
            }
            rs.close();
         } catch (SQLException e) {
            e.printStackTrace();
         } catch (Exception e) {
            e.printStackTrace();
         } finally {
            try {
               Thread.sleep(1000);
            } catch (InterruptedException e2) {
               e2.printStackTrace();
            }
         }
      }
   }
   private static void testJDBCWithConnectionRecreation() {
      // *** this correctly refreshes from the database
      Connection conn = null;
      Statement stmt = null;
      while (true) {
         try {
            String url = "jdbc:interbase://localhost:3060/C:/Test/test.fdb";
            Class.forName("interbase.interclient.Driver");
            conn = DriverManager.getConnection(url, "sysdba", "masterkey");
            stmt = conn.createStatement();
            ResultSet rs = stmt.executeQuery("select revision from PROFILE where name='foo'");
            while (rs.next()) {
               System.out.println(" Revision: " + rs.getInt(1));
            }
            rs.close();
         } catch (SQLException e) {
            e.printStackTrace();
         } catch (Exception e) {
            e.printStackTrace();
         } finally {
            try {
               Thread.sleep(1000);
            } catch (InterruptedException e2) {
               e2.printStackTrace();
            }
         }
      }
   }
}


And finally, the following is the log output...you'll have to trust that amidst this iterative output I used the ISQL console to update and commit change on the revision column from 1 to 2...as you can see, hibernate continues to return a result of 1...
[code]16:41:06,713 INFO Environment:462 - Hibernate 2.1.4
16:41:06,733 INFO Environment:496 - loaded properties from resource hibernate.properties: {hibernate.connection.driver_class=interbase.interclient.Driver, hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=com.NullCacheProvider, hibernate.cache.use_query_cache=false, hibernate.max_fetch_depth=1, hibernate.dialect=net.sf.hibernate.dialect.InterbaseDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.jdbc.batch_size=0, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.connection.username=sysdba, hibernate.connection.url=jdbc:interbase://localhost:3060/C:/Test/test.fdb, hibernate.show_sql=true, hibernate.connection.password=masterkey, hibernate.statement_cache.size=0, hibernate.connection.pool_size=1}
16:41:06,733 INFO Environment:521 - using java.io streams to persist binary types
16:41:06,743 INFO Environment:522 - using CGLIB reflection optimizer
16:41:06,813 INFO Configuration:347 - Mapping resource: com/Profile.hbm.xml
16:41:06,924 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
16:41:06,924 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
16:41:07,114 INFO Binder:229 - Mapping class: com.Profile -> PROFILE
16:41:07,214 DEBUG Binder:475 - Mapped property: id -> ID, type: integer
16:41:07,234 DEBUG Binder:475 - Mapped property: name -> NAME, type: string
16:41:07,244 DEBUG Binder:475 - Mapped property: revision -> REVISION, type: integer
16:41:07,244 DEBUG Binder:1267 - Named query: Profile.findProfileByName ->
select p from Profile as p where p.name = :name

16:41:07,244 INFO Configuration:613 - processing one-to-many association mappings
16:41:07,244 INFO Configuration:622 - processing one-to-one association property references
16:41:07,244 INFO Configuration:647 - processing foreign key constraints
16:41:07,284 INFO Dialect:82 - Using dialect: net.sf.hibernate.dialect.InterbaseDialect
16:41:07,284 INFO SettingsFactory:58 - Maximim outer join fetch depth: 1
16:41:07,284 INFO SettingsFactory:62 - Use outer join fetching: true
16:41:07,294 INFO DriverManagerConnectionProvider:42 - Using Hibernate built-in connection pool (not for production use!)
16:41:07,294 INFO DriverManagerConnectionProvider:43 - Hibernate connection pool size: 1
16:41:07,324 INFO DriverManagerConnectionProvider:77 - using driver: interbase.interclient.Driver at URL: jdbc:interbase://localhost:3060/C:/Test/test.fdb
16:41:07,324 INFO DriverManagerConnectionProvider:78 - connection properties: {user=sysdba, password=masterkey}
16:41:07,334 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
16:41:07,334 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:07,334 DEBUG DriverManagerConnectionProvider:100 - opening new JDBC connection
16:41:08,496 DEBUG DriverManagerConnectionProvider:106 - created connection to: jdbc:interbase://localhost:3060/C:/Test/test.fdb, Isolation Level: 8
16:41:08,496 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:08,506 WARN SettingsFactory:95 - Could not obtain connection metadata
interbase.interclient.DriverNotCapableException: [interclient] Unsupported feature: Using a JDBC 2 method which is not yet supported.
See API reference for exception interbase.interclient.DriverNotCapableException
at interbase.interclient.DatabaseMetaData.supportsResultSetType(DatabaseMetaData.java:4957)
at net.sf.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:75)
at net.sf.hibernate.cfg.Configuration.buildSettings(Configuration.java:1132)
at net.sf.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:766)
at com.Test.testHibernateNamedQueryWithFactoryReuse(Test.java:32)
at com.Test.main(Test.java:19)
16:41:08,506 INFO SettingsFactory:102 - Use scrollable result sets: false
16:41:08,506 INFO SettingsFactory:105 - Use JDBC3 getGeneratedKeys(): false
16:41:08,506 INFO SettingsFactory:108 - Optimize cache for minimal puts: false
16:41:08,506 INFO SettingsFactory:114 - echoing all SQL to stdout
16:41:08,506 INFO SettingsFactory:117 - Query language substitutions: {no='N', true=1, yes='Y', false=0}
16:41:08,506 INFO SettingsFactory:128 - cache provider: com.NullCacheProvider
16:41:08,516 INFO Configuration:1093 - instantiating and configuring caches
16:41:08,666 INFO SessionFactoryImpl:119 - building session factory
16:41:08,666 DEBUG SessionFactoryImpl:125 - instantiating session factory with properties: {java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.connection.password=masterkey, hibernate.cache.provider_class=com.NullCacheProvider, sun.boot.library.path=C:\Program Files\Java\j2sdk1.4.2_04\jre\bin, java.vm.version=1.4.2_04-b05, hibernate.connection.username=sysdba, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, hibernate.cache.use_query_cache=false, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=US, sun.os.patch.level=Service Pack 1, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Test, java.runtime.version=1.4.2_04-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\SEANLI~1.PAN\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.java2d.fontpath=, java.library.path=C:\Program Files\Java\j2sdk1.4.2_04\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\IM;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\;C:\Program Files\Common Files\Adaptec Shared\System;C:\Program Files\Java\j2sdk1.4.2_03\bin\;C:\Program Files\Java\ant-1.6.1\bin\;C:\Work\install\InterBase\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, hibernate.connection.pool_size=1, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.1, user.home=C:\Documents and Settings\sean.lindsay.PANGONETWORKS, user.timezone=America/New_York, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.4, hibernate.connection.driver_class=interbase.interclient.Driver, java.class.path=C:\Test;C:\Test\lib\cglib-full-2.0.1.jar;C:\Test\lib\commons-collections-2.1.jar;C:\Test\lib\commons-logging-1.0.3.jar;C:\Test\lib\dom4j-1.4.jar;C:\Test\lib\hibernate2.jar;C:\Test\lib\interclient.jar;C:\Test\lib\jta.jar;C:\Test\lib\log4j-1.2.8.jar, user.name=sean.lindsay, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.show_sql=true, java.vm.specification.version=1.0, java.home=C:\Program Files\Java\j2sdk1.4.2_04\jre, sun.arch.data.model=32, hibernate.dialect=net.sf.hibernate.dialect.InterbaseDialect, hibernate.connection.url=jdbc:interbase://localhost:3060/C:/Test/test.fdb, user.language=en, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, hibernate.jdbc.use_streams_for_binary=true, java.version=1.4.2_04, java.ext.dirs=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\ext, sun.boot.class.path=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\rt.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\i18n.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\sunrsasign.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\jsse.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\jce.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\charsets.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\classes, java.vendor=Sun Microsystems Inc., hibernate.jdbc.batch_size=0, file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, hibernate.statement_cache.size=0, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, hibernate.max_fetch_depth=1, sun.cpu.isalist=pentium i486 i386}
16:41:09,017 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
16:41:09,027 DEBUG SessionFactoryObjectFactory:76 - registered: 40288210fd5d8a4400fd5d8a46990000 (unnamed)
16:41:09,027 INFO SessionFactoryObjectFactory:82 - no JNDI name configured
16:41:09,027 DEBUG SessionFactoryImpl:196 - instantiated session factory
16:41:09,077 DEBUG SessionImpl:555 - opened session
16:41:09,107 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:09,107 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:09,127 DEBUG QueryTranslator:147 - compiling query
16:41:09,157 DEBUG SessionImpl:2242 - flushing session
16:41:09,157 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:09,157 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:09,157 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:09,157 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:09,157 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:09,157 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:09,157 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:09,167 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:09,167 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:09,167 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:09,167 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:09,167 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:09,167 DEBUG BatcherImpl:241 - preparing statement
16:41:09,247 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:09,247 DEBUG IteratorImpl:83 - retrieving next results
16:41:09,257 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:09,257 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:09,257 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:09,257 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:09,267 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:09,267 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:09,267 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:09,267 DEBUG BatcherImpl:241 - preparing statement
16:41:09,277 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:09,277 DEBUG Loader:197 - processing result set
16:41:09,277 DEBUG Loader:405 - result row: 1
16:41:09,287 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:09,297 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:09,297 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:09,297 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:09,297 DEBUG Loader:226 - done processing result set (1 rows)
16:41:09,307 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:09,307 DEBUG BatcherImpl:261 - closing statement
16:41:09,307 DEBUG Loader:239 - total objects hydrated: 1
16:41:09,307 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:09,307 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:09,307 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:09,307 DEBUG IteratorImpl:79 - exhausted results
16:41:09,307 DEBUG IteratorImpl:67 - closing iterator
16:41:09,347 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:09,347 DEBUG BatcherImpl:261 - closing statement
16:41:09,347 DEBUG IteratorImpl:120 - returning current results
com.Profile@1742700
Revision: 1
16:41:10,349 DEBUG SessionImpl:573 - closing session
16:41:10,349 DEBUG SessionImpl:3332 - disconnecting session
16:41:10,349 DEBUG JDBCExceptionReporter:18 - SQL Warning
java.sql.SQLWarning: [interclient] Specified dialect not supported: The SQL Dialect has been changed to 3.
See API reference for exception interbase.interclient.SQLDialectException
at interbase.interclient.RecvMessage.createSQLWarning(RecvMessage.java:709)
at interbase.interclient.RecvMessage.makeSQLWarning(RecvMessage.java:578)
at interbase.interclient.RecvMessage.get_WARNINGS(RecvMessage.java:534)
at interbase.interclient.Connection.remote_ATTACH_DATABASE(Connection.java:409)
at interbase.interclient.Connection.connect(Connection.java:331)
at interbase.interclient.Connection.<init>(Connection.java:285)
at interbase.interclient.Driver.connect(Driver.java:204)
at java.sql.DriverManager.getConnection(DriverManager.java:512)
at java.sql.DriverManager.getConnection(DriverManager.java:140)
at net.sf.hibernate.connection.DriverManagerConnectionProvider.getConnection(DriverManagerConnectionProvider.java:101)
at net.sf.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:72)
at net.sf.hibernate.cfg.Configuration.buildSettings(Configuration.java:1132)
at net.sf.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:766)
at com.Test.testHibernateNamedQueryWithFactoryReuse(Test.java:32)
at com.Test.main(Test.java:19)
16:41:10,349 WARN JDBCExceptionReporter:20 - SQL Warning: 130, SQLState: 01JB0
16:41:10,349 WARN JDBCExceptionReporter:28 - [interclient] Specified dialect not supported: The SQL Dialect has been changed to 3.
See API reference for exception interbase.interclient.SQLDialectException
16:41:10,349 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:10,349 DEBUG SessionImpl:585 - transaction completion
16:41:10,349 DEBUG SessionImpl:555 - opened session
16:41:10,349 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:10,349 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:10,349 DEBUG SessionImpl:2242 - flushing session
16:41:10,349 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:10,349 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:10,349 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:10,359 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:10,359 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:10,359 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:10,359 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:10,359 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:10,359 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:10,359 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:10,359 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:10,359 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:10,359 DEBUG BatcherImpl:241 - preparing statement
16:41:10,359 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:10,369 DEBUG IteratorImpl:83 - retrieving next results
16:41:10,369 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:10,369 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:10,369 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:10,369 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:10,369 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:10,369 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:10,369 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:10,369 DEBUG BatcherImpl:241 - preparing statement
16:41:10,379 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:10,379 DEBUG Loader:197 - processing result set
16:41:10,379 DEBUG Loader:405 - result row: 1
16:41:10,379 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:10,379 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:10,379 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:10,379 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:10,379 DEBUG Loader:226 - done processing result set (1 rows)
16:41:10,379 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:10,389 DEBUG BatcherImpl:261 - closing statement
16:41:10,389 DEBUG Loader:239 - total objects hydrated: 1
16:41:10,389 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:10,389 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:10,389 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:10,389 DEBUG IteratorImpl:79 - exhausted results
16:41:10,389 DEBUG IteratorImpl:67 - closing iterator
16:41:10,389 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:10,389 DEBUG BatcherImpl:261 - closing statement
16:41:10,389 DEBUG IteratorImpl:120 - returning current results
com.Profile@89cc5e
Revision: 1
16:41:11,390 DEBUG SessionImpl:573 - closing session
16:41:11,390 DEBUG SessionImpl:3332 - disconnecting session
16:41:11,390 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:11,390 DEBUG SessionImpl:585 - transaction completion
16:41:11,390 DEBUG SessionImpl:555 - opened session
16:41:11,390 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:11,390 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:11,390 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:11,390 DEBUG SessionImpl:2242 - flushing session
16:41:11,390 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:11,390 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:11,390 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:11,390 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:11,390 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:11,390 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:11,440 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:11,440 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:11,440 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:11,440 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:11,440 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:11,450 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:11,450 DEBUG BatcherImpl:241 - preparing statement
16:41:11,450 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:11,450 DEBUG IteratorImpl:83 - retrieving next results
16:41:11,450 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:11,450 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:11,460 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:11,460 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:11,460 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:11,460 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:11,460 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:11,460 DEBUG BatcherImpl:241 - preparing statement
16:41:11,460 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:11,460 DEBUG Loader:197 - processing result set
16:41:11,500 DEBUG Loader:405 - result row: 1
16:41:11,500 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:11,500 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:11,500 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:11,510 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:11,510 DEBUG Loader:226 - done processing result set (1 rows)
16:41:11,510 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:11,510 DEBUG BatcherImpl:261 - closing statement
16:41:11,510 DEBUG Loader:239 - total objects hydrated: 1
16:41:11,510 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:11,510 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:11,510 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:11,510 DEBUG IteratorImpl:79 - exhausted results
16:41:11,510 DEBUG IteratorImpl:67 - closing iterator
16:41:11,510 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:11,510 DEBUG BatcherImpl:261 - closing statement
16:41:11,520 DEBUG IteratorImpl:120 - returning current results
com.Profile@1de9ac4
Revision: 1
16:41:12,522 DEBUG SessionImpl:573 - closing session
16:41:12,522 DEBUG SessionImpl:3332 - disconnecting session
16:41:12,522 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:12,522 DEBUG SessionImpl:585 - transaction completion
16:41:12,522 DEBUG SessionImpl:555 - opened session
16:41:12,522 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:12,522 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:12,522 DEBUG SessionImpl:2242 - flushing session
16:41:12,522 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:12,522 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:12,522 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:12,522 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:12,522 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:12,522 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:12,522 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:12,522 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:12,522 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:12,522 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:12,552 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:12,552 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:12,552 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:12,552 DEBUG BatcherImpl:241 - preparing statement
16:41:12,562 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:12,562 DEBUG IteratorImpl:83 - retrieving next results
16:41:12,562 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:12,562 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:12,562 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:12,562 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:12,562 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:12,562 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:12,562 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:12,562 DEBUG BatcherImpl:241 - preparing statement
16:41:12,572 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:12,572 DEBUG Loader:197 - processing result set
16:41:12,572 DEBUG Loader:405 - result row: 1
16:41:12,572 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:12,572 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:12,572 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:12,572 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:12,582 DEBUG Loader:226 - done processing result set (1 rows)
16:41:12,582 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:12,582 DEBUG BatcherImpl:261 - closing statement
16:41:12,582 DEBUG Loader:239 - total objects hydrated: 1
16:41:12,582 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:12,582 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:12,582 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:12,582 DEBUG IteratorImpl:79 - exhausted results
16:41:12,582 DEBUG IteratorImpl:67 - closing iterator
16:41:12,582 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:12,582 DEBUG BatcherImpl:261 - closing statement
16:41:12,582 DEBUG IteratorImpl:120 - returning current results
com.Profile@513d61
Revision: 1
16:41:13,593 DEBUG SessionImpl:573 - closing session
16:41:13,593 DEBUG SessionImpl:3332 - disconnecting session
16:41:13,593 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:13,593 DEBUG SessionImpl:585 - transaction completion
16:41:13,593 DEBUG SessionImpl:555 - opened session
16:41:13,593 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:13,593 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:13,593 DEBUG SessionImpl:2242 - flushing session
16:41:13,593 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:13,593 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:13,593 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:13,593 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:13,593 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:13,593 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:13,593 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:13,593 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:13,593 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:13,593 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:13,603 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:13,603 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:13,603 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:13,603 DEBUG BatcherImpl:241 - preparing statement
16:41:13,603 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:13,603 DEBUG IteratorImpl:83 - retrieving next results
16:41:13,603 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:13,603 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:13,603 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:13,603 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:13,603 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:13,603 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:13,603 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:13,613 DEBUG BatcherImpl:241 - preparing statement
16:41:13,613 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:13,613 DEBUG Loader:197 - processing result set
16:41:13,613 DEBUG Loader:405 - result row: 1
16:41:13,613 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:13,613 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:13,613 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:13,613 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:13,623 DEBUG Loader:226 - done processing result set (1 rows)
16:41:13,623 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:13,623 DEBUG BatcherImpl:261 - closing statement
16:41:13,623 DEBUG Loader:239 - total objects hydrated: 1
16:41:13,623 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:13,623 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:13,623 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:13,623 DEBUG IteratorImpl:79 - exhausted results
16:41:13,623 DEBUG IteratorImpl:67 - closing iterator
16:41:13,623 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:13,623 DEBUG BatcherImpl:261 - closing statement
16:41:13,643 DEBUG IteratorImpl:120 - returning current results
com.Profile@16c163f
Revision: 1
16:41:14,645 DEBUG SessionImpl:573 - closing session
16:41:14,645 DEBUG SessionImpl:3332 - disconnecting session
16:41:14,645 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:14,645 DEBUG SessionImpl:585 - transaction completion
16:41:14,645 DEBUG SessionImpl:555 - opened session
16:41:14,645 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:14,645 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:14,645 DEBUG SessionImpl:2242 - flushing session
16:41:14,645 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:14,645 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:14,645 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:14,645 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:14,645 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:14,645 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:14,645 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:14,645 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:14,645 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:14,655 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:14,655 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:14,655 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:14,655 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:14,655 DEBUG BatcherImpl:241 - preparing statement
16:41:14,655 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:14,655 DEBUG IteratorImpl:83 - retrieving next results
16:41:14,685 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:14,685 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:14,685 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:14,685 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:14,685 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:14,685 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:14,695 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:14,695 DEBUG BatcherImpl:241 - preparing statement
16:41:14,695 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:14,695 DEBUG Loader:197 - processing result set
16:41:14,695 DEBUG Loader:405 - result row: 1
16:41:14,695 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:14,695 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:14,695 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:14,695 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:14,695 DEBUG Loader:226 - done processing result set (1 rows)
16:41:14,705 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:14,705 DEBUG BatcherImpl:261 - closing statement
16:41:14,705 DEBUG Loader:239 - total objects hydrated: 1
16:41:14,705 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:14,705 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:14,705 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:14,705 DEBUG IteratorImpl:79 - exhausted results
16:41:14,705 DEBUG IteratorImpl:67 - closing iterator
16:41:14,705 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:14,705 DEBUG BatcherImpl:261 - closing statement
16:41:14,705 DEBUG IteratorImpl:120 - returning current results
com.Profile@1060478
Revision: 1
16:41:15,716 DEBUG SessionImpl:573 - closing session
16:41:15,716 DEBUG SessionImpl:3332 - disconnecting session
16:41:15,716 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:15,716 DEBUG SessionImpl:585 - transaction completion
16:41:15,716 DEBUG SessionImpl:555 - opened session
16:41:15,716 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:15,716 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:15,716 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:15,716 DEBUG SessionImpl:2242 - flushing session
16:41:15,716 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:15,716 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:15,716 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:15,716 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:15,716 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:15,716 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:15,716 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:15,716 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:15,716 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:15,726 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:15,726 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:15,726 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:15,726 DEBUG BatcherImpl:241 - preparing statement
16:41:15,726 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:15,726 DEBUG IteratorImpl:83 - retrieving next results
16:41:15,726 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:15,726 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:15,736 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:15,736 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:15,736 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:15,736 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:15,736 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:15,776 DEBUG BatcherImpl:241 - preparing statement
16:41:15,786 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:15,786 DEBUG Loader:197 - processing result set
16:41:15,786 DEBUG Loader:405 - result row: 1
16:41:15,786 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:15,786 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:15,786 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:15,796 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:15,796 DEBUG Loader:226 - done processing result set (1 rows)
16:41:15,796 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:15,796 DEBUG BatcherImpl:261 - closing statement
16:41:15,796 DEBUG Loader:239 - total objects hydrated: 1
16:41:15,796 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:15,796 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:15,796 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:15,796 DEBUG IteratorImpl:79 - exhausted results
16:41:15,796 DEBUG IteratorImpl:67 - closing iterator
16:41:15,796 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:15,796 DEBUG BatcherImpl:261 - closing statement
16:41:15,796 DEBUG IteratorImpl:120 - returning current results
com.Profile@165a3c2
Revision: 1
16:41:16,808 DEBUG SessionImpl:573 - closing session
16:41:16,808 DEBUG SessionImpl:3332 - disconnecting session
16:41:16,808 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:16,808 DEBUG SessionImpl:585 - transaction completion
16:41:16,808 DEBUG SessionImpl:555 - opened session
16:41:16,808 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:16,808 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:16,808 DEBUG SessionImpl:2242 - flushing session
16:41:16,808 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:16,808 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:16,808 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:16,808 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:16,808 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:16,808 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:16,808 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:16,808 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:16,808 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:16,808 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:16,808 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:16,808 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:16,818 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:16,808 DEBUG BatcherImpl:241 - preparing statement
16:41:16,818 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:16,828 DEBUG IteratorImpl:83 - retrieving next results
16:41:16,828 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:16,828 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:16,828 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:16,828 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:16,828 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:16,828 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:16,828 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:16,828 DEBUG BatcherImpl:241 - preparing statement
16:41:16,828 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:16,838 DEBUG Loader:197 - processing result set
16:41:16,838 DEBUG Loader:405 - result row: 1
16:41:16,838 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:16,838 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:16,838 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:16,838 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:16,838 DEBUG Loader:226 - done processing result set (1 rows)
16:41:16,838 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:16,838 DEBUG BatcherImpl:261 - closing statement
16:41:16,838 DEBUG Loader:239 - total objects hydrated: 1
16:41:16,838 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:16,838 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:16,848 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:16,848 DEBUG IteratorImpl:79 - exhausted results
16:41:16,848 DEBUG IteratorImpl:67 - closing iterator
16:41:16,848 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:16,848 DEBUG BatcherImpl:261 - closing statement
16:41:16,848 DEBUG IteratorImpl:120 - returning current results
com.Profile@1bb5c09
Revision: 1
16:41:17,849 DEBUG SessionImpl:573 - closing session
16:41:17,849 DEBUG SessionImpl:3332 - disconnecting session
16:41:17,849 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:17,849 DEBUG SessionImpl:585 - transaction completion
16:41:17,849 DEBUG SessionImpl:555 - opened session
16:41:17,849 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:17,849 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:17,849 DEBUG SessionImpl:2242 - flushing session
16:41:17,849 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:17,849 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:17,849 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:17,849 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:17,849 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:17,849 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:17,849 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:17,849 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:17,849 DEBUG SessionImpl:3384 - running Session.finalize()
16:41:17,849 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:17,849 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:17,849 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:17,849 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:17,859 DEBUG BatcherImpl:241 - preparing statement
16:41:17,859 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:17,859 DEBUG IteratorImpl:83 - retrieving next results
16:41:17,859 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:17,859 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:17,859 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:17,869 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:17,869 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:17,869 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:17,879 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:17,879 DEBUG BatcherImpl:241 - preparing statement
16:41:17,879 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:17,879 DEBUG Loader:197 - processing result set
16:41:17,879 DEBUG Loader:405 - result row: 1
16:41:17,879 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:17,88
Top
 Profile  
 
sean
 Post subject:
PostPosted: Mon Jun 28, 2004 7:55 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Gavin,
I was optimistic when you indicated that it surely must be some misconfiguration on my end that the above example would highlight a glaring mistake I'd made...any thoughts as to why the first hibernate example would fail but the second would work, when all that is different is the SessionFactory instantiation inside the loop?...is there any additional information I can provide?

If it will help, here's a more brief review of the example...

The configuration...
Code:
### Query Language ###
hibernate.query.substitutions true 1, false 0, yes 'Y', no 'N'

### Platforms ###
hibernate.dialect net.sf.hibernate.dialect.InterbaseDialect
hibernate.connection.username sysdba
hibernate.connection.password masterkey
hibernate.connection.driver_class interbase.interclient.Driver
hibernate.connection.url jdbc:interbase://localhost:3060/C:/Test/test.fdb

### Hibernate Connection Pool ###
hibernate.connection.pool_size 1

### Miscellaneous Settings ###
hibernate.statement_cache.size 0
hibernate.show_sql true
hibernate.jdbc.batch_size 0
hibernate.jdbc.use_streams_for_binary true
hibernate.max_fetch_depth 1

### Second-level Cache ###
hibernate.cache.use_query_cache false
hibernate.cache.provider_class com.NullCacheProvider


The code...
Code:
   private static void testHibernateNamedQueryWithFactoryReuse() {
      // *** THIS DOES NOT CORRECTLY REFRESH FROM THE DATABASE
      try {
         // create hibernate configuration
         Configuration config = new Configuration();
         // add hibernate supported types
         config.addClass(Profile.class);
         // create session factory singleton
         SessionFactory factory = config.buildSessionFactory();
         while (true) {
            Session session = factory.openSession();
            // find using named query
            Query query = session.getNamedQuery("Profile.findProfileByName");
            query.setParameter("name", "foo");
            dump(query.iterate());
            session.close();
         }
      } catch (HibernateException ex) {
      }
   }
   private static void testHibernateNamedQueryWithFactoryRecreation() {
      // *** this correctly refreshes from the database
      try {
         // create hibernate configuration
         Configuration config = new Configuration();
         // add hibernate supported types
         config.addClass(Profile.class);
         while (true) {
            // create session factory singleton
            SessionFactory factory = config.buildSessionFactory();
            Session session = factory.openSession();
            // find using named query
            Query query = session.getNamedQuery("Profile.findProfileByName");
            query.setParameter("name", "foo");
            dump(query.iterate());
            session.close();
         }
      } catch (HibernateException ex) {
      }
   }


And the log...
Code:
16:41:06,713 INFO Environment:462 - Hibernate 2.1.4
16:41:06,733 INFO Environment:496 - loaded properties from resource hibernate.properties: {hibernate.connection.driver_class=interbase.interclient.Driver, hibernate.cglib.use_reflection_optimizer=true, hibernate.cache.provider_class=com.NullCacheProvider, hibernate.cache.use_query_cache=false, hibernate.max_fetch_depth=1, hibernate.dialect=net.sf.hibernate.dialect.InterbaseDialect, hibernate.jdbc.use_streams_for_binary=true, hibernate.jdbc.batch_size=0, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.connection.username=sysdba, hibernate.connection.url=jdbc:interbase://localhost:3060/C:/Test/test.fdb, hibernate.show_sql=true, hibernate.connection.password=masterkey, hibernate.statement_cache.size=0, hibernate.connection.pool_size=1}
16:41:06,733 INFO Environment:521 - using java.io streams to persist binary types
16:41:06,743 INFO Environment:522 - using CGLIB reflection optimizer
16:41:06,813 INFO Configuration:347 - Mapping resource: com/Profile.hbm.xml
16:41:06,924 DEBUG DTDEntityResolver:20 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
16:41:06,924 DEBUG DTDEntityResolver:29 - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
16:41:07,114 INFO Binder:229 - Mapping class: com.Profile -> PROFILE
16:41:07,214 DEBUG Binder:475 - Mapped property: id -> ID, type: integer
16:41:07,234 DEBUG Binder:475 - Mapped property: name -> NAME, type: string
16:41:07,244 DEBUG Binder:475 - Mapped property: revision -> REVISION, type: integer
16:41:07,244 DEBUG Binder:1267 - Named query: Profile.findProfileByName ->
select p from Profile as p where p.name = :name

16:41:07,244 INFO Configuration:613 - processing one-to-many association mappings
16:41:07,244 INFO Configuration:622 - processing one-to-one association property references
16:41:07,244 INFO Configuration:647 - processing foreign key constraints
16:41:07,284 INFO Dialect:82 - Using dialect: net.sf.hibernate.dialect.InterbaseDialect
16:41:07,284 INFO SettingsFactory:58 - Maximim outer join fetch depth: 1
16:41:07,284 INFO SettingsFactory:62 - Use outer join fetching: true
16:41:07,294 INFO DriverManagerConnectionProvider:42 - Using Hibernate built-in connection pool (not for production use!)
16:41:07,294 INFO DriverManagerConnectionProvider:43 - Hibernate connection pool size: 1
16:41:07,324 INFO DriverManagerConnectionProvider:77 - using driver: interbase.interclient.Driver at URL: jdbc:interbase://localhost:3060/C:/Test/test.fdb
16:41:07,324 INFO DriverManagerConnectionProvider:78 - connection properties: {user=sysdba, password=masterkey}
16:41:07,334 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
16:41:07,334 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:07,334 DEBUG DriverManagerConnectionProvider:100 - opening new JDBC connection
16:41:08,496 DEBUG DriverManagerConnectionProvider:106 - created connection to: jdbc:interbase://localhost:3060/C:/Test/test.fdb, Isolation Level: 8
16:41:08,496 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:08,506 WARN SettingsFactory:95 - Could not obtain connection metadata
interbase.interclient.DriverNotCapableException: [interclient] Unsupported feature: Using a JDBC 2 method which is not yet supported.
See API reference for exception interbase.interclient.DriverNotCapableException
at interbase.interclient.DatabaseMetaData.supportsResultSetType(DatabaseMetaData.java:4957)
at net.sf.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:75)
at net.sf.hibernate.cfg.Configuration.buildSettings(Configuration.java:1132)
at net.sf.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:766)
at com.Test.testHibernateNamedQueryWithFactoryReuse(Test.java:32)
at com.Test.main(Test.java:19)
16:41:08,506 INFO SettingsFactory:102 - Use scrollable result sets: false
16:41:08,506 INFO SettingsFactory:105 - Use JDBC3 getGeneratedKeys(): false
16:41:08,506 INFO SettingsFactory:108 - Optimize cache for minimal puts: false
16:41:08,506 INFO SettingsFactory:114 - echoing all SQL to stdout
16:41:08,506 INFO SettingsFactory:117 - Query language substitutions: {no='N', true=1, yes='Y', false=0}
16:41:08,506 INFO SettingsFactory:128 - cache provider: com.NullCacheProvider
16:41:08,516 INFO Configuration:1093 - instantiating and configuring caches
16:41:08,666 INFO SessionFactoryImpl:119 - building session factory
16:41:08,666 DEBUG SessionFactoryImpl:125 - instantiating session factory with properties: {java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.connection.password=masterkey, hibernate.cache.provider_class=com.NullCacheProvider, sun.boot.library.path=C:\Program Files\Java\j2sdk1.4.2_04\jre\bin, java.vm.version=1.4.2_04-b05, hibernate.connection.username=sysdba, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, hibernate.cache.use_query_cache=false, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=US, sun.os.patch.level=Service Pack 1, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Test, java.runtime.version=1.4.2_04-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\SEANLI~1.PAN\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.java2d.fontpath=, java.library.path=C:\Program Files\Java\j2sdk1.4.2_04\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\IM;C:\Program Files\Microsoft SQL Server\80\Tools\Binn\;C:\Program Files\Microsoft Office\OFFICE11\Business Contact Manager\;C:\Program Files\Common Files\Adaptec Shared\System;C:\Program Files\Java\j2sdk1.4.2_03\bin\;C:\Program Files\Java\ant-1.6.1\bin\;C:\Work\install\InterBase\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, hibernate.connection.pool_size=1, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.1, user.home=C:\Documents and Settings\sean.lindsay.PANGONETWORKS, user.timezone=America/New_York, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.4, hibernate.connection.driver_class=interbase.interclient.Driver, java.class.path=C:\Test;C:\Test\lib\cglib-full-2.0.1.jar;C:\Test\lib\commons-collections-2.1.jar;C:\Test\lib\commons-logging-1.0.3.jar;C:\Test\lib\dom4j-1.4.jar;C:\Test\lib\hibernate2.jar;C:\Test\lib\interclient.jar;C:\Test\lib\jta.jar;C:\Test\lib\log4j-1.2.8.jar, user.name=sean.lindsay, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N', hibernate.show_sql=true, java.vm.specification.version=1.0, java.home=C:\Program Files\Java\j2sdk1.4.2_04\jre, sun.arch.data.model=32, hibernate.dialect=net.sf.hibernate.dialect.InterbaseDialect, hibernate.connection.url=jdbc:interbase://localhost:3060/C:/Test/test.fdb, user.language=en, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, hibernate.jdbc.use_streams_for_binary=true, java.version=1.4.2_04, java.ext.dirs=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\ext, sun.boot.class.path=C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\rt.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\i18n.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\sunrsasign.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\jsse.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\jce.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\lib\charsets.jar;C:\Program Files\Java\j2sdk1.4.2_04\jre\classes, java.vendor=Sun Microsystems Inc., hibernate.jdbc.batch_size=0, file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, hibernate.statement_cache.size=0, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, hibernate.max_fetch_depth=1, sun.cpu.isalist=pentium i486 i386}
16:41:09,017 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
16:41:09,027 DEBUG SessionFactoryObjectFactory:76 - registered: 40288210fd5d8a4400fd5d8a46990000 (unnamed)
16:41:09,027 INFO SessionFactoryObjectFactory:82 - no JNDI name configured
16:41:09,027 DEBUG SessionFactoryImpl:196 - instantiated session factory
16:41:09,077 DEBUG SessionImpl:555 - opened session
16:41:09,107 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:09,107 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:09,127 DEBUG QueryTranslator:147 - compiling query
16:41:09,157 DEBUG SessionImpl:2242 - flushing session
16:41:09,157 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:09,157 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:09,157 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:09,157 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:09,157 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:09,157 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:09,157 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:09,167 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:09,167 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:09,167 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:09,167 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:09,167 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:09,167 DEBUG BatcherImpl:241 - preparing statement
16:41:09,247 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:09,247 DEBUG IteratorImpl:83 - retrieving next results
16:41:09,257 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:09,257 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:09,257 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:09,257 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:09,267 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:09,267 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:09,267 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:09,267 DEBUG BatcherImpl:241 - preparing statement
16:41:09,277 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:09,277 DEBUG Loader:197 - processing result set
16:41:09,277 DEBUG Loader:405 - result row: 1
16:41:09,287 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:09,297 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:09,297 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:09,297 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:09,297 DEBUG Loader:226 - done processing result set (1 rows)
16:41:09,307 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:09,307 DEBUG BatcherImpl:261 - closing statement
16:41:09,307 DEBUG Loader:239 - total objects hydrated: 1
16:41:09,307 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:09,307 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:09,307 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:09,307 DEBUG IteratorImpl:79 - exhausted results
16:41:09,307 DEBUG IteratorImpl:67 - closing iterator
16:41:09,347 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:09,347 DEBUG BatcherImpl:261 - closing statement
16:41:09,347 DEBUG IteratorImpl:120 - returning current results
com.Profile@1742700
Revision: 1
16:41:10,349 DEBUG SessionImpl:573 - closing session
16:41:10,349 DEBUG SessionImpl:3332 - disconnecting session
16:41:10,349 DEBUG JDBCExceptionReporter:18 - SQL Warning
java.sql.SQLWarning: [interclient] Specified dialect not supported: The SQL Dialect has been changed to 3.
See API reference for exception interbase.interclient.SQLDialectException
at interbase.interclient.RecvMessage.createSQLWarning(RecvMessage.java:709)
at interbase.interclient.RecvMessage.makeSQLWarning(RecvMessage.java:578)
at interbase.interclient.RecvMessage.get_WARNINGS(RecvMessage.java:534)
at interbase.interclient.Connection.remote_ATTACH_DATABASE(Connection.java:409)
at interbase.interclient.Connection.connect(Connection.java:331)
at interbase.interclient.Connection.<init>(Connection.java:285)
at interbase.interclient.Driver.connect(Driver.java:204)
at java.sql.DriverManager.getConnection(DriverManager.java:512)
at java.sql.DriverManager.getConnection(DriverManager.java:140)
at net.sf.hibernate.connection.DriverManagerConnectionProvider.getConnection(DriverManagerConnectionProvider.java:101)
at net.sf.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:72)
at net.sf.hibernate.cfg.Configuration.buildSettings(Configuration.java:1132)
at net.sf.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:766)
at com.Test.testHibernateNamedQueryWithFactoryReuse(Test.java:32)
at com.Test.main(Test.java:19)
16:41:10,349 WARN JDBCExceptionReporter:20 - SQL Warning: 130, SQLState: 01JB0
16:41:10,349 WARN JDBCExceptionReporter:28 - [interclient] Specified dialect not supported: The SQL Dialect has been changed to 3.
See API reference for exception interbase.interclient.SQLDialectException
16:41:10,349 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
16:41:10,349 DEBUG SessionImpl:585 - transaction completion
16:41:10,349 DEBUG SessionImpl:555 - opened session
16:41:10,349 DEBUG SessionImpl:1587 - iterate:
select p from Profile as p where p.name = :name

16:41:10,349 DEBUG QueryParameters:109 - named parameters: {name=foo}
16:41:10,349 DEBUG SessionImpl:2242 - flushing session
16:41:10,349 DEBUG SessionImpl:2435 - Flushing entities and processing referenced collections
16:41:10,349 DEBUG SessionImpl:2776 - Processing unreferenced collections
16:41:10,349 DEBUG SessionImpl:2790 - Scheduling collection removes/(re)creates/updates
16:41:10,359 DEBUG SessionImpl:2266 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
16:41:10,359 DEBUG SessionImpl:2271 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:41:10,359 DEBUG SessionImpl:1814 - Dont need to execute flush
16:41:10,359 DEBUG QueryTranslator:199 - HQL:
select p from com.Profile as p where p.name = :name

16:41:10,359 DEBUG QueryTranslator:200 - SQL: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:10,359 DEBUG BatcherImpl:196 - about to open: 0 open PreparedStatements, 0 open ResultSets
16:41:10,359 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
16:41:10,359 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
16:41:10,359 DEBUG SQL:237 - select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
16:41:10,359 DEBUG BatcherImpl:241 - preparing statement
16:41:10,359 DEBUG StringType:46 - binding 'foo' to parameter: 1
16:41:10,369 DEBUG IteratorImpl:83 - retrieving next results
16:41:10,369 DEBUG IntegerType:68 - returning '1' as column: x0_0_
16:41:10,369 DEBUG SessionImpl:1982 - loading [com.Profile#1]
16:41:10,369 DEBUG SessionImpl:2079 - attempting to resolve [com.Profile#1]
16:41:10,369 DEBUG SessionImpl:2112 - object not resolved in any cache [com.Profile#1]
16:41:10,369 DEBUG EntityPersister:416 - Materializing entity: [com.Profile#1]
16:41:10,369 DEBUG BatcherImpl:196 - about to open: 1 open PreparedStatements, 1 open ResultSets
16:41:10,369 DEBUG SQL:237 - select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
16:41:10,369 DEBUG BatcherImpl:241 - preparing statement
16:41:10,379 DEBUG IntegerType:46 - binding '1' to parameter: 1
16:41:10,379 DEBUG Loader:197 - processing result set
16:41:10,379 DEBUG Loader:405 - result row: 1
16:41:10,379 DEBUG Loader:536 - Initializing object from ResultSet: 1
16:41:10,379 DEBUG Loader:605 - Hydrating entity: com.Profile#1
16:41:10,379 DEBUG StringType:68 - returning 'foo' as column: NAME0_
16:41:10,379 DEBUG IntegerType:68 - returning '1' as column: REVISION0_
16:41:10,379 DEBUG Loader:226 - done processing result set (1 rows)
16:41:10,379 DEBUG BatcherImpl:203 - done closing: 1 open PreparedStatements, 1 open ResultSets
16:41:10,389 DEBUG BatcherImpl:261 - closing statement
16:41:10,389 DEBUG Loader:239 - total objects hydrated: 1
16:41:10,389 DEBUG SessionImpl:2198 - resolving associations for [com.Profile#1]
16:41:10,389 DEBUG SessionImpl:2222 - done materializing entity [com.Profile#1]
16:41:10,389 DEBUG SessionImpl:3112 - initializing non-lazy collections
16:41:10,389 DEBUG IteratorImpl:79 - exhausted results
16:41:10,389 DEBUG IteratorImpl:67 - closing iterator
16:41:10,389 DEBUG BatcherImpl:203 - done closing: 0 open PreparedStatements, 0 open ResultSets
16:41:10,389 DEBUG BatcherImpl:261 - closing statement
16:41:10,389 DEBUG IteratorImpl:120 - returning current results
com.Profile@89cc5e
Revision: 1


Top
 Profile  
 
steve
 Post subject:
PostPosted: Mon Jun 28, 2004 8:25 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
I suggest you strip this down to a simple self-contained main(). Have the test 1) create a Profile, 2) run the query, 3) open a jdbc connection and manually perform the update, 4) execute the query again.

I have apps doing integration work against the tables underneath Hibernate (Hibernate knows nothing of these manual updates) and this works fine.
Top
 Profile  
 
sean
 Post subject:
PostPosted: Mon Jun 28, 2004 8:30 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Steve, thanks for the confirmation that this absolutely should work as configured...I'll whip up a quick test as you detailed, all in process with distinct JDBC connections, and let you know what we find...
Top
 Profile  
 
sean
 Post subject:
PostPosted: Mon Jun 28, 2004 9:20 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Well, good news and bad news (for us anyway)...the single process test works fine...

Code:
Hibernate: select gen_id( hibernate_sequence, 1 ) from RDB$DATABASE
Hibernate: insert into PROFILE (NAME, REVISION, ID) values (?, ?, ?)
com.Profile@4fc156
Created Profile Revision: 1
08:56:06,334  WARN JDBCExceptionReporter:20 - SQL Warning: 130, SQLState: 01JB0
08:56:06,334  WARN JDBCExceptionReporter:28 - [interclient] Specified dialect not supported: The SQL Dialect has been changed to 3.
See API reference for exception interbase.interclient.SQLDialectException
Updated Profile Revision via JDBC to: 2
Hibernate: select profile0_.ID as x0_0_ from PROFILE profile0_ where (profile0_.NAME=? )
Hibernate: select profile0_.ID as ID0_, profile0_.NAME as NAME0_, profile0_.REVISION as REVISION0_ from PROFILE profile0_ where profile0_.ID=?
com.Profile@9b42e6
Loaded Profile Revision: 2


Unfortunately, a similar test (literally copying the same code into two classes and running them at the command line) over multiple processes still doesn't work...which suggest that Interclient is the culprit and further explains why trashing the SessionFactory (and thus all the DB connections) appears to clear out the stale data...

I haven't seen much traffic here regarding Interbase/Interclient, but has anyone else managed to get a multi process Interbase system working with Hibernate, with or without encountering this problem?
Top
 Profile  
 
steve
 Post subject:
PostPosted: Mon Jun 28, 2004 9:31 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Well that would lead me to believe its either a problem with 1) transactions or 2) your db/jdbc-driver caching data.

I have never used Interbase, so I could not say for sure.
Top
 Profile  
 
sean
 Post subject:
PostPosted: Mon Jun 28, 2004 9:36 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
Yeah, I'm confident the transaction handling is sound, but I agree with your assessment that Firebird Interclient 2.01 appears to be caching...

This actually confirms what I saw but simply couldn't believe in my prior runs in the debugger...that the content of the result set returned from the driver to Hibernate actually contains stale data...

From the Hibernate perspective, can anyone recommend a better driver for Interbase 6.0.1, or some additional configuration I may be able to specify to disable this caching?...I've searched with very little success...
Top
 Profile  
 
baliukas
 Post subject:
PostPosted: Mon Jun 28, 2004 9:46 am 
CGLIB Developer
CGLIB Developer

Joined: Thu Aug 28, 2003 1:44 pm
Posts: 1217
Location: Vilnius, Lithuania
Commit transaction before to "close", you return uncommited transaction to pool, if transaction isolation level is "serializable" then you will see random data (it will depend on connection you will get from pool).
Top
 Profile  
 
sean
 Post subject:
PostPosted: Mon Jun 28, 2004 10:01 am 
Newbie

Joined: Thu Jun 24, 2004 9:10 pm
Posts: 15
I understand the need to commit transactions and I'm doing so...as discussed, the committed data has been confirmed by additional processes and sql tools...you'll also notice in my example that the connection pool is of size 1, so the data state might be uncommitted but it will not be "random"...

Both the single/split process test and my run in the debugger appear to confirm that its the driver returning stale data...if the read process is restarted (without any other commit actions in any process) it picks up the fresh data from the database...if the read process SessionFactory (and underlying connection pool) is destroyed and recreated it then picks up the fresh data from the database...

Can anyone confirm the Interclient driver (or Interserver process) is performing some kind of caching?
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 2
  [ 25 posts ]  Go to page 1, 2  Next

Board index » Hibernate & Java Persistence » Hibernate Users

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:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.