Description

I am using ehcache-core 2.6.6 … I could not select the correct version from the drop down. I have around 300 threads blocked only under load with the following thread dump. I use ehcache core 2.6.6 and use spring’s cache abstraction backed by ehcache. I am not sure what is going on here. Could you confirm is this fixed in future releases?

“tomcat-http–1836” daemon prio=10 tid=0x000000001af0a800 nid=0x14d2 waiting on condition [0x00002b354e594000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x000000060bff7bc8> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:964) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1282) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:731) at net.sf.ehcache.store.FrontEndCacheTier.containsKeyInMemory(FrontEndCacheTier.java:483) at net.sf.ehcache.Cache.searchInStoreWithStats(Cache.java:1941) at net.sf.ehcache.Cache.get(Cache.java:1584) at org.springframework.cache.ehcache.EhCacheCache.get(EhCacheCache.java:61) at org.springframework.cache.interceptor.CacheAspectSupport.inspectCacheables(CacheAspectSupport.java:310) at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:198) at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622) at com.ihg.dec.apps.hi.modelBeans.core.CRONumberModelBeanImpl$EnhancerByCGLIB$98c2cc9.getCRONumberService( ) at com.ihg.dec.apps.hi.businessServices.cro.CRONumberDomainService.getResDirectPhoneNumber(CRONumberDomainService.java:116) at com.ihg.dec.apps.hi.actions.hotel.delegate.HotelDetailsController.addResDirectPhoneNumbers(HotelDetailsController.java:279) at com.ihg.dec.apps.hi.actions.hotel.delegate.HotelDetailsController.setRedirectNumbers(HotelDetailsController.java:933) at com.ihg.dec.apps.hi.actions.hotel.delegate.HotelDetailsController.handleRequestInternal(HotelDetailsController.java:728) at sun.reflect.GeneratedMethodAccessor1440.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:436) at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:424) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882) at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778) at javax.servlet.http.HttpServlet.service(HttpServlet.java:621) at javax.servlet.http.HttpServlet.service(HttpServlet.java:728) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.web.uhf.wallet.WalletFilter.doFilter(WalletFilter.java:204) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.pcr2.cdm.CDCFilter.doFilter(CDCFilter.java:157) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.multibrand.sso.cm.SSOFilter.doFilter(SSOFilter.java:228) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:83) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.commons.filter.NoDuplicateCookiesFilter.doFilter(NoDuplicateCookiesFilter.java:25) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.server.dao.endeavor.EndeavorContextFilter.doFilter(EndeavorContextFilter.java:84) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.ihg.commons.filter.XSSFilter.doFilter(XSSFilter.java:73) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:172) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310) - locked <0x000000074d821690> (a org.apache.tomcat.util.net.SocketWrapper) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744) Locked ownable synchronizers: - 0x000000074968bb38> (a java.util.concurrent.ThreadPoolExecutor$Worker)

Comments

Louis Jacomet Jacomet 2014-03-12

Hi,

Hard to conclude anything from this partial thread dump. It is waiting for a read lock, so I would assume the thread holding the write lock is stuck for some reason.

Dinakar Manchikalapudi 2014-03-12

Thanks Louis for your quick reply. Here are some more details… My spring annotation for the method looks like this

@Override
    @Cacheable(value = "Impl:CRONumberService:getCRONumber", key = "T(com.ihg.dec.apps.hi.modelBeans.core.CROCacheKeyGeneratorUtil).getCROCacheKey(#croNumberDetailsRequest)")
    public ResdirectPhoneNumber getCRONumberService(final InvocationContext context, final CRONumberDetailsRequest croNumberDetailsRequest) {
          // 1) Make service call to retrieve the response
          // 2) Inspect the response. .. if it does not have what we need ... throw a subclass of runtime exception. Throwing any exception will not put an entry into the ehcache cache for the key generated above. Do you think this is causing 
                 the issue? if so, how do I avoid this? Is there a setting on the cache that I can set that will release the lock on write after a timeout?
          // 3) Else .. .return response and cache it on its way out for the key generated above
    }

I am constructing the key value using a static call in a class called CROCacheKeyGeneratorUtil that takes in the request param and returns the concatenated tostring value of the attributes of interest. The method looks very simple.

    public static String getCROCacheKey(final CRONumberDetailsRequest croNumberDetailsRequest) {
        StringBuilder strBuilder = new StringBuilder(100);
        if (croNumberDetailsRequest != null) {
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getCIDParam()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getRefIdParam()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getIATAParam()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getIATACookie()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getSiteIdParam()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getBrand().toLowerCase()).trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getRegion().toLowerCase()).trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getLocale().toLowerCase()).trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getCountryOfOrigin()).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(String.valueOf(croNumberDetailsRequest.getSlot())).toLowerCase().trim());
            strBuilder.append(StringUtils.defaultString(croNumberDetailsRequest.getHotelMnemonic()).toLowerCase().trim());
        }
        LOG.info("Returning cache key {} for CRO Cache region", strBuilder.toString());
        return strBuilder.toString();
    }

At what point is a write lock acquired? when a key is generated? if so, what happens when a runtime exception is thrown from the body of the method its trying to cache?

Louis Jacomet Jacomet 2014-03-14

I am not a specialist on the Spring caching abstraction, but I assume it would:

Create the key

Look it up in the cache

Return cached value if found

Proceed otherwise

Execute method body

Intercept result and put in cache

In such context, there is no reason for a lock to be hold while the method is executing, nor should throwing an exception result in a lock be maintained.

Have a look at a complete thread dump when the issue arise and find out what the thread holding the lock other thread(s) is(are) waiting for is doing.