Heap leak as JCache provider?

[Steve Goldsmith]

I'm using Hazelcast 3.6.4 as a JCache provider under TomEE 7. Using MAT I see "One instance of "com.hazelcast.cache.impl.CacheService" loaded by "java.net.URLClassLoader @ 0x805b5050" occupies 162,660,400 (71.07%) bytes". The memory is accumulated in one instance of "com.hazelcast.cache.impl.CachePartitionSegment[]" loaded by "java.net.URLClassLoader @ 0x805b5050".

Using javax.cache MBean I can see CacheRemovals is 0, but CacheEvictions is 207,315. Is this normal behavior (not freeing the memory unless it's needed perhaps)? I'm have 2G reserved for heap and the server is using about 250 MB on the low end. It has doubled in size over 5 or 6 days and I only have one item that caches for 24 hours with a 30% hit ratio.

[Steve Goldsmith]

I'm working this over on the TomEE user forum as well http://tomee-openejb.979440.n4.nabble.com/Heap-leak-as-JCache-provider-td4679471.html

[sgj...@gmail.com]

I'm using Hazelcast 3.6.4 as a JCache provider under TomEE 7. Using MAT I see One instance of "com.hazelcast.cache.impl.CacheService" loaded by "java.net.URLClassLoader @ 0x805b5050" occupies 162,660,400 (71.07%) bytes. The memory is accumulated in one instance of "com.hazelcast.cache.impl.CachePartitionSegment[]" loaded by "java.net.URLClassLoader @ 0x805b5050".

[vass...@hazelcast.com]

Hi Steve,

the CacheRemovals statistic reports " The total number of removals from the cache. This does not include evictions, where the cache itself initiates the removal to make space." [1], so it is not related to evictions, rather it counts explicit removals with cache.remove or cache.getAndRemove. 

On the classloader issue, would you be able to provide a very simple app with your cache singleton & hazelcast config to deploy on a TomEE server and observe the behavior?

Cheers!

Vassilis

[1] https://github.com/jsr107/jsr107spec/blob/master/src/main/java/javax/cache/management/CacheStatisticsMXBean.java#L134-L140

[Steve Goldsmith]

Take a look at https://github.com/sgjava/jcache-tomee which basically has the same project structure. The actual app is a proxy for millions of cable set top boxes, so it's not easy to strip down and provide an example. I did drill down into the dominator tree in MAT and can see the actual com.hazelcast.cache.impl.record.CacheDataRecord.expirationTime. I tried using cachingProvider = Caching.getCachingProvider(Thread.currentThread().getContextClassLoader()) to make sure it wasn't a TCCL issue either.

[Vassilis Bekiaris]

Thanks Steve,

I deployed the WAR from the github project on a local TomEE 7.0.1 server, then POSTed 10,000 UserDTO objects and obtained a heap dump. Unfortunately I cannot reproduce the behavior you observe: CacheService and CachePartitionSegment[] are loaded by an instance of "org.apache.tomee.catalina.TomEEWebappClassLoader @ 0x6c175a2e0" so I can only assume that there is something different in the way hazelcast is started in your actual webapp in which you observe CacheService being loaded by a java.net.URLClassLoader.

On 26/7/16 16:37 , Steve Goldsmith wrote:

Take a look at https://github.com/sgjava/jcache-tomee which basically has the same project structure. The actual app is a proxy for millions of cable set top boxes, so it's not easy to strip down and provide an example. I did drill down into the dominator tree in MAT and can see the actual com.hazelcast.cache.impl.record.CacheDataRecord.expirationTime. I tried using cachingProvider = Caching.getCachingProvider(Thread.currentThread().getContextClassLoader())to make sure it wasn't a TCCL issue either.

On Tuesday, July 26, 2016 at 4:26:37 AM UTC-4, vass...@hazelcast.com wrote:

Hi Steve,

the CacheRemovals statistic reports " The total number of removals from the cache. This does not include evictions, where the cache itself initiates the removal to make space." [1], so it is not related to evictions, rather it counts explicit removals with cache.remove or cache.getAndRemove. 

On the classloader issue, would you be able to provide a very simple app with your cache singleton & hazelcast config to deploy on a TomEE server and observe the behavior?

Cheers!

Vassilis

[1] https://github.com/jsr107/jsr107spec/blob/master/src/main/java/javax/cache/management/CacheStatisticsMXBean.java#L134-L140

On Tuesday, July 26, 2016 at 9:52:46 AM UTC+3, Steve Goldsmith wrote:

I'm using Hazelcast 3.6.4 as a JCache provider under TomEE 7. Using MAT I see One instance of "com.hazelcast.cache.impl.CacheService" loaded by "java.net.URLClassLoader @ 0x805b5050" occupies 162,660,400 (71.07%) bytes. The memory is accumulated in one instance of "com.hazelcast.cache.impl.CachePartitionSegment[]" loaded by "java.net.URLClassLoader @ 0x805b5050".

Using javax.cache MBean I can see CacheRemovals is 0, but CacheEvictions is 207,315. Is this normal behavior (not freeing the memory unless it's needed perhaps)? I'm have 2G reserved for heap and the server is using about 250 MB on the low end. It has doubled in size over 5 or 6 days and I only have one item that caches for 24 hours with a 30% hit ratio.

--
You received this message because you are subscribed to the Google Groups "Hazelcast" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hazelcast+...@googlegroups.com.
To post to this group, send email to haze...@googlegroups.com.
Visit this group at https://groups.google.com/group/hazelcast.
To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/3f5b655a-1392-492e-9ded-405cbc8887e4%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Steve Goldsmith]

I'm using a distributed installation. Plus you'd need to cache 10K unique DTOs, not the same one? The class loader difference is the unit test container versus deployed TomEE runtime.

I am running a distributed configuration in production, so that's the only configuration difference. partitionCount is at 271, so that's not growing. In jvisualvm used heap is around 200 MB and heap size is 950 MB out of 2G max. I'll keep an eye on used heap right after GC and see if it grows. Used heap is what is important. I'll let the app run for a couple weeks and see what happens. It could be MAT is seeing the cache segments as leaks because they are long lived (I cache one item for 24 hours).

--
You received this message because you are subscribed to a topic in the Google Groups "Hazelcast" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/hazelcast/orRsbxZD_dQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to hazelcast+...@googlegroups.com.

To post to this group, send email to haze...@googlegroups.com.
Visit this group at https://groups.google.com/group/hazelcast.

To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/d4125133-03c7-daba-2c3c-60c7ddc43a5c%40gmail.com.

For more options, visit https://groups.google.com/d/optout.

--

Steven P. Goldsmith

[Vassilis Bekiaris]

Hi Steve,

Τη Τετάρτη, 27 Ιουλίου 2016 - 5:13:38 μ.μ. UTC+3, ο χρήστης Steve Goldsmith έγραψε:

I'm using a distributed installation. Plus you'd need to cache 10K unique DTOs, not the same one? The class loader difference is the unit test container versus deployed TomEE runtime.

 

Yes, in my test I created 10K unique UserDTO on two separate TomEE instances with the jcache-tomee webapp deployed. In this setup I observe Hazelcast CacheService and CachePartitionSegment[] are loaded by an instance of org.apache.tomee.catalina.TomEEWebappClassLoader in both TomEE instances.

I am running a distributed configuration in production, so that's the only configuration difference. partitionCount is at 271, so that's not growing. In jvisualvm used heap is around 200 MB and heap size is 950 MB out of 2G max. I'll keep an eye on used heap right after GC and see if it grows. Used heap is what is important. I'll let the app run for a couple weeks and see what happens. It could be MAT is seeing the cache segments as leaks because they are long lived (I cache one item for 24 hours).

I am not familiar with the kind of algorithm used in MAT to locate leak suspects but I think this is a false alarm. It observes my 10K objects map as a a leak suspect as well (see screenshot). Probably it has to do with a large chunk of heap being accessible from a single instance? (just guessing).

Best,

Vassilis

[Steve Goldsmith]

Yea, used heap is around 240 MB after 3 days, so it's growing slowly. It should stabilize after a week or two I'm hoping. The objects held for 24 hours are never removed, only evicted, so this could be the cause. Only time will tell. I'm hoping it's a false detection.

--

You received this message because you are subscribed to a topic in the Google Groups "Hazelcast" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/hazelcast/orRsbxZD_dQ/unsubscribe.
To unsubscribe from this group and all its topics, send an email to hazelcast+...@googlegroups.com.
To post to this group, send email to haze...@googlegroups.com.
Visit this group at https://groups.google.com/group/hazelcast.

To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/a4e50158-2e0c-4397-9557-7829aca4d7e3%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Steven P. Goldsmith

[vass...@hazelcast.com]

Thanks Steve,

please get back to this thread if you notice anything suspicious in the long run.

Cheers!
Vassilis

[Steve Goldsmith]

It's around 270MB used heap now at 8 days. I'll check it in another week and see if the slow climb continues. Then I'll do a heap dump and look at the contents to see if old cached items are still present. 30 MB in 5 days isn't crazy. I have 900K hits across 3 caches on one VM.

To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/33f2a73d-02aa-4dc6-8bb8-ad5aea6a5fbd%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Steven P. Goldsmith

[Steve Goldsmith]

OK, I found the issue. It's not evicting items from the cache, thus MAT thinks it's a leak (which it is in reality):

This is how I configure the cache:

cacheManager.createCache("header", new MutableConfiguration().setStoreByValue(false).setStatisticsEnabled(true).setManagementEnabled(true).setExpiryPolicyFactory(CreatedExpiryPolicy.factoryOf(new Duration(TimeUnit.MINUTES,config.getInt("headerExpireMin")))));

in my configuration I have:

    <!-- Header data cache expire in minutes -->
    <headerExpireMin>1440</headerExpireMin>

But after the items were created > 24 hours ago (1440 minutes) the evictions shows 0 in JMX.

[Steve Goldsmith]

I checked and I'm using <eviction-policy>NONE</eviction-policy>, so this might be the issue until it reaches <eviction-percentage>25</eviction-percentage>.

To unsubscribe from this group and all its topics, send an email to hazelcast+unsubscribe@googlegroups.com.

To post to this group, send email to haze...@googlegroups.com.
Visit this group at https://groups.google.com/group/hazelcast.

To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/33f2a73d-02aa-4dc6-8bb8-ad5aea6a5fbd%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

Steven P. Goldsmith

[Vassilis Bekiaris]

Hi Steve,

it is normal for evictions to be 0. Evictions are a mechanism for Hazelcast to reclaim memory based on a policy that has to do with the number of items in the cache or memory used (for example allow the cache to have 10.000 entries at most, once we get over that limit evict the less recently used entries) -- see http://docs.hazelcast.org/docs/3.6/manual/html-single/index.html#jcache-eviction for the full details (some eviction policies are only available in Hazelcast Enterprise).

Item expiry is a separate mechanism that limits the time duration for which cache entries are valid: an expired entry is not removed from memory at the time it is expired. Rather, it is removed from the cache store when touched (e.g. someone attempts to execute cache.get(key) or cache.contains(key) or another operation on that key but the entry is expired).

There is a point at which eviction & expiry intersect and this is the time during which eviction algorithm attempts to locate items for eviction: in this case, candidate entries for eviction are located according to the given eviction strategy. When an eviction candidate is expired, then this entry will be chosen for eviction. See here for eviction algorithm documentation http://docs.hazelcast.org/docs/3.6/manual/html-single/index.html#eviction-algorithm

That said, the local cache statistics interface (com.hazelcast.cache.CacheStatistics) does not provide the count of cache expiries performed; however it is available if you downcast to its member-side implementation com.hazelcast.cache.impl.CacheStatisticsImpl (WARNING: this is an implementation class and may change without warning; it looks valid for versions 3.5 through 3.7-EA but no guarantees). So the following code should give you the number of expiries in the local cache.

*** Ugly hack warning, this code relies on internal classes and may or may not work depending on your hazelcast version ***

cache.put("a", "b");
// should print expiries=0
System.out.println("Immediately get(a) = " + cache.get("a") + 
        ", expiries=" + ((CacheStatisticsImpl)cache.getLocalCacheStatistics()).getCacheExpiries());

// wait for entry to expire
Thread.sleep(120000);

// should print expiries=1
System.out.println("After 2 minutes get(a) = " + cache.get("a") + 
        ", expiries=" + ((CacheStatisticsImpl)cache.getLocalCacheStatistics()).getCacheExpiries());

To obtain metrics for the whole cluster, you need to get a cache reference from each member, unwrap it to ICache then aggregate on ((CacheStatisticsImpl)cache.getLocalCacheStatistics()). getCacheExpiries().

Cheers!

Vassilis

You received this message because you are subscribed to the Google Groups "Hazelcast" group.

To unsubscribe from this group and stop receiving emails from it, send an email to hazelcast+...@googlegroups.com.

To post to this group, send email to haze...@googlegroups.com.
Visit this group at https://groups.google.com/group/hazelcast.

To view this discussion on the web visit https://groups.google.com/d/msgid/hazelcast/b20667e8-9832-4313-b14a-0ecf3529837c%40googlegroups.com.