[jboss-user] [JBoss Cache: Core Edition] - Re: JPA/Hibernate JBC usage

Wed Apr 1 13:32:06 EDT 2009

These are my checkings in order to be sure the entity is in the cache:

- Before T1 starts, I check the cache in the jmx console and the entity is there.
- After T1 and T2 finish their execution, I check both the CacheMgmtInterceptor statistics (2 hits, one find per transaction), which looks fine and also the traces. Below you can see them, from before T1 reads to after it is done. T1 reads a Customer entity which has some CustomerInventory entities (collection). I only see the select to retrieve the collection but not the entity itself.

2009-04-01 13:51:50,468 INFO  [STDOUT] (WorkerThread#0[127.0.0.1:4967]) TX: t1 starts
  | 2009-04-01 13:51:50,468 INFO  [STDOUT] (WorkerThread#0[127.0.0.1:4967]) TX: t1 reading Customer 1137 from Cache
  | 2009-04-01 13:51:50,468 DEBUG [org.hibernate.impl.SessionImpl] (WorkerThread#0[127.0.0.1:4967]) opened session at timestamp: 12385867104
  | 2009-04-01 13:51:50,468 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (WorkerThread#0[127.0.0.1:4967]) Looking for a JTA transaction to join
  | 2009-04-01 13:51:50,468 DEBUG [org.hibernate.jdbc.JDBCContext] (WorkerThread#0[127.0.0.1:4967]) successfully registered Synchronization
  | 2009-04-01 13:51:50,468 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (WorkerThread#0[127.0.0.1:4967]) Looking for a JTA transaction to join
  | 2009-04-01 13:51:50,468 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (WorkerThread#0[127.0.0.1:4967]) Transaction already joined
  | 2009-04-01 13:51:50,484 DEBUG [org.hibernate.engine.StatefulPersistenceContext] (WorkerThread#0[127.0.0.1:4967]) initializing non-lazy collections
  | 2009-04-01 13:51:50,484 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) loading collection: [org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory#1137]
  | 2009-04-01 13:51:50,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] (WorkerThread#0[127.0.0.1:4967]) about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
  | 2009-04-01 13:51:50,484 DEBUG [org.hibernate.jdbc.ConnectionManager] (WorkerThread#0[127.0.0.1:4967]) opening JDBC connection
  | 2009-04-01 13:51:50,484 DEBUG [org.hibernate.SQL] (WorkerThread#0[127.0.0.1:4967]) select customerin0_.ci_customerid as ci5_1_, customerin0_.ci_id as ci1_1_, customerin0_.ci_id as ci1_4_0_, customerin0_.ci_itemid as ci2_4_0_, customerin0_.ci_quantity as ci3_4_0_, customerin0_.ci_value as ci4_4_0_, customerin0_.ci_customerid as ci5_4_0_ from c_customerinventory customerin0_ where customerin0_.ci_customerid=?
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.jdbc.AbstractBatcher] (WorkerThread#0[127.0.0.1:4967]) about to open ResultSet (open ResultSets: 0, globally: 0)
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) result set contains (possibly empty) collection: [org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory#1137]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) result row: EntityKey[org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56510]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) found row of collection: [org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory#1137]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) result row: EntityKey[org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56525]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) found row of collection: [org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory#1137]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.jdbc.AbstractBatcher] (WorkerThread#0[127.0.0.1:4967]) about to close ResultSet (open ResultSets: 1, globally: 1)
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.jdbc.AbstractBatcher] (WorkerThread#0[127.0.0.1:4967]) about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.jdbc.ConnectionManager] (WorkerThread#0[127.0.0.1:4967]) aggressively releasing JDBC connection
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.jdbc.ConnectionManager] (WorkerThread#0[127.0.0.1:4967]) releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) resolving associations for [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56510]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) adding entity to second-level cache: [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56510]
  | 2009-04-01 13:51:50,515 DEBUG [org.jboss.cache.invocation.CacheInvocationDelegate] (WorkerThread#0[127.0.0.1:4967]) putForExternalRead() called with Fqn /persistence.unit:unitName=SPECjAppServer.ear/corp.jar#corp-persistence/org/spec/jappserver/corp/customerinventoryent/ejb/CCustomerInventory/ENTITY/org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56510 and this node already exists.  This method is hence a no op.
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) done materializing entity [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56510]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) resolving associations for [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56525]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) adding entity to second-level cache: [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56525]
  | 2009-04-01 13:51:50,515 DEBUG [org.jboss.cache.invocation.CacheInvocationDelegate] (WorkerThread#0[127.0.0.1:4967]) putForExternalRead() called with Fqn /persistence.unit:unitName=SPECjAppServer.ear/corp.jar#corp-persistence/org/spec/jappserver/corp/customerinventoryent/ejb/CCustomerInventory/ENTITY/org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56525 and this node already exists.  This method is hence a no op.
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.TwoPhaseLoad] (WorkerThread#0[127.0.0.1:4967]) done materializing entity [org.spec.jappserver.corp.customerinventoryent.ejb.CCustomerInventory#56525]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] (WorkerThread#0[127.0.0.1:4967]) 1 collections were found in result set for role: org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] (WorkerThread#0[127.0.0.1:4967]) collection fully initialized: [org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory#1137]
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] (WorkerThread#0[127.0.0.1:4967]) 1 collections initialized for role: org.spec.jappserver.corp.customerent.ejb.CCustomer.customerInventory
  | 2009-04-01 13:51:50,515 DEBUG [org.hibernate.loader.Loader] (WorkerThread#0[127.0.0.1:4967]) done loading collection
  | 2009-04-01 13:51:50,515 INFO  [STDOUT] (WorkerThread#0[127.0.0.1:4967]) TX: t1 doing other things ...

What you think?

View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4222744#4222744

Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4222744