1.02 java.lang.RuntimeException: LRUAlgorithm.evict()

[octopus]

Under (relatively) heavy load LRUAlgorithm for some reason tries to remove the same node twice. Result is java.lang.RuntimeException: LRUAlgorithm.evict(): null node map entry for fqn: /test1/node835264.

Test case. local-eviction-service.xml is used. Default region - 5000 nodes max. LRU policy.

 public void test2() throws Exception {
 cache = new TreeCache();
 PropertyConfigurator config = new PropertyConfigurator();
 config.configure(cache, "jboss/local-eviction-service.xml");
 cache.setTransactionManagerLookupClass("org.jboss.cache.DummyTransactionManagerLookup");
 cache.start();

 cache.put("/test1", "value", new Integer(1));

 for (int i = 0; i < 10; i++) {
 new Thread() {
 public void run() {
 while (true) {
 int i = (int) (Math.random() * 10000000);
 try {
 cache.put("/test1/node" + i, "value", new Integer(i));
 } catch (Exception e) {
 e.printStackTrace();
 }
 }
 }
 }.start();
 }

 while (true) {
 Node node = cache.get("/test1");
 int count = node == null || node.getChildren() == null ? 0 : node.getChildren().size();
 log.info("Nodes: " + count);
 Thread.sleep(1000);
 }

 }

After running, in about 10 sec there's LRUAlgorith exception.

12:14:41,515 INFO [PropertyConfigurator] configure(): attribute size: 19
12:14:41,562 INFO [TreeCache] setClusterConfig(): setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=false;mcast_addr=228.1.2.3;mcast_port=45566;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD(down_thread=true;shun=true;up_thread=true):VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=false;up_thread=false)
12:14:41,624 INFO [TreeCache] setEvictionPolicyConfig(): [config: null]
12:14:41,843 INFO [LRUPolicy] Starting eviction policy using the provider: org.jboss.cache.eviction.LRUPolicy
12:14:42,437 INFO [LRUPolicy] Starting a eviction timer with wake up interval of (secs) 5
12:14:42,437 INFO [TreeCache] cache mode is local, will not create the channel
12:14:42,546 INFO [TestCache] Nodes: 4
12:14:43,577 INFO [TestCache] Nodes: 484
12:14:44,734 INFO [TestCache] Nodes: 889
12:14:45,765 INFO [TestCache] Nodes: 1399
12:14:46,765 INFO [TestCache] Nodes: 2415
12:14:47,796 INFO [TestCache] Nodes: 2920
12:14:48,812 INFO [TestCache] Nodes: 4115
12:14:49,827 INFO [TestCache] Nodes: 5146
12:14:50,827 INFO [TestCache] Nodes: 6396
12:14:51,843 INFO [TestCache] Nodes: 7799
12:14:52,843 INFO [TestCache] Nodes: 8787
java.lang.RuntimeException: LRUAlgorithm.evict(): null node map entry for fqn: /test1/node835264
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:314)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:285)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:56)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:33)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
12:14:53,859 INFO [TestCache] Nodes: 9878
12:14:54,859 INFO [TestCache] Nodes: 10932

Looking into detailed log shows that this node is going to be evicted twice. (see the first and last line, /test1/node835264)

12:14:53,093 DEBUG [LRUAlgorithm] prune(): over-capacity. Evict node /test1/node835264
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node4856351", value, 4856351)
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node6325913", value, 6325913)
12:14:53,093 DEBUG [Node] createChild: fqn=/test1/node5183986
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node4979935", value, 4979935)
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node8576147", value, 8576147)
12:14:53,093 DEBUG [Node] createChild: fqn=/test1/node7151499
12:14:53,093 DEBUG [LRUPolicy] nodeAdded(): fqn- /test1/node7151499
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node7151499 will use the global default region
12:14:53,093 DEBUG [LRUPolicy] nodeModified(): redirecting to node visited. fqn- /test1/node7151499
12:14:53,093 DEBUG [LRUPolicy] nodeVisited(): fqn- /test1/node7151499
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node7151499 will use the global default region
12:14:53,093 DEBUG [Node] createChild: fqn=/test1/node1241366
12:14:53,093 DEBUG [LRUPolicy] nodeAdded(): fqn- /test1/node1241366
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node1241366 will use the global default region
12:14:53,093 DEBUG [LRUPolicy] nodeModified(): redirecting to node visited. fqn- /test1/node1241366
12:14:53,093 DEBUG [LRUPolicy] nodeVisited(): fqn- /test1/node1241366
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node1241366 will use the global default region
12:14:53,093 DEBUG [Node] createChild: fqn=/test1/node9401565
12:14:53,093 DEBUG [LRUPolicy] nodeAdded(): fqn- /test1/node9401565
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node9401565 will use the global default region
12:14:53,093 DEBUG [LRUPolicy] nodeModified(): redirecting to node visited. fqn- /test1/node9401565
12:14:53,093 DEBUG [LRUPolicy] nodeVisited(): fqn- /test1/node9401565
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node9401565 will use the global default region
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node4180297", value, 4180297)
12:14:53,093 DEBUG [TreeCache] invokeMethod(): calling method _put
12:14:53,093 DEBUG [TreeCache] _put(null, "/test1/node4740050", value, 4740050)
12:14:53,093 DEBUG [LRUPolicy] nodeAdded(): fqn- /test1/node5183986
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node5183986 will use the global default region
12:14:53,093 DEBUG [LRUPolicy] nodeModified(): redirecting to node visited. fqn- /test1/node5183986
12:14:53,093 DEBUG [LRUPolicy] nodeVisited(): fqn- /test1/node5183986
12:14:53,093 DEBUG [RegionManager] getRegion(): not user-specified region found for this fqn- /test1/node5183986 will use the global default region
12:14:53,093 DEBUG [TreeCache] _remove(null, "/test1/node835264")
12:14:53,093 DEBUG [LRUAlgorithm] prune(): over-capacity. Evict node /test1/node835264

[octopus]

Seems that exactly this error already been posted on this forum

http://jboss.org/index.html?module=bb&op=viewtopic&t=52457

as far as I see it's still exists.

[ben.wang]

Hi,

Since I have just refactored the eviction policy last week, I have tried your test case on the latest code on jboss-head. I don't see any error right now. So can you try it yourself to make sure the problem is resolved?

I will incorporate your test case.

Thanks,

-Ben

[octopus]

Ben,

Now it's working much better, it takes some time to get this error. But unfortunately, it's still there.
Seems it heavily depends on system load. It I put Thread.sleep(10) in putting thread it never happens.

configure(): attribute size: 25
setClusterConfig(): setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=true;mcast_addr=228.1.2.3;mcast_port=45566;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
setEvictionPolicyConfig(): [config: null]
interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
class org.jboss.cache.interceptors.TransactionInterceptor
cache mode is REPL_SYNC
unicast sockets will use interface 192.168.2.3
socket information:
local_addr=grc03:3519, mcast_addr=228.1.2.3:45566, bind_addr=/192.168.2.3, ttl=64
sock: bound to 192.168.2.3:3519, receive buffer size=80000, send buffer size=150000
mcast_recv_sock: bound to 192.168.2.3:45566, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.2.3:3520, send buffer size=150000, receive buffer size=80000

-------------------------------------------------------
GMS: address is grc03:3519
-------------------------------------------------------
viewAccepted(): new members: [grc03:3519]
state could not be retrieved (must be first member in group)
Starting eviction policy using the provider: org.jboss.cache.eviction.LRUPolicy
new cache is null (maybe first member in cluster)
Starting a eviction timer with wake up interval of (secs) 5
Nodes: 161
Nodes: 2951
Nodes: 12388
Nodes: 17902
Nodes: 25040
Nodes: 28816
Nodes: 3142
Nodes: 11843
Nodes: 20680
Nodes: 25990
Nodes: 33636
Nodes: 4868
Nodes: 13993
Nodes: 20029
Nodes: 28710
Nodes: 36381
Nodes: 4335
Nodes: 13071
Nodes: 19388
Nodes: 28335
Nodes: 35693
Nodes: 43115
Nodes: 48385
Nodes: 5213
Nodes: 14498
Nodes: 6281
Nodes: 15074
Nodes: 23786
Nodes: 28775
Nodes: 37780
Nodes: 1423
Nodes: 10301
Nodes: 19641
Nodes: 28831
Nodes: 37106
Nodes: 28555
Nodes: 31029
Nodes: 35806
Nodes: 38927
Nodes: 40414
Nodes: 42059
Nodes: 47092
Nodes: 51839
Nodes: 56676
Nodes: 57094
Nodes: 57111
Nodes: 60808
Nodes: 64463
Nodes: 68561
Nodes: 72609
Nodes: 75329
Nodes: 76526
Nodes: 80795
Nodes: 85269
Nodes: 89576
Nodes: 93573
Nodes: 94997
Nodes: 99122
Nodes: 100316
Nodes: 101730
Nodes: 103151
Nodes: 104694
Nodes: 105332
Nodes: 101138
Nodes: 101183
Nodes: 101193
Nodes: 94799
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test1/node3774346 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test1/node3774346
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:69)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test1/node3774346 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test1/node3774346
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:69)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Nodes: 48758
Nodes: 50600
Nodes: 58431
Nodes: 66235

Comparing with previous version it'n not 100% reproduced. Since no it's not stopping next eviction calls I can live with it. But there's another problem.

Under heavy load eviction doesn't manage to do it work in time. In my case I easily get OutOfMemory exception (following example for policy maxNodes set to just 100)

configure(): attribute size: 25
setClusterConfig(): setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=true;mcast_addr=228.1.2.3;mcast_port=45566;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
setEvictionPolicyConfig(): [config: null]
interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
class org.jboss.cache.interceptors.TransactionInterceptor
cache mode is REPL_SYNC
unicast sockets will use interface 192.168.2.3
socket information:
local_addr=grc03:4855, mcast_addr=228.1.2.3:45566, bind_addr=/192.168.2.3, ttl=64
sock: bound to 192.168.2.3:4855, receive buffer size=80000, send buffer size=150000
mcast_recv_sock: bound to 192.168.2.3:45566, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.2.3:4856, send buffer size=150000, receive buffer size=80000

-------------------------------------------------------
GMS: address is grc03:4855
-------------------------------------------------------
viewAccepted(): new members: [grc03:4855]
state could not be retrieved (must be first member in group)
Starting eviction policy using the provider: org.jboss.cache.eviction.LRUPolicy
new cache is null (maybe first member in cluster)
Starting a eviction timer with wake up interval of (secs) 5
Tue Aug 24 11:06:28 CEST 2004 Nodes: 163
Tue Aug 24 11:06:29 CEST 2004 Nodes: 3070
Tue Aug 24 11:06:30 CEST 2004 Nodes: 8896
Tue Aug 24 11:06:31 CEST 2004 Nodes: 14002
Tue Aug 24 11:06:32 CEST 2004 Nodes: 22968
Tue Aug 24 11:06:33 CEST 2004 New eviction task started.
Tue Aug 24 11:06:33 CEST 2004 Nodes: 27600
Tue Aug 24 11:06:34 CEST 2004 Nodes: 33372
Tue Aug 24 11:06:35 CEST 2004 Eviction task finished.
Tue Aug 24 11:06:35 CEST 2004 Nodes: 169
Tue Aug 24 11:06:36 CEST 2004 Nodes: 8495
Tue Aug 24 11:06:37 CEST 2004 Nodes: 15999
Tue Aug 24 11:06:38 CEST 2004 New eviction task started.
Tue Aug 24 11:06:38 CEST 2004 Nodes: 22538
Tue Aug 24 11:06:39 CEST 2004 Nodes: 29884
Tue Aug 24 11:06:40 CEST 2004 Nodes: 37066
Tue Aug 24 11:06:41 CEST 2004 Nodes: 44396
Tue Aug 24 11:06:42 CEST 2004 Nodes: 50692
Tue Aug 24 11:06:43 CEST 2004 Nodes: 53754
Tue Aug 24 11:06:44 CEST 2004 Nodes: 58896
Tue Aug 24 11:06:45 CEST 2004 Nodes: 66052
Tue Aug 24 11:06:46 CEST 2004 Nodes: 72438
Tue Aug 24 11:06:47 CEST 2004 Nodes: 74223
Tue Aug 24 11:06:48 CEST 2004 Nodes: 80446
Tue Aug 24 11:06:49 CEST 2004 Nodes: 87711
Tue Aug 24 11:06:51 CEST 2004 Nodes: 89614
Tue Aug 24 11:06:52 CEST 2004 Nodes: 96986
Tue Aug 24 11:06:54 CEST 2004 Nodes: 99668
Tue Aug 24 11:06:55 CEST 2004 Nodes: 101496
Tue Aug 24 11:06:57 CEST 2004 Nodes: 105142
Tue Aug 24 11:06:58 CEST 2004 Nodes: 106932
Tue Aug 24 11:07:00 CEST 2004 Nodes: 108747
Tue Aug 24 11:07:02 CEST 2004 Nodes: 110573
Tue Aug 24 11:07:03 CEST 2004 Nodes: 112388
Tue Aug 24 11:07:05 CEST 2004 Nodes: 114023
Tue Aug 24 11:07:06 CEST 2004 Nodes: 115293
Tue Aug 24 11:07:08 CEST 2004 Nodes: 116271
Tue Aug 24 11:07:09 CEST 2004 Nodes: 117051
Tue Aug 24 11:07:11 CEST 2004 Nodes: 117644
Tue Aug 24 11:07:12 CEST 2004 Nodes: 118095
Tue Aug 24 11:07:14 CEST 2004 Nodes: 118431
Tue Aug 24 11:07:15 CEST 2004 Nodes: 118713
Tue Aug 24 11:07:17 CEST 2004 Nodes: 118935

java.lang.OutOfMemoryError

org.jboss.util.NestedRuntimeException: - nested throwable: (java.lang.OutOfMemoryError)
 at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:3176)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1742)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1725)
 at test.com.dukascopy.mt.data.TestCache$1.run(TestCache.java:63)
Caused by: java.lang.OutOfMemoryError
org.jboss.util.NestedRuntimeException: - nested throwable: (java.lang.OutOfMemoryError)
 at org.jboss.cache.TreeCache.invokeMethod(TreeCache.

As you see eviction task started but for a minute didn't manage to do any noticeable garbage collecting.
I thing it production environment it's very possible case. Don't you thing you should advance eviction thread priority so it's always cleaning faster then garbage appear?

[octopus]

I've just put latest jboss-cache.jar into jboss and run my application testunit. It's about the same I used above. It puts as much as possible my cached objects to cache.
Shortly after start I noticed that number of cached object keep rising far above limit (10000). I stopped my testcase.
Then, while there's no any activity with cache, it jboss stdout I see that on each eviction step the same exception it thrown.
By the way, according to printDetails() called from jmx console, this particular key [ChartRequest 425, 60, 41, candle] does not exist in cache while eviction process keeps trying to remove it.

13:52:05,867 INFO [STDOUT] Tue Aug 24 13:52:05 CEST 2004 New eviction task started.
13:52:05,867 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:05,867 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:05,882 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:05,882 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:05,882 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:05,882 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:05,898 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:05,898 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:05,898 INFO [STDOUT] Tue Aug 24 13:52:05 CEST 2004 Eviction task finished.
13:52:10,870 INFO [STDOUT] Tue Aug 24 13:52:10 CEST 2004 New eviction task started.
13:52:10,870 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:10,885 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:10,885 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:10,901 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:10,901 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:10,901 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:10,901 INFO [CurrentTimeService] Current time updated. New value: 1093348340 (Tue Aug 24 13:52:20 CEST 2004)
13:52:10,901 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:10,916 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:10,916 INFO [STDOUT] Tue Aug 24 13:52:10 CEST 2004 Eviction task finished.
13:52:15,873 INFO [STDOUT] Tue Aug 24 13:52:15 CEST 2004 New eviction task started.
13:52:15,873 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:15,888 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:15,888 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:15,888 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:15,904 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:15,904 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:15,904 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:15,904 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:15,904 INFO [STDOUT] Tue Aug 24 13:52:15 CEST 2004 Eviction task finished.
13:52:20,003 INFO [CurrentTimeService] Current time updated. New value: 1093348350 (Tue Aug 24 13:52:30 CEST 2004)
13:52:20,876 INFO [STDOUT] Tue Aug 24 13:52:20 CEST 2004 New eviction task started.
13:52:20,876 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:20,891 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:20,891 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:20,891 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:20,891 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:20,907 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:20,907 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:20,907 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:20,907 INFO [STDOUT] Tue Aug 24 13:52:20 CEST 2004 Eviction task finished.
13:52:25,879 INFO [STDOUT] Tue Aug 24 13:52:25 CEST 2004 New eviction task started.
13:52:25,895 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:25,895 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:25,910 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:25,910 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:25,910 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:25,910 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:25,910 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:25,926 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:25,926 INFO [STDOUT] Tue Aug 24 13:52:25 CEST 2004 Eviction task finished.
13:52:28,903 INFO [CurrentTimeService] Current time updated. New value: 1093348360 (Tue Aug 24 13:52:40 CEST 2004)
13:52:30,882 INFO [STDOUT] Tue Aug 24 13:52:30 CEST 2004 New eviction task started.
13:52:30,882 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:30,898 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:30,898 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:30,898 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:30,913 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:30,913 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:30,913 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:30,913 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:30,913 INFO [STDOUT] Tue Aug 24 13:52:30 CEST 2004 Eviction task finished.
13:52:35,885 INFO [STDOUT] Tue Aug 24 13:52:35 CEST 2004 New eviction task started.
13:52:35,885 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:35,901 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:35,901 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:35,916 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:35,916 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:35,916 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:35,916 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:35,916 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:35,932 INFO [STDOUT] Tue Aug 24 13:52:35 CEST 2004 Eviction task finished.
13:52:40,888 INFO [STDOUT] Tue Aug 24 13:52:40 CEST 2004 New eviction task started.
13:52:40,888 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:40,888 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:40,904 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:40,904 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:40,904 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:40,904 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:40,920 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:40,920 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:40,920 INFO [STDOUT] Tue Aug 24 13:52:40 CEST 2004 Eviction task finished.
13:52:40,935 INFO [CurrentTimeService] Current time updated. New value: 1093348370 (Tue Aug 24 13:52:50 CEST 2004)
13:52:45,891 INFO [STDOUT] Tue Aug 24 13:52:45 CEST 2004 New eviction task started.
13:52:45,891 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:45,891 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:45,907 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:45,907 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:45,907 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:45,907 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:45,923 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:45,923 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:45,923 INFO [STDOUT] Tue Aug 24 13:52:45 CEST 2004 Eviction task finished.
13:52:49,866 INFO [CurrentTimeService] Current time updated. New value: 1093348380 (Tue Aug 24 13:53:00 CEST 2004)
13:52:50,895 INFO [STDOUT] Tue Aug 24 13:52:50 CEST 2004 New eviction task started.
13:52:50,895 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:50,910 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:50,910 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:50,926 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:50,926 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:50,926 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:50,926 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:50,926 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:50,941 INFO [STDOUT] Tue Aug 24 13:52:50 CEST 2004 Eviction task finished.
13:52:55,898 INFO [STDOUT] Tue Aug 24 13:52:55 CEST 2004 New eviction task started.
13:52:55,898 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:52:55,898 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:52:55,898 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:52:55,898 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:52:55,898 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:52:55,898 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:52:55,898 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:52:55,898 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:52:55,898 INFO [STDOUT] Tue Aug 24 13:52:55 CEST 2004 Eviction task finished.
13:52:59,140 INFO [CurrentTimeService] Current time updated. New value: 1093348390 (Tue Aug 24 13:53:10 CEST 2004)
13:53:03,379 INFO [STDOUT] Tue Aug 24 13:53:03 CEST 2004 New eviction task started.
13:53:03,395 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:03,395 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:03,395 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:03,395 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:03,395 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:03,395 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:03,395 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:03,395 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:03,395 INFO [STDOUT] Tue Aug 24 13:53:03 CEST 2004 Eviction task finished.
13:53:08,382 INFO [STDOUT] Tue Aug 24 13:53:08 CEST 2004 New eviction task started.
13:53:08,398 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:08,398 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:08,413 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:08,413 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:08,413 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:08,429 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:08,429 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:08,429 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:08,429 INFO [STDOUT] Tue Aug 24 13:53:08 CEST 2004 Eviction task finished.
13:53:10,938 INFO [CurrentTimeService] Current time updated. New value: 1093348400 (Tue Aug 24 13:53:20 CEST 2004)
13:53:13,385 INFO [STDOUT] Tue Aug 24 13:53:13 CEST 2004 New eviction task started.
13:53:16,409 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:16,424 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:16,424 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:16,440 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:16,440 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:16,440 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:16,440 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:16,456 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:16,471 INFO [STDOUT] Tue Aug 24 13:53:16 CEST 2004 Eviction task finished.
13:53:18,388 INFO [STDOUT] Tue Aug 24 13:53:18 CEST 2004 New eviction task started.
13:53:18,388 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:18,388 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:18,388 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:18,388 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:18,388 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:18,388 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:18,388 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:18,388 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:18,388 INFO [STDOUT] Tue Aug 24 13:53:18 CEST 2004 Eviction task finished.
13:53:19,900 INFO [CurrentTimeService] Current time updated. New value: 1093348410 (Tue Aug 24 13:53:30 CEST 2004)
13:53:23,391 INFO [STDOUT] Tue Aug 24 13:53:23 CEST 2004 New eviction task started.
13:53:23,391 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:23,391 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:23,391 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:23,407 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:23,407 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:23,407 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:23,407 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:23,407 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:23,407 INFO [STDOUT] Tue Aug 24 13:53:23 CEST 2004 Eviction task finished.
13:53:28,394 INFO [STDOUT] Tue Aug 24 13:53:28 CEST 2004 New eviction task started.
13:53:28,394 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:28,394 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:28,394 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:28,394 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:28,394 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:28,394 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:28,394 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:28,394 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:28,394 INFO [STDOUT] Tue Aug 24 13:53:28 CEST 2004 Eviction task finished.
13:53:28,862 INFO [CurrentTimeService] Current time updated. New value: 1093348420 (Tue Aug 24 13:53:40 CEST 2004)
13:53:33,398 INFO [STDOUT] Tue Aug 24 13:53:33 CEST 2004 New eviction task started.
13:53:33,398 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:33,398 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:33,398 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:33,398 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:33,398 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:33,398 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:33,398 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:33,398 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:33,413 INFO [STDOUT] Tue Aug 24 13:53:33 CEST 2004 Eviction task finished.
13:53:38,401 INFO [STDOUT] Tue Aug 24 13:53:38 CEST 2004 New eviction task started.
13:53:38,401 ERROR [EvictionTimerTask] run(): error processing eviction with exception: org.jboss.cache.eviction.Eviction
Exception: LRUAlgorith.evict(). Node not found with this fqn: //charts/[ChartRequest 425, 60, 41, candle] will reset the
eviction list.
13:53:38,401 INFO [STDOUT] org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn
: //charts/[ChartRequest 425, 60, 41, candle]
13:53:38,401 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
13:53:38,401 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
13:53:38,401 INFO [STDOUT] at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
13:53:38,401 INFO [STDOUT] at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
13:53:38,401 INFO [STDOUT] at java.util.TimerThread.mainLoop(Timer.java:432)
13:53:38,401 INFO [STDOUT] at java.util.TimerThread.run(Timer.java:382)
13:53:38,401 INFO [STDOUT] Tue Aug 24 13:53:38 CEST 2004 Eviction task finished.


..... the same exception forever.

[uwen]

I encounter the same problem, the exception for the no-existing node is raised again and again.

Maybe the problem is again related to the Bug: [ 1013153 ] infinite loop in LRUAlgorithm.prune

There has been a discussion about this, the related bug has been closed, but I see the problematic code again in LRUAlgorithm.removeFromQueue:

ne.getPrevious().setNext(ne.getPrevious());
ne.getNext().setPrevious(ne.getNext());

This infinitely blocks the EvictionTimerTask, but maybe I am wrong?
-uwe

[ben.wang]

Can you guys try it one more time by getting the latest jboss-head? It is actually not a serious error, per se. Here is why.

What happened was in TreeCache, it will do another nodeModified event notification after the parent (leaf node has no problem) node is evicted. So you see, it will loop back to eviction policy again. And therefore could not found the evicted node.

Bela and I have found a solution to stop the notification in this case. So the problem should be solved.

If not, it is something else I need to look at.

Thanks,

-Ben

[ben.wang]

Uwe,

You are right! I thought I have fixed this in release1.02. But I couldn't find any trace in cvs log! So I am embarassed to say that I must have let it slip through. :-)

Anyway, I have just checked in to the code into jboss-head. Please grab it and re-try again.

Thanks,

-Ben

[octopus]

Ben,

Unfortunately, it's still there. I updated from cvs-head and run my testcase which I used in the beginning of this thread. It took an hour before this exception appeared. Seems somehow it depend on system load..

Uve, Could you also try to reproduce this bug to assure Ben it's a real thing?

configure(): attribute size: 23
setClusterConfig(): setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=true;mcast_addr=228.1.2.3;mcast_port=45566;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
setEvictionPolicyConfig(): [config: null]
interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
class org.jboss.cache.interceptors.TransactionInterceptor
cache mode is REPL_SYNC
unicast sockets will use interface 192.168.2.3
socket information:
local_addr=grc03:4096, mcast_addr=228.1.2.3:45566, bind_addr=/192.168.2.3, ttl=64
sock: bound to 192.168.2.3:4096, receive buffer size=80000, send buffer size=150000
mcast_recv_sock: bound to 192.168.2.3:45566, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.2.3:4097, send buffer size=150000, receive buffer size=80000

-------------------------------------------------------
GMS: address is grc03:4096
-------------------------------------------------------
state could not be retrieved (must be first member in group)
Starting eviction policy using the provider: org.jboss.cache.eviction.LRUPolicy
viewAccepted(): new members: [grc03:4096]
new cache is null (maybe first member in cluster)
Starting a eviction timer with wake up interval of (secs) 5
Tue Aug 24 21:02:27 CEST 2004 Nodes: 155
Tue Aug 24 21:02:28 CEST 2004 Nodes: 2556
Tue Aug 24 21:02:29 CEST 2004 Nodes: 5735
Tue Aug 24 21:02:30 CEST 2004 Nodes: 9410
Tue Aug 24 21:02:31 CEST 2004 Nodes: 12971
Tue Aug 24 21:02:32 CEST 2004 New eviction task started.
Tue Aug 24 21:02:32 CEST 2004 Nodes: 9177
Tue Aug 24 21:02:33 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:33 CEST 2004 Nodes: 4822
Tue Aug 24 21:02:34 CEST 2004 Nodes: 8511
Tue Aug 24 21:02:35 CEST 2004 Nodes: 12265
Tue Aug 24 21:02:36 CEST 2004 Nodes: 14853
Tue Aug 24 21:02:37 CEST 2004 New eviction task started.
Tue Aug 24 21:02:37 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:37 CEST 2004 Nodes: 1575
Tue Aug 24 21:02:38 CEST 2004 Nodes: 5325
Tue Aug 24 21:02:39 CEST 2004 Nodes: 9088
Tue Aug 24 21:02:40 CEST 2004 Nodes: 12817
Tue Aug 24 21:02:41 CEST 2004 Nodes: 15358
Tue Aug 24 21:02:42 CEST 2004 New eviction task started.
Tue Aug 24 21:02:42 CEST 2004 Nodes: 1773
Tue Aug 24 21:02:42 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:43 CEST 2004 Nodes: 5137
Tue Aug 24 21:02:44 CEST 2004 Nodes: 8920
Tue Aug 24 21:02:45 CEST 2004 Nodes: 12663
Tue Aug 24 21:02:46 CEST 2004 Nodes: 15323
Tue Aug 24 21:02:47 CEST 2004 New eviction task started.
Tue Aug 24 21:02:47 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:47 CEST 2004 Nodes: 1451
Tue Aug 24 21:02:48 CEST 2004 Nodes: 5292
Tue Aug 24 21:02:49 CEST 2004 Nodes: 8943
Tue Aug 24 21:02:50 CEST 2004 Nodes: 12695
Tue Aug 24 21:02:51 CEST 2004 Nodes: 15444
Tue Aug 24 21:02:52 CEST 2004 New eviction task started.
Tue Aug 24 21:02:52 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:52 CEST 2004 Nodes: 1845
Tue Aug 24 21:02:53 CEST 2004 Nodes: 5673
Tue Aug 24 21:02:54 CEST 2004 Nodes: 9467
Tue Aug 24 21:02:55 CEST 2004 Nodes: 13266
Tue Aug 24 21:02:56 CEST 2004 Nodes: 15762
Tue Aug 24 21:02:57 CEST 2004 New eviction task started.
Tue Aug 24 21:02:57 CEST 2004 Eviction task finished.
Tue Aug 24 21:02:57 CEST 2004 Nodes: 1625
Tue Aug 24 21:02:58 CEST 2004 Nodes: 5502
Tue Aug 24 21:02:59 CEST 2004 Nodes: 9289
Tue Aug 24 21:03:00 CEST 2004 Nodes: 13058
Tue Aug 24 21:03:01 CEST 2004 Nodes: 15618
Tue Aug 24 21:03:02 CEST 2004 New eviction task started.
Tue Aug 24 21:03:02 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:02 CEST 2004 Nodes: 1562
Tue Aug 24 21:03:03 CEST 2004 Nodes: 5309
Tue Aug 24 21:03:04 CEST 2004 Nodes: 9060
Tue Aug 24 21:03:05 CEST 2004 Nodes: 12799
Tue Aug 24 21:03:06 CEST 2004 Nodes: 15379
Tue Aug 24 21:03:07 CEST 2004 New eviction task started.
Tue Aug 24 21:03:07 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:07 CEST 2004 Nodes: 1511
Tue Aug 24 21:03:08 CEST 2004 Nodes: 5300
Tue Aug 24 21:03:09 CEST 2004 Nodes: 8993
Tue Aug 24 21:03:10 CEST 2004 Nodes: 12789
Tue Aug 24 21:03:11 CEST 2004 Nodes: 15414
Tue Aug 24 21:03:12 CEST 2004 New eviction task started.
Tue Aug 24 21:03:12 CEST 2004 Nodes: 1790
Tue Aug 24 21:03:12 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:13 CEST 2004 Nodes: 5273
Tue Aug 24 21:03:14 CEST 2004 Nodes: 9078
Tue Aug 24 21:03:15 CEST 2004 Nodes: 12824
Tue Aug 24 21:03:16 CEST 2004 Nodes: 15658
Tue Aug 24 21:03:17 CEST 2004 New eviction task started.
Tue Aug 24 21:03:17 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:17 CEST 2004 Nodes: 1729
Tue Aug 24 21:03:18 CEST 2004 Nodes: 5516
Tue Aug 24 21:03:19 CEST 2004 Nodes: 9252
Tue Aug 24 21:03:20 CEST 2004 Nodes: 13038
Tue Aug 24 21:03:22 CEST 2004 Nodes: 16253
Tue Aug 24 21:03:22 CEST 2004 New eviction task started.
Tue Aug 24 21:03:22 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:23 CEST 2004 Nodes: 2718
Tue Aug 24 21:03:24 CEST 2004 Nodes: 6433
Tue Aug 24 21:03:25 CEST 2004 Nodes: 10213
Tue Aug 24 21:03:26 CEST 2004 Nodes: 13972
Tue Aug 24 21:03:27 CEST 2004 Nodes: 17650
Tue Aug 24 21:03:27 CEST 2004 New eviction task started.
Tue Aug 24 21:03:28 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:28 CEST 2004 Nodes: 3058
Tue Aug 24 21:03:29 CEST 2004 Nodes: 6802
Tue Aug 24 21:03:30 CEST 2004 Nodes: 10575
Tue Aug 24 21:03:31 CEST 2004 Nodes: 14357
Tue Aug 24 21:03:32 CEST 2004 Nodes: 18057
Tue Aug 24 21:03:32 CEST 2004 New eviction task started.
Tue Aug 24 21:03:33 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:33 CEST 2004 Nodes: 1754
Tue Aug 24 21:03:34 CEST 2004 Nodes: 5585
Tue Aug 24 21:03:35 CEST 2004 Nodes: 9418
Tue Aug 24 21:03:36 CEST 2004 Nodes: 13182
Tue Aug 24 21:03:37 CEST 2004 Nodes: 16953
Tue Aug 24 21:03:37 CEST 2004 New eviction task started.
Tue Aug 24 21:03:38 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:38 CEST 2004 Nodes: 1911
Tue Aug 24 21:03:39 CEST 2004 Nodes: 5673
Tue Aug 24 21:03:40 CEST 2004 Nodes: 9435
Tue Aug 24 21:03:41 CEST 2004 Nodes: 13181
Tue Aug 24 21:03:42 CEST 2004 Nodes: 16629
Tue Aug 24 21:03:42 CEST 2004 New eviction task started.
Tue Aug 24 21:03:43 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:43 CEST 2004 Nodes: 2723
Tue Aug 24 21:03:44 CEST 2004 Nodes: 5791
Tue Aug 24 21:03:45 CEST 2004 Nodes: 9644
Tue Aug 24 21:03:46 CEST 2004 Nodes: 13429
Tue Aug 24 21:03:47 CEST 2004 Nodes: 17135
Tue Aug 24 21:03:47 CEST 2004 New eviction task started.
Tue Aug 24 21:03:48 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:48 CEST 2004 Nodes: 2909
Tue Aug 24 21:03:49 CEST 2004 Nodes: 6636
Tue Aug 24 21:03:50 CEST 2004 Nodes: 10382
Tue Aug 24 21:03:51 CEST 2004 Nodes: 14157
Tue Aug 24 21:03:52 CEST 2004 Nodes: 17848
Tue Aug 24 21:03:52 CEST 2004 New eviction task started.
Tue Aug 24 21:03:53 CEST 2004 Eviction task finished.
Tue Aug 24 21:03:53 CEST 2004 Nodes: 1771

-------------- cut ---------------------

Tue Aug 24 22:07:42 CEST 2004 Nodes: 10241
Tue Aug 24 22:07:43 CEST 2004 Nodes: 14143
Tue Aug 24 22:07:44 CEST 2004 Nodes: 17979
Tue Aug 24 22:07:44 CEST 2004 New eviction task started.
Tue Aug 24 22:07:45 CEST 2004 Nodes: 10275
Tue Aug 24 22:07:45 CEST 2004 Eviction task finished.
Tue Aug 24 22:07:46 CEST 2004 Nodes: 4926
Tue Aug 24 22:07:47 CEST 2004 Nodes: 8763
Tue Aug 24 22:07:48 CEST 2004 Nodes: 12519
Tue Aug 24 22:07:49 CEST 2004 Nodes: 16385
Tue Aug 24 22:07:49 CEST 2004 New eviction task started.
Tue Aug 24 22:07:49 CEST 2004 Eviction task finished.
Tue Aug 24 22:07:50 CEST 2004 Nodes: 2740
Tue Aug 24 22:07:51 CEST 2004 Nodes: 5748
Tue Aug 24 22:07:52 CEST 2004 Nodes: 9631
Tue Aug 24 22:07:53 CEST 2004 Nodes: 13518
Tue Aug 24 22:07:54 CEST 2004 Nodes: 17363
Tue Aug 24 22:07:54 CEST 2004 New eviction task started.
Tue Aug 24 22:07:54 CEST 2004 Eviction task finished.
Tue Aug 24 22:07:55 CEST 2004 Nodes: 2450
Tue Aug 24 22:07:56 CEST 2004 Nodes: 6359
Tue Aug 24 22:07:57 CEST 2004 Nodes: 10129
Tue Aug 24 22:07:58 CEST 2004 Nodes: 13859
Tue Aug 24 22:07:59 CEST 2004 Nodes: 17754
Tue Aug 24 22:07:59 CEST 2004 New eviction task started.
Tue Aug 24 22:08:00 CEST 2004 Nodes: 9040
Tue Aug 24 22:08:00 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:01 CEST 2004 Nodes: 4888
Tue Aug 24 22:08:02 CEST 2004 Nodes: 8719
Tue Aug 24 22:08:03 CEST 2004 Nodes: 12642
Tue Aug 24 22:08:04 CEST 2004 Nodes: 16549
Tue Aug 24 22:08:04 CEST 2004 New eviction task started.
Tue Aug 24 22:08:04 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:05 CEST 2004 Nodes: 2481
Tue Aug 24 22:08:06 CEST 2004 Nodes: 5538
Tue Aug 24 22:08:07 CEST 2004 Nodes: 9434
Tue Aug 24 22:08:08 CEST 2004 Nodes: 13204
Tue Aug 24 22:08:09 CEST 2004 Nodes: 17093
Tue Aug 24 22:08:09 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:09 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:10 CEST 2004 Nodes: 9830
Tue Aug 24 22:08:11 CEST 2004 Nodes: 13701
Tue Aug 24 22:08:12 CEST 2004 Nodes: 17532
Tue Aug 24 22:08:13 CEST 2004 Nodes: 21444
Tue Aug 24 22:08:14 CEST 2004 Nodes: 25268
Tue Aug 24 22:08:14 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:14 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:15 CEST 2004 Nodes: 26629
Tue Aug 24 22:08:16 CEST 2004 Nodes: 30549
Tue Aug 24 22:08:17 CEST 2004 Nodes: 34344
Tue Aug 24 22:08:18 CEST 2004 Nodes: 38063
Tue Aug 24 22:08:19 CEST 2004 Nodes: 41823
Tue Aug 24 22:08:19 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:19 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:20 CEST 2004 Nodes: 44799
Tue Aug 24 22:08:21 CEST 2004 Nodes: 48649
Tue Aug 24 22:08:22 CEST 2004 Nodes: 49852
Tue Aug 24 22:08:23 CEST 2004 Nodes: 53716
Tue Aug 24 22:08:24 CEST 2004 Nodes: 57565
Tue Aug 24 22:08:24 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:24 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:25 CEST 2004 Nodes: 60343
Tue Aug 24 22:08:26 CEST 2004 Nodes: 64198
Tue Aug 24 22:08:27 CEST 2004 Nodes: 67816
Tue Aug 24 22:08:28 CEST 2004 Nodes: 71511
Tue Aug 24 22:08:29 CEST 2004 Nodes: 75386
Tue Aug 24 22:08:29 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:29 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:30 CEST 2004 Nodes: 78233
Tue Aug 24 22:08:31 CEST 2004 Nodes: 82075
Tue Aug 24 22:08:32 CEST 2004 Nodes: 85900
Tue Aug 24 22:08:33 CEST 2004 Nodes: 86203
Tue Aug 24 22:08:34 CEST 2004 New eviction task started.
Tue Aug 24 22:08:34 CEST 2004 Nodes: 89865
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
Tue Aug 24 22:08:34 CEST 2004 Eviction task finished.
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:35 CEST 2004 Nodes: 93097
Tue Aug 24 22:08:36 CEST 2004 Nodes: 96855
Tue Aug 24 22:08:37 CEST 2004 Nodes: 100437
Tue Aug 24 22:08:39 CEST 2004 Nodes: 101307
Tue Aug 24 22:08:39 CEST 2004 New eviction task started.
Tue Aug 24 22:08:41 CEST 2004 Nodes: 102455
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:41 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:43 CEST 2004 Nodes: 105320
Tue Aug 24 22:08:44 CEST 2004 Nodes: 107149
Tue Aug 24 22:08:44 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:44 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:46 CEST 2004 Nodes: 108657
Tue Aug 24 22:08:48 CEST 2004 Nodes: 110482
Tue Aug 24 22:08:50 CEST 2004 New eviction task started.
Tue Aug 24 22:08:50 CEST 2004 Nodes: 112385
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:50 CEST 2004 Eviction task finished.
Tue Aug 24 22:08:52 CEST 2004 Nodes: 113787
Tue Aug 24 22:08:53 CEST 2004 Nodes: 115618
Tue Aug 24 22:08:55 CEST 2004 New eviction task started.
Tue Aug 24 22:08:55 CEST 2004 Nodes: 117079
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
Tue Aug 24 22:08:55 CEST 2004 Eviction task finished.
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:08:57 CEST 2004 Nodes: 118021
Tue Aug 24 22:08:59 CEST 2004 Nodes: 119145
Tue Aug 24 22:09:01 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:09:01 CEST 2004 Eviction task finished.
Tue Aug 24 22:09:01 CEST 2004 Nodes: 120101
Tue Aug 24 22:09:02 CEST 2004 Nodes: 120474
Tue Aug 24 22:09:04 CEST 2004 Nodes: 121162
Tue Aug 24 22:09:05 CEST 2004 Nodes: 121693
Tue Aug 24 22:09:07 CEST 2004 New eviction task started.
Tue Aug 24 22:09:07 CEST 2004 Nodes: 122095
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /charts/node168549
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Tue Aug 24 22:09:07 CEST 2004 Eviction task finished.
Tue Aug 24 22:09:09 CEST 2004 Nodes: 122267
Tue Aug 24 22:09:10 CEST 2004 Nodes: 122582
org.jboss.util.NestedRuntimeException: - nested throwable: (java.lang.OutOfMemoryError)
 at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:3180)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1742)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1725)
 at test.com.dukascopy.mt.data.TestCache$1.run(TestCache.java:63)
Caused by: java.lang.OutOfMemoryError
java.lang.OutOfMemoryError
java.lang.OutOfMemoryError
org.jboss.util.NestedRuntimeException: - nested throwable: (java.lang.OutOfMemoryError)
 at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:3180)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1742)
 at org.jboss.cache.TreeCache.put(TreeCache.java:1725)
 at test.com.dukascopy.mt.data.TestCache$1.run(TestCache.java:63)
Caused by: java.lang.OutOfMemoryError

[uwen]

Hi,
I can easily reproduce the java.lang.OutOfMemoryError with the testcase,
but I am not sure - if this is really a bug.
Could it be possible, that simply the parameters in local-eviction-service.xml are not optimal for the use case and the environment?
-uwe

[ben.wang]

Guys,

I don't think it is a bug. I can also re-produce the OOM error myself here as well. The key is the load is simply not realistic if we have multiple threads that are generating put and get all the time and thus exhibiting 100% CPU.

A more realistic use case will requires a random sleep in between put/get so the eviction timer has time to pocess those.

In another persective, to tune it up, you can decrease the parameter "wakeUpIntervaleSeconds" so the timer wakes up more often. But again there is a limit that it can do that, especially, when it is *local* mode of which put/get is really quick.

If it is replicated mode, then the bottle neck will probably not be CPU bound anymore.

Thanks a lot for all your help.

-Ben

[ben.wang]

Guys,

I don't think it is a bug. I can also re-produce the OOM error myself here as well. The key is the load is simply not realistic if we have multiple threads that are generating put and get all the time and thus exhibiting 100% CPU.

A more realistic use case will requires a random sleep in between put/get so the eviction timer has time to pocess those.

In another persective, to tune it up, you can decrease the parameter "wakeUpIntervaleSeconds" so the timer wakes up more often. But again there is a limit that it can do that, especially, when it is *local* mode of which put/get is really quick.

If it is replicated mode, then the bottle neck will probably not be CPU bound anymore.

Thanks a lot for all your help.

-Ben

[octopus]

Uwen, Ben,

Of course I do not consider this particular out of memory exception as a bug.
The thing is OutOfMem CAUSED by exception which is this thread's topic.

In my last post - take a look - first this exception appeared, it repeated with each eviction cycle effectively stopping eviction.
This caused rising number of nodes far behind maxNodes limit, and, AS A RESULT, OutOfMem.

Again, as you see in my last post's log extracts, cache keeps trying to remove the same node, _which is not exitst in cache at the moment_, causing exception. THIS is a bug, imho.

Thanks,

[octopus]

Ben,

Here's a test unit which reproduces this bug in 100% run. default local-eviction-service.xml is taken with no changes. _defatlt_ region is used with maxModes=5000. Here it is:

 public void test2() throws Exception {
 cache = new TreeCache();
 PropertyConfigurator config = new PropertyConfigurator();
 config.configure(cache, "META-INF/local-eviction-service.xml");
 cache.setTransactionManagerLookupClass("org.jboss.cache.DummyTransactionManagerLookup");
 cache.start();

 for (int i = 0; i < 50; i++) {
 new Thread() {
 public void run() {
 while (true) {
 int i = (int) (Math.random() * 10000);
 try {
 cache.put("/test/node"+i, "value", new Integer(i));
 Thread.sleep(10);
 } catch (Exception e) {
 e.printStackTrace();
 }
 }
 }
 }.start();
 }

 while (true) {
 Node node = cache.get("/test");
 int count = node == null || node.getChildren() == null ? 0 : node.getChildren().size();
 log.info(new Date() + " Nodes: " + count);
 Thread.sleep(1000);
 }

 }

Here is the output a get:

configure(): attribute size: 19
setClusterConfig(): setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=false;mcast_addr=228.1.2.3;mcast_port=45566;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD(down_thread=true;shun=true;up_thread=true):VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=false;up_thread=false)
setEvictionPolicyConfig(): [config: null]
interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.TransactionInterceptor
cache mode is local, will not create the channel
Starting eviction policy using the provider: org.jboss.cache.eviction.LRUPolicy
Starting a eviction timer with wake up interval of (secs) 5
Thu Aug 26 12:03:23 CEST 2004 Nodes: 105
Thu Aug 26 12:03:24 CEST 2004 Nodes: 2247
Thu Aug 26 12:03:25 CEST 2004 Nodes: 4242
Thu Aug 26 12:03:26 CEST 2004 Nodes: 5934
Thu Aug 26 12:03:27 CEST 2004 Nodes: 6987
Thu Aug 26 12:03:28 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test/node2704 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test/node2704
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Thu Aug 26 12:03:28 CEST 2004 Eviction task finished.
Thu Aug 26 12:03:29 CEST 2004 Nodes: 7651
Thu Aug 26 12:03:30 CEST 2004 Nodes: 8262
Thu Aug 26 12:03:31 CEST 2004 Nodes: 8720
Thu Aug 26 12:03:32 CEST 2004 Nodes: 9122
Thu Aug 26 12:03:33 CEST 2004 Nodes: 9388
Thu Aug 26 12:03:33 CEST 2004 New eviction task started.
run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test/node2704 will reset the eviction list.
org.jboss.cache.eviction.EvictionException: LRUAlgorith.evict(). Node not found with this fqn: /test/node2704
 at org.jboss.cache.eviction.LRUAlgorithm.evict(LRUAlgorithm.java:623)
 at org.jboss.cache.eviction.LRUAlgorithm.prune(LRUAlgorithm.java:565)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:111)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)
Thu Aug 26 12:03:33 CEST 2004 Eviction task finished.
Thu Aug 26 12:03:34 CEST 2004 Nodes: 9548
Thu Aug 26 12:03:35 CEST 2004 Nodes: 9648

Hint: when i change
int i = (int) (Math.random() * 10000); // creates node0...node9999
to say
int i = (int) (Math.random() * 1000000000);
it disappears.
Taking into account that maxNodes=5000 it seems that exception appears then I putting the same node which is already exists and enlisted for eviction... something like this.

[octopus]

Ben, just to assure it's not an artificial case: the bug appears in my real application where cache is to cache stock charts which are produced in relatively long time but frequently requested from web (8-digit requests daily).
I reproduce this bug just running some 10 threads in JMeter making web requests, which is far less then it's going to be in production.

Thanks,