• Bug
  • Status: Closed
  • 2 Major
  • Resolution: Not a Bug
  • drb
  • Reporter: tgautier
  • February 27, 2010
  • 0
  • Watchers: 1
  • March 19, 2010
  • March 09, 2010

Description

I don’t know why but the Timestamps cache doesn’t seem to accept updates. If you’ll look at the attached screenshot, you’ll see that the misses is 18, yet it’s size is 0.

My environment: Sprint PetClinic performing the “find all vets” query.

Hibernate/Spring config:

true net.sf.ehcache.hibernate.EhCacheRegionFactory

I didn’t see this behavior with Terracotta 3.2.0, you can see two strange things in the attached screenshot: 1) There are misses recorded in the cache (though I cannot tell for certain that these misses are the TimestampCache it appears to be the culprit since it is the only cache with misses) 2) The size never increases on this cache indicating no puts are ever attempted? I can’t figure out why that would be the case.

At first I was just using default cache settings:

But then I added:

There was no effect when adding the second setting.

Comments

Taylor Gautier 2010-02-27

I’ve tried with the older cache factory just to see if it made any difference,

            <prop key="hibernate.cache.region.factory_class">net.sf.ehcache.hibernate.EhCacheRegionFactory</prop>

This did not make any difference, the symptoms are the same.

Fiona OShea 2010-03-02

can you take a quick look at this and let us know what you think it would take to fix?

Chris Dennis 2010-03-02

I did some playing around with the Spring PetClinic example app using Ehcache as a second level cache, and I think the behavior that Taylor is seeing is correct, in that it is the behavior that one should expect from Hibernate in this situation. I shall explain in more detail by stepping through what Hibernate is doing.

We start off with a fresh setup, the caches are all empty.

  1. We click “Display all veterinarians” and trigger a query for Vet objects (which I have modified in the source to set as cacheable). This results in: StandardQueryCache: Hits: 0, Misses: 1 (since we checked to see if the query was cached), Puts: 1 (since we cached the result of the query) Specialty: Misses: 3, Puts: 3 (a miss and a put for each speciality) Vet: Misses: 6, Puts: 6 (a miss and a put for each Vet)

Since the query did not hit the query cache there was no need to check the timestamps cache (hence there are no hits on it). Since the query did not mutate any of the database ‘spaces’ the update timestamps cache was not invalidated (and hence nothing was put into it).

  1. We refresh the page and trigger the query again. This results in (delta’s only): StandardQueryCache: Hits: 1 (we hit the cached query this time) UpdateTimestampsCache: Misses: 1 (since we hit the cached query we have to check to see if anyone mutated the Vet table - as this could make the cached query stale and we would be forced to discard it - no one has so its a miss) Specialty: Hits: 3 (everything hit the cache) Vet: Hits: 6 (everything hit the cache)

Subsequent queries will just repeat step 2. In order to force some data into the UpdateTimestampsCache lets actually do some mutative work on the db:

  1. Navigate to “Find Owner -> Add Owner” and create a new Owner object which will be persisted to the database: UpdateTimestampsCache: Puts: 2, Updates: 2 (pre-invalidate and invalidate for both the Owner entity, and the pets collection) Owner: Misses: 2, Puts: 1 (add the new Owner into the cache)

  2. Now search for the newly created Owner: StandardQueryCache: Misses: 1, Puts: 1 (cache the query) UpdateTimestampsCache: nothing (we didn’t hit the query cache) Owner: Hits: 2, (seems that Hibernate is hitting the cache twice here for some reason)

  3. Searching again causes the query cache (and the update timestamps cache - since it has an invalidation time for the Owner table) to be hit: StandardQueryCache: Hits: 1 UpdateTimestampsCache: Hits: 1 Owner: Hits: 2

I’m not sure why this didn’t happen for Taylor when using the TC 3.2 caching, (it may be Hibernate setup related) - but the UpdateTimestampsCache is definitely accepting updates.

One further thing to note here is that I don’t believe Hibernate ever bothers to update the hit, miss or put counts for the UpdateTimestampsCache. This means the Hibernate version of the caching panel in the dev-console will never show anything other than 0 for these statistics (numbers in the Ehcache panel will of course be correct).

Chris

Fiona OShea 2010-03-03

Assigning back to DRB. I’m guessing we close this as “not our bug”. Do we need to doc anything?

Chris Dennis 2010-03-03

That sounds fair to me. We might want to doc the effect of EHC-634, but that would go under the other JIRA item. Anything else we could doc would just be documenting Hibernate behavior which I hate doing since its not our code, and we won’t know if subsequent code changes invalidate behavior (especially since this is behavior that is almost certainly not captured in any spec document).

Taylor Gautier 2010-03-07

I just confirmed what Chris said,

“One further thing to note here is that I don’t believe Hibernate ever bothers to update the hit, miss or put counts for the UpdateTimestampsCache. This means the Hibernate version of the caching panel in the dev-console will never show anything other than 0 for these statistics (numbers in the Ehcache panel will of course be correct). “

I am seeing misses reported in Ehcache panel but not in second level cache panel as Chris describes.

After I add an owner I start getting hits on the timestamp cache.