6 Replies Latest reply on Jun 12, 2012 1:20 PM by Dan Berindei

    Problem with expiration in Infinispan

    Carlo Maione Newbie

      Hi all,

      I have a problem with parameters of expiration in Infinispan.

       

      I have this environment:

      1. JDK 1.6.0_26

      2. Infinispan 5.1.4.FINAL

      3. Distributed Cache without persistent storage

      4. Client - Server Topology (Hot Rod)

       

      Configuration of the server is the following:

       

      <?xml version="1.0" encoding="UTF-8"?>

      <infinispan>

            xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

            xsi:schemaLocation="urn:infinispan:config:5.1 http://www.infinispan.org/schemas/infinispan-config-5.1.xsd"

            xmlns="urn:infinispan:config:5.1">

      <global>

        <globalJmxStatistics enabled="true" jmxDomain="org.infinispan" cacheManagerName="SampleCacheManager" />

          <transport clusterName="AVS-infinispan-cluster" machineId="m1" nodeName="m1-Node-A">

           <properties>

          <property name="configurationFile" value="jgroups-udp.xml" />

           </properties>

          </transport>

      </global>

       

      <namedCache name="AVSBeCache">

        <eviction maxEntries="5000" strategy="LRU" />

        <expiration wakeUpInterval="60000" lifespan="-1" maxIdle="120000" />

        <jmxStatistics enabled="true" />

        <clustering mode="distribution">

         <async />

         <hash numOwners="2" rehashWait="120000" rehashRpcTimeout="600000"/>

         <l1 enabled="false" />

        </clustering>

      </namedCache>

      </infinispan>

       

      After a put operation of a key, I wait more 2 mins but the entry doesn't expire (get operation return the key).

      I have monitored the nodes with the JConsole and I see numberEntries always different from 0.

       

      I have set the level log of org.infinispan package to TRACE and I have find this message in the server log (in detail red bold)

       

      2012-06-11 20:49:13,792 TRACE (OOB-3,BeeTVHiveHivePlus-58305) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=webportal204-38224, value=192.168.7.204:11222, flags=[CACHE_MODE_LOCAL, SKIP_LOCKING, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContextSingleKeyNonTxInvocationContext{flags=[CACHE_MODE_LOCAL, SKIP_LOCKING, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK]}]

      2012-06-11 20:49:13,794 TRACE (OOB-3,BeeTVHiveHivePlus-58305) [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=webportal204-38224, value=192.168.7.204:11222, flags=[CACHE_MODE_LOCAL,SKIP_LOCKING, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP, SKIP_SHARED_CACHE_STORE, SKIP_OWNERSHIP_CHECK], putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}.

      2012-06-11 20:49:13,810 TRACE (InfinispanServer-Main) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=BeeTVHiveHivePlus-58305, value=192.168.7.82:11222, flags=null, putIfAbsent=false,lifespanMillis=-1, maxIdleTimeMillis=-1} and InvocationContext [SingleKeyNonTxInvocationContext{flags=null}]

      2012-06-11 20:49:13,820 TRACE (InfinispanServer-Main) [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=BeeTVHiveHivePlus-58305, value=192.168.7.82:11222, flags=null, putIfAbsent=false, lifespanMillis=-1,maxIdleTimeMillis=-1}.

      2012-06-11 20:49:13,820 TRACE (InfinispanServer-Main) [org.infinispan.remoting.rpc.RpcManagerImpl] BeeTVHiveHivePlus-58305 broadcasting call PutKeyValueCommand{key=BeeTVHiveHivePlus-58305, value=192.168.7.82:11222, flags=null,putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1} to recipient list null

      2012-06-11 20:49:13,822 TRACE (InfinispanServer-Main) [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=null, command=SingleRpcCommand{cacheName='___hotRodTopologyCache', command=PutKeyValueCommand{key=BeeTVHiveHivePlus-58305, value=192.168.7.82:11222, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}}, mode=SYNCHRONOUS, timeout=10000

      2012-06-11 20:49:13,822 TRACE (InfinispanServer-Main) [org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher] Replication task sending SingleRpcCommand{cacheName='___hotRodTopologyCache',command=PutKeyValueCommand{key=BeeTVHiveHivePlus-58305, value=192.168.7.82:11222, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}} to single recipient webportal204-38224 with response mode GET_ALL

      2012-06-11 20:49:13,826 TRACE (InfinispanServer-Main) [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to SingleRpcCommand{cacheName='___hotRodTopologyCache', command=PutKeyValueCommand{key=BeeTVHiveHivePlus-58305,value=192.168.7.82:11222, flags=null, putIfAbsent=false, lifespanMillis=-1, maxIdleTimeMillis=-1}} is {webportal204-38224=null}

       

      Why in the start of the server, lifespan and maxIdle are setting to value -1?

       

      Thanks in advance and best regards.

        • 1. Re: Problem with expiration in Infinispan
          Martin Gencur Novice

          Hi Carlo,

          did you provide really the configuration you used in your app? Because I see you're setting lifespan="-1" which means that cache entries will never expire and thus remain in the cache.

          • 2. Re: Problem with expiration in Infinispan
            Carlo Maione Newbie

            Hi Martin,

            yes, this is the configuration of Infinispan Server. I tried also with lifespan=60000 but I have the same problem.

             

            Nevertheless, my question is: parameters in the log (lifespanMillis=-1, maxIdleTimeMillis=-1), are passed to the Infinispan server? If yes, why are different by parameters in the configuration file?

             

            N.B.: I start the Infinispan server with this command ./startServer.sh -r hotrod -l 192.168.7.86 -p 11222 -c /product/infinispan/config/AVS-cacheinf-config.xml where AVS-cacheinf-config.xml is the configuration file

             

            Regards

            • 3. Re: Problem with expiration in Infinispan
              Martin Gencur Novice

              OK.

              The log shows lifespanMillis and maxIdleTimeMillis values for different caches IMO - at least I see cacheName='___hotRodTopologyCache' in the log.

              Are you storing the keys in the right cache? You define the configuration for a named cache "AVSBeCache" so you must use this one and not a default cache which still has default configuration cos your config is only for the named cache.

              1 of 1 people found this helpful
              • 4. Re: Problem with expiration in Infinispan
                Carlo Maione Newbie

                This is log of a put operation:

                 

                2012-06-12 10:57:38,073 TRACE (pool-4-thread-2) [org.infinispan.server.core.transport.NettyTransport] Thread name will be HotRodServerWorker-1-2, with current thread name being Thread[pool-4-thread-2,5,main] and proposed name being 'New I/O server worker #1-2'

                2012-06-12 10:57:38,085 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,085 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.Decoder10$] Operation code: 23 has been matched to PingRequest

                2012-06-12 10:57:38,085 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decoded header HotRodHeader{op=PingRequest, version=11, messageId=1, cacheName=, flag=NoFlag, clientIntelligence=3, topologyId=0}

                2012-06-12 10:57:38,086 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Write response Response{version=11, messageId=1, operation=PingResponse, status=Success, cacheName=}

                2012-06-12 10:57:38,086 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Encode msg Response{version=11, messageId=1, operation=PingResponse, status=Success, cacheName=}

                2012-06-12 10:57:38,086 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Write buffer contents A101180000 to channel [id: 0x609f3e95, /192.168.12.17:65171 => /192.168.7.204:11222]

                2012-06-12 10:57:38,089 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,089 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.Decoder10$] Operation code: 23 has been matched to PingRequest

                2012-06-12 10:57:38,090 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decoded header HotRodHeader{op=PingRequest, version=11, messageId=2, cacheName=AVSBeCache, flag=NoFlag, clientIntelligence=3, topologyId=0}

                2012-06-12 10:57:38,090 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Write response Response{version=11, messageId=2, operation=PingResponse, status=Success, cacheName=AVSBeCache}

                2012-06-12 10:57:38,090 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Encode msg Response{version=11, messageId=2, operation=PingResponse, status=Success, cacheName=AVSBeCache}

                2012-06-12 10:57:38,090 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Write buffer contents A102180000 to channel [id: 0x609f3e95, /192.168.12.17:65171 => /192.168.7.204:11222]

                2012-06-12 10:57:38,112 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,114 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.Decoder10$] Operation code: 1 has been matched to PutRequest

                2012-06-12 10:57:38,114 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decoded header HotRodHeader{op=PutRequest, version=11, messageId=3, cacheName=AVSBeCache, flag=NoFlag, clientIntelligence=3, topologyId=0}

                2012-06-12 10:57:38,115 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,115 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,117 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Decode using instance @16881cb3

                2012-06-12 10:57:38,119 TRACE (HotRodServerWorker-1-2) [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, lifespanMillis=-1000, maxIdleTimeMillis=-1000} and InvocationContext [SingleKeyNonTxInvocationContext{flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}]

                2012-06-12 10:57:38,119 TRACE (HotRodServerWorker-1-2) [org.infinispan.statetransfer.StateTransferLockImpl] Acquired shared state transfer shared lock, total holders: 1

                2012-06-12 10:57:38,119 TRACE (HotRodServerWorker-1-2) [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to lock ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}} with acquisition timeout of 10000 millis

                2012-06-12 10:57:38,119 TRACE (HotRodServerWorker-1-2) [org.infinispan.util.concurrent.locks.LockManagerImpl] Successfully acquired lock ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}!

                2012-06-12 10:57:38,119 TRACE (HotRodServerWorker-1-2) [org.infinispan.container.EntryFactoryImpl] Exists in context? null

                2012-06-12 10:57:38,120 TRACE (HotRodServerWorker-1-2) [org.infinispan.container.EntryFactoryImpl] Retrieved from container null

                2012-06-12 10:57:38,120 TRACE (HotRodServerWorker-1-2) [org.infinispan.container.EntryFactoryImpl] Creating new entry.

                2012-06-12 10:57:38,120 TRACE (HotRodServerWorker-1-2) [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, lifespanMillis=-1000, maxIdleTimeMillis=-1000}.

                2012-06-12 10:57:38,122 TRACE (HotRodServerWorker-1-2) [org.infinispan.interceptors.DistributionInterceptor] Invoking command PutKeyValueCommand{key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, lifespanMillis=-1000, maxIdleTimeMillis=-1000} on hosts [webportal204-59652]

                2012-06-12 10:57:38,122 TRACE (HotRodServerWorker-1-2) [org.infinispan.remoting.rpc.RpcManagerImpl] webportal204-59652 broadcasting call PutKeyValueCommand{key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, lifespanMillis=-1000, maxIdleTimeMillis=-1000} to recipient list [webportal204-59652]

                2012-06-12 10:57:38,122 TRACE (HotRodServerWorker-1-2) [org.infinispan.remoting.rpc.RpcManagerImpl] We're the only member in the cluster; Don't invoke remotely.

                2012-06-12 10:57:38,122 TRACE (HotRodServerWorker-1-2) [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to SingleRpcCommand{cacheName='AVSBeCache', command=PutKeyValueCommand{key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, flags=[SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP], putIfAbsent=false, lifespanMillis=-1000, maxIdleTimeMillis=-1000}} is {}

                2012-06-12 10:57:38,123 TRACE (HotRodServerWorker-1-2) [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}} removed=false valid=true changed=true created=true value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}]

                2012-06-12 10:57:38,123 TRACE (HotRodServerWorker-1-2) [org.infinispan.interceptors.EntryWrappingInterceptor] Committed entry ReadCommittedEntry(7a5388b5){key=ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}, value=CacheValue{data=ByteArray{size=12, array=0x033e094f47474554..}, version=4294967297}, oldValue=null, isCreated=false, isChanged=false, isRemoved=false, isValid=true}

                2012-06-12 10:57:38,124 TRACE (HotRodServerWorker-1-2) [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock ByteArrayKey{data=ByteArray{size=11, hashCode=53e6978d, array=0x033e084348494156..}}

                2012-06-12 10:57:38,124 TRACE (HotRodServerWorker-1-2) [org.infinispan.statetransfer.StateTransferLockImpl] Released shared state transfer shared lock, remaining holders: 0

                2012-06-12 10:57:38,124 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodDecoder] Write response Response{version=11, messageId=3, operation=PutResponse, status=Success, cacheName=AVSBeCache}

                2012-06-12 10:57:38,124 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Encode msg Response{version=11, messageId=3, operation=PutResponse, status=Success, cacheName=AVSBeCache}

                2012-06-12 10:57:38,124 TRACE (HotRodServerWorker-1-2) [org.infinispan.server.hotrod.HotRodEncoder] Write buffer contents A103020000 to channel [id: 0x609f3e95, /192.168.12.17:65171 => /192.168.7.204:11222]

                 

                Now the name of the cache is correct but now the values of lifespan and maxIdle are both -1000.

                 

                A question, is mandatory the section <default> in configuration file?

                 

                Thanks again and regards.

                • 5. Re: Problem with expiration in Infinispan
                  Dan Berindei Expert

                  Carlo, the HotRod client will always override the default lifespan/maxIdle settings because of a limitation in the protocol. We already have an open issue for it: ISPN-1293

                   

                  About the '___hotRodTopologyCache' cache: this is an internal cache, used by the HotRod server to publish the HotRod endpoint information to all the other servers in the cluster. Because of this, is uses a special configuration and it always has -1 for both lifespan and maxIdle settings.


                  • 6. Re: Problem with expiration in Infinispan
                    Dan Berindei Expert

                    Carlo Maione wrote:

                     

                    A question, is mandatory the section <default> in configuration file?

                     

                    No, it's completely optional.