1 2 Previous Next 22 Replies Latest reply on Apr 6, 2009 1:06 PM by Brian Stansberry

    JPA/Hibernate JBC usage

    Ignacio Alvarez Newbie

      Hi all,

      please help me in understanding how Hibernate uses the second level cache through this test case I'm running:
      - 2 threads start at the same time.
      - Both threads are reading for three consecutive times an overlapping subset of Entity Beans by means of an element manager named query.
      - I see how the 2nd level cache is updated as soon as the first query is executed.

      But, checking the cache statistics I don't see any reads on the cache (read/writes ratio is 0.0). Why is this happening this way?
      Are there any traces I can enable to be sure JBC is being read by the queries I execute?.

      Thanks a lot!

        • 1. Re: JPA/Hibernate JBC usage
          Ignacio Alvarez Newbie

          I'm gonna answer my own question but I still need clarification:

          1.- Entity caching is done by configuring

          <property name="hibernate.cache.use_query_cache" value="true"/>

          in persistence.xml. The cache will start showing up entities, but entities will never be accessed from the cache (this is the point that i need to clarify).

          2.- If besides the above, the entity is configured with the HINT
          @QueryHint(name="org.hibernate.cacheable",value="true")
          , then queries will also be cached, and if a query is repeated, results will be retrieved from cached.

          It seems caching entities don't make any sense if query caching is not enabled. Is it that way?

          Thanks a lot !!

          • 2. Re: JPA/Hibernate JBC usage
            Brian Stansberry Master

            For a discussion of the relevant concepts and configurations, please see http://www.jboss.org/jbossclustering/docs/hibernate-jbosscache-guide-3.pdf.

            enables query result set caching, where the cache key is the query string + parameter values and the cache value is the set of entity PKs that match the query result. It does *not* enable caching of the entities themselves, for which you must specify

            Enabling entity caching and not query result set caching makes perfect sense, since Hibernate will check the cache first any time it needs to find an entity by PK.

            • 3. Re: JPA/Hibernate JBC usage
              Brian Stansberry Master

              Geez, after 1 million posts I forget the "code" button:

              <property name="hibernate.cache.use_query_cache" value="true"/>


              enables query result set caching.

              <property name="hibernate.cache.use_second_level_cache" value="true"/>


              enables entity and collection caching.

              • 4. Re: JPA/Hibernate JBC usage
                Ignacio Alvarez Newbie

                Thanks Brian,

                I'm testing with these two properties in the persistence.xml file.
                Even if use_query_cache is set to true, you need to set @QueryHint to see query results in the cache, though, yes, entities are cached.

                Anyway, the key point I was missing is the PK. Entities are cached and will also be retrieved from the cache when searched by PK.

                However, still confusing the behaviour of the statistics, since cache hits is always zero and so it is Hit/Miss ratio. Cache misses seems to be working fine.

                • 5. Re: JPA/Hibernate JBC usage
                  Brian Stansberry Master

                  Are you talking about the Hibernate SecondLevelCacheStatistics or the stats exposed by JBoss Cache?

                  • 6. Re: JPA/Hibernate JBC usage
                    Ignacio Alvarez Newbie

                    I guess they are the stats exposed by JBC. I access them through the jmx console, jboss.cache, and then the Cache Mgmt Interceptor of the cache I'm using.

                    I didn't even know of the existence of Hibernate statistics.

                    Anyway, Brian, I retested it and statistics seem to be working fine. I tested several times to be sure. I don't really know what test case I executed that I did not see hits in the cache. Forget about it.

                    Thanks again.

                    • 7. Re: JPA/Hibernate JBC usage
                      Ignacio Alvarez Newbie

                      Ooops I forgot another couple of questions:

                      - I'm testing the cache with PESSIMISTIC and both RR and RC.
                      - I understood from Manik that RC does not make any sense since hibernate session provides RR.
                      - But according to the document you pointed me to (hibernate-jbc), "pessimistic locking with REPEATABLE_READ will cause a write to block if there is a concurrent transaction which holds a read lock, till the read transaction commits".

                      I tested the following which leads me to a different interpretation.
                      - T1 and T2 reads an entity which has been previously cached. T2 starts slightly after T1.
                      - T1 then just waits ..... and T2 modifies a field of the read entity and commits (I see the cache and db updated).
                      - Then after a while T1 prints the same field T2 modified, and commits.

                      The two reads of T1 reports the same value (this is consistent with RR policy) but I don't see T2 blocking till T1 commits, which according to the document should be the case if OPTIMISTIC is used.

                      I'm sure I'm missing something "again" ;-) .

                      • 8. Re: JPA/Hibernate JBC usage
                        Brian Stansberry Master

                        Are you certain the entity is in the cache when T1 reads it? If not there's no read lock in the cache to prevent the T2 write.

                        • 9. Re: JPA/Hibernate JBC usage
                          Ignacio Alvarez Newbie

                          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?

                          • 10. Re: JPA/Hibernate JBC usage
                            Brian Stansberry Master

                            How is TX1 reading the entity? Via an EntityManager.find() or are you using a query that amounts to the same thing?

                            The logging like this:

                            | 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.


                            tells me Hibernate is trying to cache an entity that is already cached. It would only do that if it didn't try to read the cache in the first place. So I'm trying to understand why it didn't read the cache. (The non-read of the cache by TX1 is why the TX2 write doesn't block on a read lock.)

                            • 11. Re: JPA/Hibernate JBC usage
                              Ignacio Alvarez Newbie

                              1- Both Tx1 and Tx2 are reading the entity via the EntityManager.find().
                              2- I use a named query in another transaction which I execute before Tx1 and Tx2 to preload the cache with some entities. One of them would be read by Tx1 and Tx2.
                              3- The CCustomerInventory entity is a collection of the CCustomer entity which is read by Tx1 and Tx2, and it is in the cache because of 2.
                              4- What I understood from navigating the traces is that collections are always read from DB, considering I have defined "fetch=FetchType.EAGER" in the OneToMany relationship between Customers and Customer Inventories.
                              5- Bear in mind cache statistics are indeed showing up the EntityManager.find() is reading the CCustomer from the cache.

                              • 12. Re: JPA/Hibernate JBC usage
                                Brian Stansberry Master

                                If you run TX1 and TX2 with org.jboss.cache logging at TRACE it should shed some light on this.

                                • 13. Re: JPA/Hibernate JBC usage
                                  Ignacio Alvarez Newbie

                                  I've already done it.

                                  I'm sending you an e-mail with the traces.
                                  It would be great if you can post the answer here !!!

                                  Thanks a lot Brian !!

                                  • 14. Re: JPA/Hibernate JBC usage
                                    Ignacio Alvarez Newbie

                                    Brian,

                                    hibernate doc does not say anything about it, but is there a way to configure collections to not be read again and again from db ? Well , this is my understanding from reading the traces I sent you.

                                    Of course I mean, if no changes were applied to neither the entity nor the collection, and given that the first read already inserted the collection in the cache.

                                    1 2 Previous Next