Cache hit logs?

[MiKey]

I have an environment setup with 3 caches using
ehcache-spring-annotations. When I enable debug for both
ehcache-spring-annotations and ehcache itself I was expecting to see
cache hit logs in my output, but at this point I do not. I DO see log
messages from Ehcache itself like:

[2010-10-25
15:57:49,002][net.sf.ehcache.store.MemoryStore][DEBUG]questionCacheCache: Cannot
remove entry as key -559951139 was not found

and I do see ehcache-spring-annotations intercepting the method calls
for cache in the logs:

[2010-10-25
15:57:49,003][com.googlecode.ehcache.annotations.interceptor.EhCacheInterceptor][DEBUG]Generated
key '1477021980' for invocation: ParameterFilteringMethodInvocation
[filteredArguments=[BPEvQfR0mGj8mfEbK-FnDPepF08],
methodInvocation=ReflectiveMethodInvocation: public abstract void
com.liveensure.core.DataAccessProxy.setQuestionsForUser(java.util.List,java.lang.String)
throws com.liveensure.dao.DAOException; target is of class
[com.liveensure.core.impl.DataAccessProxyImpl]]

So I have 2 questions really if allowed...

1) Would this indicate I am never getting cache hits? Do I need a
different config in ehcache to get cache hits in logs?

2) Does the ehcache log message tell me I have an issue in my
@TriggersRemove? I do have a key generator configured. It seems to me
this is a concerning log statement as to whether I may be thrashing in
cache somewhere where keys no longer exist for some reason...my load
test does not update any data at all and uses the same data request
thousands of times so I would think everything after the first run would
give me cache hits.

Thanks for any insight.

Mike Key

[Nicholas Blair]

The EhCacheInterceptor doesn't log hits/misses.
Do you have any debug logging in your @Cacheable annotated method? Do
you see the log statements from your method being printed every time?

If you have statistics enabled for your caches, you can also enable
JMX monitoring for your JVM and watch the cache statistics

The "Cannot remove entry as key -559951139" log message would raise an
alarm for me, it may be that the KeyGenerators you are using between
the @Cacheable method that placed the element in cache and the
@TriggersRemove that attempts the cache removal are inconsistent.

Are you using custom KeyGenerator implementations, and if so do you
have unit tests for them? If not, do your method arguments properly
implement equals, hashCode, and toString?

[Nicholas Blair]

On Tue, Oct 26, 2010 at 9:59 AM, Nicholas Blair
<nichola...@gmail.com> wrote:
> The "Cannot remove entry as key -559951139" log message would raise an
> alarm for me, it may be that the KeyGenerators you are using between
> the @Cacheable method that placed the element in cache and the
> @TriggersRemove that attempts the cache removal are inconsistent.
>

This could also occur if the @TriggersRemove annotated method was
being called before the @Cacheable method using the same cache key was
called.

[MiKey]

Thanks for the responses everyone. So one thing I am absolutely sure of...

The tests that I run ONLY do read operations, so no @TriggersRemove
should ever be being called. I do not see logs that the triggers remove
was called at all with ehcache-spring-annotations debug enabled.

My key generators for @Cachable and @TriggersRemove are as follows just
for clarity in case I do have something wrong here:

@Cacheable(cacheName = "questionCache",
keyGenerator = @KeyGenerator(
name = "HashCodeCacheKeyGenerator",
properties = @Property( name = "includeMethod", value =
"false")
))
public List<Question> getQuestionsForUser(String challengeGroupId)

@TriggersRemove(cacheName = "questionCache",
keyGenerator = @KeyGenerator(
name = "HashCodeCacheKeyGenerator",
properties = @Property( name = "includeMethod", value =
"false")
))
public void setQuestionsForUser(List<Question> userQuestions,
@PartialCacheKey String challengeGroupId)

But again I stress the method for setQuestionsForUser is NEVER called in
my tests. And I see the unable to find key messages in logs under load,
with slower performance than hitting the DB each time...seems to me to
indicate potential thrashing of the cache is going on for some reason.

I'll try the JMX approach, but still wondering if there is a way to get
some sort of logging from this where I can see if things are cycling
through the cache too much so I know where to start tuning my config.

Thanks again for the help as always on this list!