Document Ehcache Performance degradation when the default cache is used

Description

When query cache is enabled, Hibernate constantly updates timestamps cache default-update-timestamps-region.data through ehcache even though a cacheable hint was not specified in the query. This causes frequent writes to the disk causing slowness under heavy load.

According to https://vladmihalcea.com/hibernate-query-cache-n-plus-1-issue/,

Although we have enabled the Query Cache, it does not automatically apply to any query and we need to explicitly tell Hibernate which queries are to be cached.

Attached is a sample maven project where this is reproducible. Please extract the project, open in an IDE and run the test which will show the following

11:52:19.594 [main] DEBUG org.hibernate.cache.internal.TimestampsCacheEnabledImpl - Invalidating space [Attribute], timestamp: 6624827554177024
11:52:19.595 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
11:52:19.599 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on heap
11:52:19.599 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on disk
11:52:19.599 [main] DEBUG org.hibernate.cache.internal.TimestampsCacheEnabledImpl - Invalidating space [Dorm], timestamp: 6624827554177024
11:52:19.599 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
11:52:19.600 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
11:52:19.600 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
11:52:19.600 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on heap
11:52:19.600 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on disk
11:52:19.600 [main] DEBUG org.hibernate.cache.internal.TimestampsCacheEnabledImpl - Invalidating space [Purpose], timestamp: 6624827554177024
11:52:19.600 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
11:52:19.600 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
11:52:19.600 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
11:52:19.601 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on heap
11:52:19.601 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on disk
11:52:19.601 [main] DEBUG org.hibernate.cache.internal.TimestampsCacheEnabledImpl - Invalidating space [Student], timestamp: 6624827554177024
11:52:19.602 [main] DEBUG net.sf.ehcache.store.disk.Segment - put added 0 on heap
11:52:19.602 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
11:52:19.602 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk
11:52:19.602 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on heap
11:52:19.602 [main] DEBUG net.sf.ehcache.store.disk.Segment - put updated, deleted 0 on disk
11:52:19.602 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault removed 0 from heap
11:52:19.602 [default-update-timestamps-region.data] DEBUG net.sf.ehcache.store.disk.Segment - fault added 0 on disk

Attachments

1
  • 02 Apr 2021, 07:17 PM

Activity

Show:

Michał S September 20, 2022 at 12:55 PM
Edited

So I finally got down to the cause of the problem.

This is the default configuration for ehcache 2.10 (from ehcache.xml)

<defaultCache maxElementsInMemory="10000" eternal="false" timeToIdleSeconds="120" timeToLiveSeconds="120" maxElementsOnDisk="10000000" diskExpiryThreadIntervalSeconds="120" memoryStoreEvictionPolicy="LRU"> <persistence strategy="localTempSwap"/> </defaultCache>

As you can see, they have enabled disk persistence by default - and this is the crux of the problem. Of course, as Christian noted, there are warnings.

I think it would be good to at least warn the users of this behavior in the docs. Ideally some examples should be provided.

Thanks again Christian for good pointers.

Christian Beikov September 20, 2022 at 11:55 AM
Edited

Do I understand correctly that the timestamps cache will be invalidated whether query is cached or not?

Yes, obviously every mutation needs to invalidate certain query cache regions, which works through the timestamps cache.

I guess that your default cache configuration might play a role here. I don’t know much about EHCache, but maybe answers like this can help: https://stackoverflow.com/questions/67993442/hhh90001006-missing-cachedefault-update-timestamps-region-was-created-on-the

Andrea Boriero September 20, 2022 at 11:45 AM

Hi ,

can you please provide a reproducer so we can better investigate the issue? Thanks

Michał S September 20, 2022 at 11:11 AM
Edited

Thanks for the clarification Christian. It turns out we are using default ehcache configuration which, I guess, could be the problem. We have changed nothing for Hibernate upgrade, and we kept ehcache at 2.x. Maybe it’s how Hibernate configures ehcache by default was the issue.

I think there is still an issue of default ehcache settings in ehcache-failsafe.xml

 

<defaultCache maxElementsInMemory="10000" eternal="false" timeToIdleSeconds="120" timeToLiveSeconds="120" maxElementsOnDisk="10000000" diskExpiryThreadIntervalSeconds="120" memoryStoreEvictionPolicy="LRU"> <persistence strategy="localTempSwap"/> </defaultCache>

I suppose this could be not enough for the timestamps cache, and hence the problem?

Do I understand correctly that the timestamps cache will be invalidated whether query is cached or not?

Anyway thanks for looking into the issue.

Christian Beikov September 20, 2022 at 11:00 AM

Since the very beginnings of Hibernate the timestamps cache received invalidations whenever a query is executed. See https://github.com/hibernate/hibernate-orm/blob/d8d6d82e30960e0c255950eaf875ad48831b12b0/code/core/src/main/java/org/hibernate/engine/ActionQueue.java#L176

Your frequent writes to disk are a probably due to a misconfiguration. The timestamps cache should not be configured to store on disk but should stay in-memory.

Fixed
Pinned fields
Click on the next to a field label to start pinning.

Details

Assignee

Andrea Boriero

Reporter

Fix versions

Affects versions

Priority

Created April 2, 2021 at 7:18 PM
Updated October 28, 2022 at 12:09 PM
Resolved October 27, 2022 at 3:11 PM