Emergency issue about the Timed out waiting for operation

[hogan]

hi, Ray:
I get lots of warning as follows every some times:
com.googlecode.hibernate.memcached.spymemcached.SpyMemcache -
Cache 'get' timed out for key [com.test.Profile:0:2835904]
net.spy.memcached.OperationTimeoutException: Timeout waiting for value
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:765)
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:778)
at com.googlecode.hibernate.memcached.spymemcached.SpyMemcache.get
(SpyMemcache.java:27)
at com.googlecode.hibernate.memcached.MemcachedCache.memcacheGet
(MemcachedCache.java:124)
at com.googlecode.hibernate.memcached.MemcachedCache.get
(MemcachedCache.java:153)
at org.hibernate.cache.NonstrictReadWriteCache.get
(NonstrictReadWriteCache.java:69)
at org.hibernate.cache.impl.bridge.EntityAccessStrategyAdapter.get
(EntityAccessStrategyAdapter.java:55)
at
org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache
(DefaultLoadEventListener.java:524)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad
(DefaultLoadEventListener.java:397)
at org.hibernate.event.def.DefaultLoadEventListener.load
(DefaultLoadEventListener.java:165)
at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad
(DefaultLoadEventListener.java:223)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad
(DefaultLoadEventListener.java:126)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
at org.hibernate.impl.SessionImpl.get(SessionImpl.java:842)
at org.hibernate.impl.SessionImpl.get(SessionImpl.java:835)
at com.crushorflush.dao.hibernate.AbstractHibernateGenericDAO.get
(AbstractHibernateGenericDAO.java:60)
at com.crushorflush.dao.hibernate.AbstractHibernateGenericDAO.getById
(AbstractHibernateGenericDAO.java:105)
at com.crushorflush.business.ProfileMgr.getById(ProfileMgr.java:151)
at
com.crushorflush.service.online.HessianOnlineServiceServer.getRecentlyLoginedUser
(HessianOnlineServiceServer.java:644)
at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke
(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.caucho.hessian.server.HessianSkeleton.invoke
(HessianSkeleton.java:169)
at com.caucho.hessian.server.HessianServlet.service
(HessianServlet.java:365)
at com.caucho.server.dispatch.ServletFilterChain.doFilter
(ServletFilterChain.java:106)
at com.crushorflush.util.TrackLogFilter.doFilter(TrackLogFilter.java:
108)
at com.caucho.server.dispatch.FilterFilterChain.doFilter
(FilterFilterChain.java:70)
at com.crushorflush.util.TransactionCommitFilter$1.doAction
(TransactionCommitFilter.java:121)
at com.crushorflush.util.TransactionThread.doTransaction
(TransactionThread.java:58)
at com.crushorflush.util.TransactionCommitFilter.runTransaction
(TransactionCommitFilter.java:164)
at com.crushorflush.util.TransactionCommitFilter.doFilter
(TransactionCommitFilter.java:35)
at com.caucho.server.dispatch.FilterFilterChain.doFilter
(FilterFilterChain.java:70)
at
com.crushorflush.base.ui.filter.ExposeSpringContextBeansFilter.doFilterInternal
(ExposeSpringContextBeansFilter.java:22)
at org.springframework.web.filter.OncePerRequestFilter.doFilter
(OncePerRequestFilter.java:75)
at com.caucho.server.dispatch.FilterFilterChain.doFilter
(FilterFilterChain.java:70)
at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter
(UrlRewriteFilter.java:738)
at com.caucho.server.dispatch.FilterFilterChain.doFilter
(FilterFilterChain.java:70)
at com.caucho.server.webapp.WebAppFilterChain.doFilter
(WebAppFilterChain.java:173)
at com.caucho.server.dispatch.ServletInvocation.service
(ServletInvocation.java:229)
at com.caucho.server.hmux.HmuxRequest.handleRequest(HmuxRequest.java:
420)
at com.caucho.server.port.TcpConnection.run(TcpConnection.java:511)
at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:520)
at com.caucho.util.ThreadPool.run(ThreadPool.java:442)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.util.concurrent.TimeoutException: Timed out waiting
for operation
at net.spy.memcached.MemcachedClient$OperationFuture.get
(MemcachedClient.java:1487)
at net.spy.memcached.MemcachedClient$GetFuture.get
(MemcachedClient.java:1539)
at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:758)
... 43 more

have any ideas about that?

Thanks!

Hogan

[Ray Krueger]

> Essentially the spymemcached library is timing out waiting for the
> 'get' operation to complete. Really, 1 second is a long time, it
> shouldn't take that long to get something from the cache.
> Do you have network latency issues?
> How many memcached instances are you running?
> Whichever server key [com.test.Profile:0:2835904] is going to is
> taking a long time to do a 'get'.
>
> These are logged as warnings because the hibernate-memcached handles
> it by just returning null to hibernate. Which makes Hibernate see it
> as a simple cache-miss. Though having a ton of timeouts is going to
> kill you because you're adding 1 second of latency and then not using
> the cache.
>

You should definitely take a look at your "evections" stat from STATS
by the way. You were looking at cmd_set and cmd_get before, but
evictions could be related to the timeouts you're seeing here.

[Ray Krueger]

> hi, Ray:
> I get lots of warning as follows every some times:
> com.googlecode.hibernate.memcached.spymemcached.SpyMemcache -
> Cache 'get' timed out for key [com.test.Profile:0:2835904]
> net.spy.memcached.OperationTimeoutException: Timeout waiting for value
> at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:765)

The default operation timeout is 1000ms, unless you've changed it in
your configuration.
More info here...
http://code.google.com/p/hibernate-memcached/wiki/Configuration
http://bleu.west.spy.net/~dustin/projects/memcached/apidocs/constant-values.html#net.spy.memcached.DefaultConnectionFactory.DEFAULT_OPERATION_TIMEOUT

[hogan]

hi, Ray:
Thanks for your repley, I just have an memcached server. and I know
that the default timeout is 1000ms. and i check the evictions, the
number is 0, Here is the status I get from the memcached:

STAT pid 13645
STAT uptime 248627
STAT time 1228717376
STAT version 1.2.6
STAT pointer_size 64
STAT rusage_user 0.628039
STAT rusage_system 1.004062
STAT curr_items 1841
STAT total_items 1033817
STAT bytes 1759813
STAT curr_connections 19
STAT total_connections 124
STAT connection_structures 26
STAT cmd_get 158820
STAT cmd_set 1033817
STAT get_hits 74067
STAT get_misses 84753
STAT evictions 0
STAT bytes_read 137461721
STAT bytes_written 72594358
STAT limit_maxbytes 268435456
STAT threads 1
END

The server load average, cpu and memory usage are very low I am not
sure what's make the errors occur. and the error throws out every some
times.
When i disable the query cache, just use the second level cache, The
error not happens again.

Hogan

On Dec 5, 7:20 pm, "Ray Krueger" <raykrue...@gmail.com> wrote:
> > hi, Ray:
> >  I get lots of warning as follows every some times:
> >   com.googlecode.hibernate.memcached.spymemcached.SpyMemcache  -
> > Cache 'get' timed out for key [com.test.Profile:0:2835904]
> > net.spy.memcached.OperationTimeoutException: Timeout waiting for value
> >        at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:765)
>
> The default operation timeout is 1000ms, unless you've changed it in
> your configuration.

> More info here...http://code.google.com/p/hibernate-memcached/wiki/Configurationhttp://bleu.west.spy.net/~dustin/projects/memcached/apidocs/constant-...

[Ray Krueger]

> hi, Ray:
> Thanks for your repley, I just have an memcached server. and I know
> that the default timeout is 1000ms. and i check the evictions, the
> number is 0, Here is the status I get from the memcached:

> The server load average, cpu and memory usage are very low I am not
> sure what's make the errors occur. and the error throws out every some
> times.
> When i disable the query cache, just use the second level cache, The
> error not happens again.

The "operation" that times out includes all the serialization and
networking. It could be a matter of occasionally having to serialize a
large object. If it's only happening once in a great while, I wouldn't
worry about it too much. If it's happening a lot you should be
concerned.
Are you only running a single instance of memcached? That sort of
defeats the purpose, I would stand up at least 1 more at a minimum. I
don't think that's going to change anything in this matter, but you're
missing out on reliability at a minimum by running only a single
instance.

[Seon Lee]

Ray, are you saying that if the number of evictions are too high it
indicates too much turn over within the cache? How should we be
interpreting the evictions stat in relation to sets and gets stats in
the memcache server?

Maybe the OP needs to adjust the hibernate.memcached.cacheTimeSeconds
value (defaults at 5 minutes) if his evictions are too high.

We are experiencing the same problem as the OP, and am currently
trying to reproduce this outside of our production environment. What
complicates the matter for us is that when we start experiencing these
timouts in the hibernate provider, we start to see a gradual rise in
the number of database connections being made (perfectly logical) and
the application performance starts to degrade very rapidly -- almost
snowballing to the point where it becomes unusable quickly.

Ray, I noticed that only one Memcache spy client instance is created
per provider. Are there any advantages to moving to a pool of clients
or multiple clients in the provider? Or perhaps using a pool of
hibernate provider instances (with each instance having a separate
Memcache spy client)?

Cheers,
Seon

[Ray Krueger]

On Thu, Jan 15, 2009 at 11:54 AM, Seon Lee <fuc...@gmail.com> wrote:
>
> Ray, are you saying that if the number of evictions are too high it
> indicates too much turn over within the cache? How should we be
> interpreting the evictions stat in relation to sets and gets stats in
> the memcache server?

From the memcached protocol.txt
http://code.sixapart.com/svn/memcached/trunk/server/doc/protocol.txt

evictions 64u Number of valid items removed from cache
to free memory for new items

Essentially there isn't room in the cache for new items, so old items
have to be removed; even if they aren't expired yet.

>
> Maybe the OP needs to adjust the hibernate.memcached.cacheTimeSeconds
> value (defaults at 5 minutes) if his evictions are too high.

Changing the cache time won't help too much really if the cache is
just full. Either increase the size of the cache, or add more servers,
or both.

>
> We are experiencing the same problem as the OP, and am currently
> trying to reproduce this outside of our production environment. What
> complicates the matter for us is that when we start experiencing these
> timouts in the hibernate provider, we start to see a gradual rise in
> the number of database connections being made (perfectly logical) and
> the application performance starts to degrade very rapidly -- almost
> snowballing to the point where it becomes unusable quickly.

Unfortunately that's exactly what will happen when your cache layer goes down.

>
> Ray, I noticed that only one Memcache spy client instance is created
> per provider. Are there any advantages to moving to a pool of clients
> or multiple clients in the provider? Or perhaps using a pool of
> hibernate provider instances (with each instance having a separate
> Memcache spy client)?

That's how the spymemcached client works...
http://code.google.com/p/spymemcached/wiki/Optimizations

If you have in-depth questions about spymemcached I'd use that list
http://groups.google.com/group/spymemcached?pli=1

Same goes for memcached list...
http://groups.google.com/group/memcached