Clearing the cache

[drosenbaum]

I used the following code to remove all the nodes (all parents and children) in a TreeCache:

TreeCache cache = ....
Fqn root = cache.get("/").getFqn();
cache.remove(root);

However shortly after this I get messages such as the following in the logs:

[QW]21 Feb 2006 11:00:29,012 WARN org.jboss.cache.eviction.LRUAlgorithm - DataNode not found with this fqn: //org/ifmc/qies/qw/data/po/QwDataGrpVw Could have been evicted earlier already
[QW]21 Feb 2006 11:00:29,037 ERROR org.jboss.cache.eviction.EvictionTimerTask - run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: internal error. Can't find fqn in nodeMap. fqn: //org/ifmc/qies/qw/data/po/QwDataGrpVw will reset the eviction queue list.
[QW]21 Feb 2006 11:00:29,047 WARN org.jboss.cache.eviction.LRUAlgorithm - DataNode not found with this fqn: //org/ifmc/qies/qw/data/po/QwUserDfltOptn Could have been evicted earlier already
[QW]21 Feb 2006 11:00:29,047 ERROR org.jboss.cache.eviction.EvictionTimerTask - run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: internal error. Can't find fqn in nodeMap. fqn: //org/ifmc/qies/qw/data/po/QwUserDfltOptn will reset the eviction queue list.
[QW]21 Feb 2006 11:00:29,053 WARN org.jboss.cache.eviction.LRUAlgorithm - DataNode not found with this fqn: //org/ifmc/qies/qw/data/po/QwUserVw Could have been evicted earlier already
[QW]21 Feb 2006 11:00:29,054 ERROR org.jboss.cache.eviction.EvictionTimerTask - run(): error processing eviction with exception: org.jboss.cache.eviction.EvictionException: internal error. Can't find fqn in nodeMap. fqn: //org/ifmc/qies/qw/data/po/QwUserVw will reset the eviction queue list.

Is this an improper way to clear the cache? Is so, what is the correct method? And what are the consequences (if any) of having these log messages, would this cause a memory leak or anything else or are these benign messages and can be ignored?

Thank you,
Daniel

[belaban]

I think these are just error messages, because the eviction thread added the nodes to the queue and later - when trying to remove those - they were already removed, so these are no-ops.

[drosenbaum]

Thanks Bela for responding. But is this the correct way to clear the cache? Or is there some other proper method or API that I missed (and prefereably would not result in these error messages)?

[belaban]

No, you're doing the right thing. The question for the eviction guys is whether we retry an eviction if we cannot find the element in the cache, or whether we remove the eviction element from the queue...
I hope/think we do the latter

[drosenbaum]

Could one of the "eviction guys" please comment on this issue? Or should I file a bug report?

Thanks once again,
Daniel

[ben.wang]

Daniel,

I am the cache guy. :-)

I assume you can reproduce this everytime? If so, can you open up a Jira and attach your unit test case? Btw, what is the JBossCache release that you used?

Yes, the remove method is supposed to remove it from the eviction queue so it won't get evicted again.

The EvictTimerTask error is an internal exception thrown from the eviction policy. It is probably something to do with your remove("/").

I tried to re-produce it but I can't.

Thanks,

-Ben

[drosenbaum]

Thanks Ben for responding. Unfortunatly it does not happen every time. All I know is that I have had an application running with JBossCache for about 6 months now and I get messages such as this about once a week or 2, sometimes more often and sometimes less.

I have a process that runs every morning at 4 am and clears the cache, as I would like to start fresh each day with new data. There are times we need to clear the cache manually as well, such as if we modify the underlying data in the database and need our web app to use the new data. This does not happen often but there are times when it is necessary.

I suspect (though I have no way to prove) that these messages appear when elements are put in the queue for eviction, but before the thread gets around to actually evicting the elements the remove("/") is called, so the elements are no longer in the cache when the EvictTimerTask tries to remove it. Does this make any sense? I have no idea how to write a unit test for this though and is probably difficult to reproduce.

I am now using version 1.2.4SP1 the last few weeks and 1.2.2 previously, and I am seeing these log messages in both versions.

Thank you,
Daniel

[drosenbaum]

One other thought, you say that "the remove method is supposed to remove it from the eviction queue". When I call remove("/"), are all child elements of that node also being removed from the eviction queue? And the children's children at all levels of the subtree? Maybe what is happening is that only the root element is being removed from the eviction queue but not the descendants?

[ben.wang]

No, since remove("/") is recursive, so it should be removing each sub-node as well. Like I said, I have a temporary test case trying to re-produce it but couldn't.

Is there any complicated test that you are doing there?

[drosenbaum]

After working for a while I was able to come up with a JUnit test case that reproduces this. The code is below. I started with the org.jboss.cache.eviction.LRUPolicyTest class and added the following test:

public void testForEvictionInternalError() {
 try {
 String rootStr = "/test/testdata";

 for (int i = 0; i < 10; i++) {
 String str = rootStr + i;
 Fqn fqn = Fqn.fromString(str);
 try {
 cache_.put(fqn, str, str);
 } catch (Exception e) {
 fail("Failed to insert data" + e);
 e.printStackTrace();
 }
 }

 // wait for an eviction
 _sleep(2 * wakeupIntervalMillis_ + 1000);

 String val = (String) cache_.get(rootStr + "3", rootStr + "3");
 assertNull("DataNode should be empty ", val);

 // reinsert the elements
 for (int i = 0; i < 10; i++) {
 String str = rootStr + i;
 Fqn fqn = Fqn.fromString(str);
 try {
 cache_.put(fqn, str, str);
 } catch (Exception e) {
 fail("Failed to insert data" + e);
 e.printStackTrace();
 }
 }

 // clear the root
 Fqn root = cache_.get("/").getFqn();
 cache_.remove(root);

 // wait for an eviction
 _sleep(2 * wakeupIntervalMillis_ + 1000);

 val = (String) cache_.get(rootStr + "3", rootStr + "3");
 assertNull("DataNode should be empty ", val);

 } catch (Exception e) {
 e.printStackTrace();
 fail("Failed to get" + e);
 }
 }

on almost all the executions I end up having the following log statement somewhere:

org.jboss.cache.eviction.EvictionException: internal error. Can't find fqn in nodeMap. fqn: /test
 at org.jboss.cache.eviction.LRUAlgorithm.removeFromQueue(LRUAlgorithm.java:215)
 at org.jboss.cache.eviction.LRUAlgorithm.processRemovedNodes(LRUAlgorithm.java:107)
 at org.jboss.cache.eviction.LRUAlgorithm.processQueues(LRUAlgorithm.java:80)
 at org.jboss.cache.eviction.LRUAlgorithm.process(LRUAlgorithm.java:53)
 at org.jboss.cache.eviction.EvictionTimerTask.run(EvictionTimerTask.java:37)
 at java.util.TimerThread.mainLoop(Timer.java:432)
 at java.util.TimerThread.run(Timer.java:382)

I did not figure out a way to ALWAYS get this message but it appears in the majority of runs. Note that you need to actually look at the log to see it, the test itself always passes, so it is not sufficient to wait for a test to fail.

What I think is now happening is when you insert a node, wait until it gets evicted by the system, and then reinsert the same node and call cache.remove("/"), the log message appears after that. (But I am not sure of all this)

Please let me know if this test produces this log warning for you as well.

Thank you,
Daniel

[ben.wang]

OK, let me see if I can reproduce it. Will post my finding here.

-Ben

[ben.wang]

Daniel,

OK, I have created this Jira:
http://jira.jboss.com/jira/browse/JBCACHE-494

that explains the cause and fix as well.

Since IMO this is a corner case, we won't provide an official patch. However, you can build jboss-cache.jar yourself:

cvs co -r Branch_JBossCache_1_2_4_SP2 JBossCache

Do buiild jar

Please wait for one day for the cvs to propagate.

Thanks for your help,

-Ben

[ben.wang]

I just attached jboss-cache for the unofficial 1.2.4SP2 patch in the Jira, please check it out.

[drosenbaum]

Thank you Ben for resolving this.

Cheers,
Daniel

[drosenbaum]

One comment though, could it be made into a debug or info message rather than a warning? I have my logs configured to show warnings and would rather not see such log messages at all, since it is not really a problem. I am not sure why it deserves a level of warn.