You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cocoon.apache.org by Peter Hargreaves <pd...@totalise.co.uk> on 2002/01/26 15:24:38 UTC
Store Janitor Hangs System
Hi Gerhard and Team,
I'm posting in this group now I think I found a design problem with
store-janitor.
I think store-janitor works fine when it can free sufficient memory by
calling the finalize and garbage collection. But if it needs to free the
store it locks up!
The reason it appears to lock up (I think), is because it calls the
garbage collector too often - i.e. every time it frees an item from a
store. Once called the store-janitor will free an item and call the
garbage collector, repeating both until it has freed sufficient memory.
If one item frees 4.44k and the garbage collector takes 2844ms then the
time taken to free 20m will be 3.5 hours - during which time the system
appears to be locked!
The following is a brief summary of my analysis:
With the following settings:
Xms=0m
Xmx=140m
heapsize =100000000
freememory=20000000
Using Optimizeit I watched my java heap 'total' and 'in-use' growing.
When total heapsize gets to 100m the store-janitor kicks in and frees a
chunk of memory. This repeats every ten seconds but each time it frees
less memory until it is no longer able to free memory and locks up. When
locked up the garbage collector is running about 99% of the time.
Looking at the store-janitor code and my debug log I can see exactly
what happens when it locks.
I notice, examining Store-janitorImpl.run() that, if the garbage
collector alone manages to clear sufficient memory, no store items are
cleared (as expected). This is possibly all that is happening when
store-janitor appears to work! However if that is not sufficient the
following loop is started.
synchronized (this) {
while (this.memoryLow() &&
this.getStoreList().size() > 0) {
this.freeMemory();
}
this.resetIndex();
}
this.memoryLow() tests to see if sufficient is free and prints Debug info.
this.freeMemory() removes an item, runs garbage collection, and prints
Debug info.
From my log files I can see this loop being executed. Each time round
the loop I can see how much memory is freed and how long it takes.
Typically it can take seconds to free one item which can be only a few
kb. So, in my case with 'freememory' set to 20m, it is likely to take a
few hours to free sufficient memory!!
I've noticed when running Optimizeit that although garbage collection
can be quick, it sometimes takes a few seconds. If it has just been run,
and you force it to run again, then it seems to take longer. If it can't
find much to freeup, it seems to do a more time consuming search for
garbage.
I hope the above is useful.
Regards,
Peter
"listen to what I mean, not what I say" - pdh
Gateway G6-350 (392,612 RAM), NT4.0sp6, jdk-1.3.1, tomcat-4.0.1, cocoon-2.0
Gateway G6-350 (392,612 RAM), RH Linux 7.0, jdk-1.3, tomcat-4.0.1,
cocoon-2.0
DEBUG (2002-01-25) 16:51.17:329 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.17:340 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.17:350 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=12452688
DEBUG (2002-01-25) 16:51.17:350 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.17:360 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Invoking garbage collection, total
memory = 100818936, free memory = 12441344
DEBUG (2002-01-25) 16:51.21:465 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Garbage collection complete, total
memory = 100818936, free memory = 16026880
DEBUG (2002-01-25) 16:51.21:475 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.21:485 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.21:485 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16009608
DEBUG (2002-01-25) 16:51.21:495 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.21:506 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.21:506 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.21:516 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=-1
DEBUG (2002-01-25) 16:51.21:526 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=-1
DEBUG (2002-01-25) 16:51.21:526 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=0
DEBUG (2002-01-25) 16:51.24:370 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=0
DEBUG (2002-01-25) 16:51.24:380 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.24:410 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.24:410 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16014048
DEBUG (2002-01-25) 16:51.24:420 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.24:430 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.24:430 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.24:440 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=0
DEBUG (2002-01-25) 16:51.24:440 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=0
DEBUG (2002-01-25) 16:51.24:450 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=1
DEBUG (2002-01-25) 16:51.25:882 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=1
DEBUG (2002-01-25) 16:51.25:942 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.25:952 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.25:952 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16006624
DEBUG (2002-01-25) 16:51.25:962 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.25:972 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.25:972 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.25:982 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=1
DEBUG (2002-01-25) 16:51.25:982 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=1
DEBUG (2002-01-25) 16:51.25:992 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=2
DEBUG (2002-01-25) 16:51.26:002 [root.xsl]
(/self-roster/data/usergroups.html)
HttpProcessor[8080][4]/XSLTProcessorImpl: XSLTProcessorImpl:
resolve(href = ../../data/00298/group.xml, base =
file:/J:/jakarta-tomcat-4.0.1/webapps/self-roster/stylesheets/data/usergroups-dir2html.xsl);
resolver = org.apache.cocoon.environment.http.HttpEnvironment@18972b3
DEBUG (2002-01-25) 16:51.27:104 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=2
DEBUG (2002-01-25) 16:51.27:114 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.27:124 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.27:124 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16006288
DEBUG (2002-01-25) 16:51.27:134 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.27:214 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.27:224 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.27:234 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=2
DEBUG (2002-01-25) 16:51.27:244 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=2
DEBUG (2002-01-25) 16:51.27:254 [root.sto] (Unknown-URI)
Unknown-thread/MRUMemoryStore: Freeing cache
DEBUG (2002-01-25) 16:51.27:254 [root.sto] (Unknown-URI)
Unknown-thread/MRUMemoryStore: Cache size=0
DEBUG (2002-01-25) 16:51.27:264 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=3
DEBUG (2002-01-25) 16:51.30:549 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=3
DEBUG (2002-01-25) 16:51.30:559 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.30:569 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.30:589 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16009144
DEBUG (2002-01-25) 16:51.30:599 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.30:609 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.30:619 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.30:619 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=3
DEBUG (2002-01-25) 16:51.30:639 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Starting from the beginning
DEBUG (2002-01-25) 16:51.30:639 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Reseting index
DEBUG (2002-01-25) 16:51.30:659 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=0
DEBUG (2002-01-25) 16:51.32:041 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=0
DEBUG (2002-01-25) 16:51.32:051 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.32:061 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.32:071 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16011760
DEBUG (2002-01-25) 16:51.32:081 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.32:081 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.32:101 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.32:101 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=0
DEBUG (2002-01-25) 16:51.32:111 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=0
DEBUG (2002-01-25) 16:51.32:121 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=1
DEBUG (2002-01-25) 16:51.33:232 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=1
DEBUG (2002-01-25) 16:51.33:232 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.33:242 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.33:252 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16011808
DEBUG (2002-01-25) 16:51.33:252 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.33:262 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.33:272 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.33:272 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=1
DEBUG (2002-01-25) 16:51.33:282 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=1
DEBUG (2002-01-25) 16:51.33:282 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=2
DEBUG (2002-01-25) 16:51.34:384 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=2
DEBUG (2002-01-25) 16:51.34:394 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.34:414 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.34:424 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16011808
DEBUG (2002-01-25) 16:51.34:424 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.34:444 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.34:444 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.34:454 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=2
DEBUG (2002-01-25) 16:51.34:464 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=2
DEBUG (2002-01-25) 16:51.34:464 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=3
DEBUG (2002-01-25) 16:51.34:484 [root.xsl]
(/self-roster/data/usergroups.html)
HttpProcessor[8080][4]/XSLTProcessorImpl: xslSource =
org.apache.cocoon.components.source.URLSource@154f302, system id =
file:/J:/jakarta-tomcat-4.0.1/webapps/self-roster/stylesheets/data/../../data/00298/group.xml
DEBUG (2002-01-25) 16:51.35:436 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=3
DEBUG (2002-01-25) 16:51.35:526 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.35:536 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.35:536 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16001024
DEBUG (2002-01-25) 16:51.35:606 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.35:616 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.35:616 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.35:666 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=3
DEBUG (2002-01-25) 16:51.35:666 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Starting from the beginning
DEBUG (2002-01-25) 16:51.35:676 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Reseting index
DEBUG (2002-01-25) 16:51.35:686 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=0
DEBUG (2002-01-25) 16:51.36:587 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=0
DEBUG (2002-01-25) 16:51.36:617 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.36:627 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.36:627 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16008160
DEBUG (2002-01-25) 16:51.36:637 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.36:647 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.36:647 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.36:657 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=0
DEBUG (2002-01-25) 16:51.36:667 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=0
DEBUG (2002-01-25) 16:51.36:667 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=1
DEBUG (2002-01-25) 16:51.37:749 [root.xsl]
(/self-roster/data/usergroups.html)
HttpProcessor[8080][4]/XSLTProcessorImpl: XSLTProcessorImpl:
resolve(href = ../../data/00299/group.xml, base =
file:/J:/jakarta-tomcat-4.0.1/webapps/self-roster/stylesheets/data/usergroups-dir2html.xsl);
resolver = org.apache.cocoon.environment.http.HttpEnvironment@18972b3
DEBUG (2002-01-25) 16:51.37:749 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=1
DEBUG (2002-01-25) 16:51.37:799 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.37:809 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.37:819 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16000200
DEBUG (2002-01-25) 16:51.37:819 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.37:829 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.37:829 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.37:839 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=1
DEBUG (2002-01-25) 16:51.37:849 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=1
DEBUG (2002-01-25) 16:51.37:849 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=2
DEBUG (2002-01-25) 16:51.38:810 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=2
DEBUG (2002-01-25) 16:51.38:810 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.38:820 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.38:830 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16013064
DEBUG (2002-01-25) 16:51.38:830 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.38:840 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.38:850 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.38:850 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=2
DEBUG (2002-01-25) 16:51.38:870 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=2
DEBUG (2002-01-25) 16:51.38:880 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=3
DEBUG (2002-01-25) 16:51.39:952 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=3
DEBUG (2002-01-25) 16:51.39:952 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.40:012 [root.xsl]
(/self-roster/data/usergroups.html)
HttpProcessor[8080][4]/XSLTProcessorImpl: xslSource =
org.apache.cocoon.components.source.URLSource@154f60c, system id =
file:/J:/jakarta-tomcat-4.0.1/webapps/self-roster/stylesheets/data/../../data/00299/group.xml
DEBUG (2002-01-25) 16:51.40:022 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.40:032 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=15998968
DEBUG (2002-01-25) 16:51.40:042 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.40:042 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.40:052 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.40:062 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=3
DEBUG (2002-01-25) 16:51.40:062 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Starting from the beginning
DEBUG (2002-01-25) 16:51.40:072 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Reseting index
DEBUG (2002-01-25) 16:51.40:082 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=0
DEBUG (2002-01-25) 16:51.41:004 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=0
DEBUG (2002-01-25) 16:51.41:004 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.41:014 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.41:024 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16010592
DEBUG (2002-01-25) 16:51.41:024 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.41:034 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.41:044 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.41:044 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=0
DEBUG (2002-01-25) 16:51.41:054 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=0
DEBUG (2002-01-25) 16:51.41:064 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=1
DEBUG (2002-01-25) 16:51.42:195 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index after=1
DEBUG (2002-01-25) 16:51.42:225 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().totalMemory()=100818936
DEBUG (2002-01-25) 16:51.42:235 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getHeapsize()=100000000
DEBUG (2002-01-25) 16:51.42:235 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getJVM().freeMemory()=16007976
DEBUG (2002-01-25) 16:51.42:245 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: getFreememory()=20000000
DEBUG (2002-01-25) 16:51.42:255 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreJanitor freeing memory!
DEBUG (2002-01-25) 16:51.42:255 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: StoreList size=3
DEBUG (2002-01-25) 16:51.42:265 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Index before=1
DEBUG (2002-01-25) 16:51.42:275 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Freeing at index=1
DEBUG (2002-01-25) 16:51.42:275 [root.sto] (Unknown-URI)
Unknown-thread/StoreJanitorImpl: Setting index=2
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org
Re: Store Janitor Hangs System
Posted by Sylvain Wallez <sy...@anyware-tech.com>.
Stefano Mazzocchi wrote:
<snip/>
>
>Be careful when going down this road: the JLS doesn't say anything about
>'how' the weak references should be cleaned. And Java 1.3 implements it
>in the most memory efficient possible way: if the GC gets a weak
>reference, all of them are removed.
>
>Now, imagine the case: you have spent a couple of hours building up and
>tuning your cache using highly complex statistical analysis... but you
>saved them into a store that is implemented using weak references.
>
>You hit the heap ceiling and the GC kicks in.
>
>If finds one of those weak references, but it doesn't have the ability
>to ask you (well, the store) about 'which is weaker', so, wooosh,
>everything is gone.
>
>Sure, you probably collect 40Mb or heap, but then your perceived
>performance drops and your cache system works in a 'saw-like' figure
>
>
>cache size
> ^
> | /| /|
> | / | / |
> | / | / |
> | / |/ |/
> +-----------------> time
> ^
> GC kicks in
>
>and since the cache size is linearly proportional with the perceived
>efficiency of the cache, Cocoon will appear to be 'fast at times' (to be
>kind) or 'awefully bumping' (to be more reasonable).
>
>The solution I thought for this problem is simple but I don't know if it
>works (never tested it real life):
>
> 1) partition the memory store into 'clusters' which are connected using
>hard references.
>
> 2) these 'clusters' are the real containers of the stored entities and
>such entities are weak-referenced from the 'clusters'
>
>The idea is to have something like this:
>
> store +==> cluster +---> entity
> | +---> entity
> | +---> entity
> |
> +==> cluster +---> entity
> +---> entity
> +---> entity
>
>where:
>
> ===> hard reference
> ---> soft reference
>
Are you meaning "soft" or "weak" reference ?
Soft references (java.lang.ref.SoftReference) should be good to look at,
since the GC is smarter with them : only the least recently used
references are cleared. The javadoc for SoftReference even gives some
hints to implement caches.
Also, here are two cache systems I know of (without having studied
them). Maybe they're worth looking at :
- http://jpolycache.sourceforge.net/
- http://www.opensymphony.com/oscache/
>
>
>and the key concept is that, whenever the GC needs to free some memory
>that is occupied by weak references, the avalanche cleanup will be
>'stopped' at a cluster level, saving the other clusters.
>
>Now, I'm not sure this works, but if it does, we have a reasonable
>solution to the problem.
>
>>Sorry for all that crap with Store and everything.
>>
>Don't worry, it takes time to do it right but I'm sure we'll get there.
>
>Probably we need to discuss its design *before* implementing it :)
>
Design before coding is always a good thing ;)
Sylvain
--
Sylvain Wallez
Anyware Technologies - http://www.anyware-tech.com
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org
RE: Store Janitor Hangs System
Posted by Gerhard Froehlich <g-...@gmx.de>.
Ok guys,
I fixed that bug more or less quick and dirty:
The loop which removes objects out of the stores
is only iterated once, now. I also removed the
call of the gc in the loop. The next Thread
iteration calls the gc next:
run() {
if(memoryIsLow) {
call gc
while(memoryIsStillLow && Iteration < 1) {
free some objects ot of the reg. stores
count iteration +1
}
}
thread sleeps
}
Not very creative, I know.
Gerhard
"Eagles may soar, but weasels don't get
sucked into jet engines.
(Todd C. Somers)"
>-----Original Message-----
>From: Gerhard Froehlich [mailto:g-froehlich@gmx.de]
>Sent: Sunday, January 27, 2002 2:30 PM
>To: cocoon-dev@xml.apache.org
>Subject: RE: Store Janitor Hangs System
>
>
>Hi,
>
>>From: Stefano Mazzocchi [mailto:stefano@apache.org]
>>
>>Gerhard Froehlich wrote:
>>>
>>> Hi,
>>>
>>> >From: Peter Hargreaves [mailto:pdh@totalise.co.uk]
>>> >
>>> >Hi Gerhard and Team,
>>> >
>>> >I'm posting in this group now I think I found a design problem with
>>> >store-janitor.
>>>
>>> Slowly but constant this Store issues are a PITA for me :-/. I don't know
>>> why this is in Java that difficult to control a little bit memory.
>>> That's the price for automatic Memory Management!
>>> (Nothing against you Peter!)
>>
>>Eh, if you look at the VM problems in Linux 2.4 you'll see that this
>>realm is a complex one itself and now just because it's java (sure, java
>>doesn't help you when it hides everything from you, like in this case).
>
>Complex is the point.
>
>>> >I think store-janitor works fine when it can free sufficient memory by
>>> >calling the finalize and garbage collection. But if it needs to free the
>>> >store it locks up!
>>> >
>>> >The reason it appears to lock up (I think), is because it calls the
>>> >garbage collector too often - i.e. every time it frees an item from a
>>> >store. Once called the store-janitor will free an item and call the
>>> >garbage collector, repeating both until it has freed sufficient memory.
>>> >If one item frees 4.44k and the garbage collector takes 2844ms then the
>>> >time taken to free 20m will be 3.5 hours - during which time the system
>>> >appears to be locked!
>>
>>Ouch! that hurts!
>
>Yep, I still recover from that ;).
>
>>> >The following is a brief summary of my analysis:
>>> >
>>> >With the following settings:
>>> >Xms=0m
>>> >Xmx=140m
>>> >heapsize =100000000
>>> >freememory=20000000
>>> >
>>> >Using Optimizeit I watched my java heap 'total' and 'in-use' growing.
>>> >When total heapsize gets to 100m the store-janitor kicks in and frees a
>>> >chunk of memory. This repeats every ten seconds but each time it frees
>>> >less memory until it is no longer able to free memory and locks up. When
>>> >locked up the garbage collector is running about 99% of the time.
>>
>>That's *very* bad!
>
>Indeed!
>
>>> >Looking at the store-janitor code and my debug log I can see exactly
>>> >what happens when it locks.
>>> >
>>> >I notice, examining Store-janitorImpl.run() that, if the garbage
>>> >collector alone manages to clear sufficient memory, no store items are
>>> >cleared (as expected). This is possibly all that is happening when
>>> >store-janitor appears to work! However if that is not sufficient the
>>> >following loop is started.
>>> >
>>> > synchronized (this) {
>>> > while (this.memoryLow() &&
>>> >this.getStoreList().size() > 0) {
>>> > this.freeMemory();
>>> > }
>>> > this.resetIndex();
>>> > }
>>> >
>>> >this.memoryLow() tests to see if sufficient is free and prints Debug info.
>>> >this.freeMemory() removes an item, runs garbage collection, and prints
>>> >Debug info.
>>> >
>>> > From my log files I can see this loop being executed. Each time round
>>> >the loop I can see how much memory is freed and how long it takes.
>>> >Typically it can take seconds to free one item which can be only a few
>>> >kb. So, in my case with 'freememory' set to 20m, it is likely to take a
>>> >few hours to free sufficient memory!!
>>> >
>>> >I've noticed when running Optimizeit that although garbage collection
>>> >can be quick, it sometimes takes a few seconds. If it has just been run,
>>> >and you force it to run again, then it seems to take longer. If it can't
>>> >find much to freeup, it seems to do a more time consuming search for
>>> >garbage.
>>>
>>> This all makes sense too me.
>>> Then we need a limit how often the GC can be called. Maybe 100 loops
>>> should be enough.
>>
>>I don't get it: why more than one loop? I mean, if you call the GC, it
>>should free all the memory that it can... doing any more loops at that
>>time, will not change anything.
>
>Maybe I did something wrong. But the idea was that:
>
>while(MemoryIsLow) {
> free objects out of the store //physicall
> run gc
>}
>
>I run the GC after each "free objects" to clean away
>does not needed objects!
>
>The problem is now, that when he doesn't has anything
>to free from the registered stores, he runs the GC
>all the time. And then we have this endless loop!
>
>Therefore I should check if the Stores are empty. If they
>are empty and there is nothing to free anymore we should
>leave that loop.
>
>>> After that it waits as configured (threadinterval)
>>> before the next execution.
>>>
>>> Maybe there is a more elegent solution.
>>
>>Well, this is a very difficult realm, as I said, but sure, we can start
>>a redesign phase on this.
>
>We should!
>
>>> I actually develop in jakarta-commons a store (again) with Weak References.
>>> This is a much better solution. No Threads, no GC calls. When it is ready
>>> to introduce I'll explain you!
>>
>>Be careful when going down this road: the JLS doesn't say anything about
>>'how' the weak references should be cleaned. And Java 1.3 implements it
>>in the most memory efficient possible way: if the GC gets a weak
>>reference, all of them are removed.
>>
>>Now, imagine the case: you have spent a couple of hours building up and
>>tuning your cache using highly complex statistical analysis... but you
>>saved them into a store that is implemented using weak references.
>>
>>You hit the heap ceiling and the GC kicks in.
>>
>>If finds one of those weak references, but it doesn't have the ability
>>to ask you (well, the store) about 'which is weaker', so, wooosh,
>>everything is gone.
>>
>>Sure, you probably collect 40Mb or heap, but then your perceived
>>performance drops and your cache system works in a 'saw-like' figure
>>
>>
>>cache size
>> ^
>> | /| /|
>> | / | / |
>> | / | / |
>> | / |/ |/
>> +-----------------> time
>> ^
>> GC kicks in
>>
>>and since the cache size is linearly proportional with the perceived
>>efficiency of the cache, Cocoon will appear to be 'fast at times' (to be
>>kind) or 'awefully bumping' (to be more reasonable).
>>
>>The solution I thought for this problem is simple but I don't know if it
>>works (never tested it real life):
>>
>> 1) partition the memory store into 'clusters' which are connected using
>>hard references.
>
>That is the idea of jakarta-commons simplestore. To build up a store
>chain!
>
>> 2) these 'clusters' are the real containers of the stored entities and
>>such entities are weak-referenced from the 'clusters'
>>
>>The idea is to have something like this:
>>
>> store +==> cluster +---> entity
>> | +---> entity
>> | +---> entity
>> |
>> +==> cluster +---> entity
>> +---> entity
>> +---> entity
>>
>>where:
>>
>> ===> hard reference
>> ---> soft reference
>>
>>and the key concept is that, whenever the GC needs to free some memory
>>that is occupied by weak references, the avalanche cleanup will be
>>'stopped' at a cluster level, saving the other clusters.
>>
>>Now, I'm not sure this works, but if it does, we have a reasonable
>>solution to the problem.
>
>We had the same idea and we are working on that.
>==> jakarta-commons-sandbox/simplestore
>"simple" to integrate "complex" to code ;-).
>
>>> Sorry for all that crap with Store and everything.
>>
>>Don't worry, it takes time to do it right but I'm sure we'll get there.
>>
>>Probably we need to discuss its design *before* implementing it :)
>
>Indeed ;-).
>
> Gerhard
>
>"The most important question when any new
>computer architecture is introduced is 'So what?'"
>
>
>---------------------------------------------------------------------
>To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
>For additional commands, email: cocoon-dev-help@xml.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org
RE: Store Janitor Hangs System
Posted by Gerhard Froehlich <g-...@gmx.de>.
Hi,
>From: Stefano Mazzocchi [mailto:stefano@apache.org]
>
>Gerhard Froehlich wrote:
>>
>> Hi,
>>
>> >From: Peter Hargreaves [mailto:pdh@totalise.co.uk]
>> >
>> >Hi Gerhard and Team,
>> >
>> >I'm posting in this group now I think I found a design problem with
>> >store-janitor.
>>
>> Slowly but constant this Store issues are a PITA for me :-/. I don't know
>> why this is in Java that difficult to control a little bit memory.
>> That's the price for automatic Memory Management!
>> (Nothing against you Peter!)
>
>Eh, if you look at the VM problems in Linux 2.4 you'll see that this
>realm is a complex one itself and now just because it's java (sure, java
>doesn't help you when it hides everything from you, like in this case).
Complex is the point.
>> >I think store-janitor works fine when it can free sufficient memory by
>> >calling the finalize and garbage collection. But if it needs to free the
>> >store it locks up!
>> >
>> >The reason it appears to lock up (I think), is because it calls the
>> >garbage collector too often - i.e. every time it frees an item from a
>> >store. Once called the store-janitor will free an item and call the
>> >garbage collector, repeating both until it has freed sufficient memory.
>> >If one item frees 4.44k and the garbage collector takes 2844ms then the
>> >time taken to free 20m will be 3.5 hours - during which time the system
>> >appears to be locked!
>
>Ouch! that hurts!
Yep, I still recover from that ;).
>> >The following is a brief summary of my analysis:
>> >
>> >With the following settings:
>> >Xms=0m
>> >Xmx=140m
>> >heapsize =100000000
>> >freememory=20000000
>> >
>> >Using Optimizeit I watched my java heap 'total' and 'in-use' growing.
>> >When total heapsize gets to 100m the store-janitor kicks in and frees a
>> >chunk of memory. This repeats every ten seconds but each time it frees
>> >less memory until it is no longer able to free memory and locks up. When
>> >locked up the garbage collector is running about 99% of the time.
>
>That's *very* bad!
Indeed!
>> >Looking at the store-janitor code and my debug log I can see exactly
>> >what happens when it locks.
>> >
>> >I notice, examining Store-janitorImpl.run() that, if the garbage
>> >collector alone manages to clear sufficient memory, no store items are
>> >cleared (as expected). This is possibly all that is happening when
>> >store-janitor appears to work! However if that is not sufficient the
>> >following loop is started.
>> >
>> > synchronized (this) {
>> > while (this.memoryLow() &&
>> >this.getStoreList().size() > 0) {
>> > this.freeMemory();
>> > }
>> > this.resetIndex();
>> > }
>> >
>> >this.memoryLow() tests to see if sufficient is free and prints Debug info.
>> >this.freeMemory() removes an item, runs garbage collection, and prints
>> >Debug info.
>> >
>> > From my log files I can see this loop being executed. Each time round
>> >the loop I can see how much memory is freed and how long it takes.
>> >Typically it can take seconds to free one item which can be only a few
>> >kb. So, in my case with 'freememory' set to 20m, it is likely to take a
>> >few hours to free sufficient memory!!
>> >
>> >I've noticed when running Optimizeit that although garbage collection
>> >can be quick, it sometimes takes a few seconds. If it has just been run,
>> >and you force it to run again, then it seems to take longer. If it can't
>> >find much to freeup, it seems to do a more time consuming search for
>> >garbage.
>>
>> This all makes sense too me.
>> Then we need a limit how often the GC can be called. Maybe 100 loops
>> should be enough.
>
>I don't get it: why more than one loop? I mean, if you call the GC, it
>should free all the memory that it can... doing any more loops at that
>time, will not change anything.
Maybe I did something wrong. But the idea was that:
while(MemoryIsLow) {
free objects out of the store //physicall
run gc
}
I run the GC after each "free objects" to clean away
does not needed objects!
The problem is now, that when he doesn't has anything
to free from the registered stores, he runs the GC
all the time. And then we have this endless loop!
Therefore I should check if the Stores are empty. If they
are empty and there is nothing to free anymore we should
leave that loop.
>> After that it waits as configured (threadinterval)
>> before the next execution.
>>
>> Maybe there is a more elegent solution.
>
>Well, this is a very difficult realm, as I said, but sure, we can start
>a redesign phase on this.
We should!
>> I actually develop in jakarta-commons a store (again) with Weak References.
>> This is a much better solution. No Threads, no GC calls. When it is ready
>> to introduce I'll explain you!
>
>Be careful when going down this road: the JLS doesn't say anything about
>'how' the weak references should be cleaned. And Java 1.3 implements it
>in the most memory efficient possible way: if the GC gets a weak
>reference, all of them are removed.
>
>Now, imagine the case: you have spent a couple of hours building up and
>tuning your cache using highly complex statistical analysis... but you
>saved them into a store that is implemented using weak references.
>
>You hit the heap ceiling and the GC kicks in.
>
>If finds one of those weak references, but it doesn't have the ability
>to ask you (well, the store) about 'which is weaker', so, wooosh,
>everything is gone.
>
>Sure, you probably collect 40Mb or heap, but then your perceived
>performance drops and your cache system works in a 'saw-like' figure
>
>
>cache size
> ^
> | /| /|
> | / | / |
> | / | / |
> | / |/ |/
> +-----------------> time
> ^
> GC kicks in
>
>and since the cache size is linearly proportional with the perceived
>efficiency of the cache, Cocoon will appear to be 'fast at times' (to be
>kind) or 'awefully bumping' (to be more reasonable).
>
>The solution I thought for this problem is simple but I don't know if it
>works (never tested it real life):
>
> 1) partition the memory store into 'clusters' which are connected using
>hard references.
That is the idea of jakarta-commons simplestore. To build up a store
chain!
> 2) these 'clusters' are the real containers of the stored entities and
>such entities are weak-referenced from the 'clusters'
>
>The idea is to have something like this:
>
> store +==> cluster +---> entity
> | +---> entity
> | +---> entity
> |
> +==> cluster +---> entity
> +---> entity
> +---> entity
>
>where:
>
> ===> hard reference
> ---> soft reference
>
>and the key concept is that, whenever the GC needs to free some memory
>that is occupied by weak references, the avalanche cleanup will be
>'stopped' at a cluster level, saving the other clusters.
>
>Now, I'm not sure this works, but if it does, we have a reasonable
>solution to the problem.
We had the same idea and we are working on that.
==> jakarta-commons-sandbox/simplestore
"simple" to integrate "complex" to code ;-).
>> Sorry for all that crap with Store and everything.
>
>Don't worry, it takes time to do it right but I'm sure we'll get there.
>
>Probably we need to discuss its design *before* implementing it :)
Indeed ;-).
Gerhard
"The most important question when any new
computer architecture is introduced is 'So what?'"
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org
Re: Store Janitor Hangs System
Posted by Stefano Mazzocchi <st...@apache.org>.
Gerhard Froehlich wrote:
>
> Hi,
>
> >From: Peter Hargreaves [mailto:pdh@totalise.co.uk]
> >
> >Hi Gerhard and Team,
> >
> >I'm posting in this group now I think I found a design problem with
> >store-janitor.
>
> Slowly but constant this Store issues are a PITA for me :-/. I don't know
> why this is in Java that difficult to control a little bit memory.
> That's the price for automatic Memory Management!
> (Nothing against you Peter!)
Eh, if you look at the VM problems in Linux 2.4 you'll see that this
realm is a complex one itself and now just because it's java (sure, java
doesn't help you when it hides everything from you, like in this case).
> >I think store-janitor works fine when it can free sufficient memory by
> >calling the finalize and garbage collection. But if it needs to free the
> >store it locks up!
> >
> >The reason it appears to lock up (I think), is because it calls the
> >garbage collector too often - i.e. every time it frees an item from a
> >store. Once called the store-janitor will free an item and call the
> >garbage collector, repeating both until it has freed sufficient memory.
> >If one item frees 4.44k and the garbage collector takes 2844ms then the
> >time taken to free 20m will be 3.5 hours - during which time the system
> >appears to be locked!
Ouch! that hurts!
> >The following is a brief summary of my analysis:
> >
> >With the following settings:
> >Xms=0m
> >Xmx=140m
> >heapsize =100000000
> >freememory=20000000
> >
> >Using Optimizeit I watched my java heap 'total' and 'in-use' growing.
> >When total heapsize gets to 100m the store-janitor kicks in and frees a
> >chunk of memory. This repeats every ten seconds but each time it frees
> >less memory until it is no longer able to free memory and locks up. When
> >locked up the garbage collector is running about 99% of the time.
That's *very* bad!
> >Looking at the store-janitor code and my debug log I can see exactly
> >what happens when it locks.
> >
> >I notice, examining Store-janitorImpl.run() that, if the garbage
> >collector alone manages to clear sufficient memory, no store items are
> >cleared (as expected). This is possibly all that is happening when
> >store-janitor appears to work! However if that is not sufficient the
> >following loop is started.
> >
> > synchronized (this) {
> > while (this.memoryLow() &&
> >this.getStoreList().size() > 0) {
> > this.freeMemory();
> > }
> > this.resetIndex();
> > }
> >
> >this.memoryLow() tests to see if sufficient is free and prints Debug info.
> >this.freeMemory() removes an item, runs garbage collection, and prints
> >Debug info.
> >
> > From my log files I can see this loop being executed. Each time round
> >the loop I can see how much memory is freed and how long it takes.
> >Typically it can take seconds to free one item which can be only a few
> >kb. So, in my case with 'freememory' set to 20m, it is likely to take a
> >few hours to free sufficient memory!!
> >
> >I've noticed when running Optimizeit that although garbage collection
> >can be quick, it sometimes takes a few seconds. If it has just been run,
> >and you force it to run again, then it seems to take longer. If it can't
> >find much to freeup, it seems to do a more time consuming search for
> >garbage.
>
> This all makes sense too me.
> Then we need a limit how often the GC can be called. Maybe 100 loops
> should be enough.
I don't get it: why more than one loop? I mean, if you call the GC, it
should free all the memory that it can... doing any more loops at that
time, will not change anything.
> After that it waits as configured (threadinterval)
> before the next execution.
>
> Maybe there is a more elegent solution.
Well, this is a very difficult realm, as I said, but sure, we can start
a redesign phase on this.
> I actually develop in jakarta-commons a store (again) with Weak References.
> This is a much better solution. No Threads, no GC calls. When it is ready
> to introduce I'll explain you!
Be careful when going down this road: the JLS doesn't say anything about
'how' the weak references should be cleaned. And Java 1.3 implements it
in the most memory efficient possible way: if the GC gets a weak
reference, all of them are removed.
Now, imagine the case: you have spent a couple of hours building up and
tuning your cache using highly complex statistical analysis... but you
saved them into a store that is implemented using weak references.
You hit the heap ceiling and the GC kicks in.
If finds one of those weak references, but it doesn't have the ability
to ask you (well, the store) about 'which is weaker', so, wooosh,
everything is gone.
Sure, you probably collect 40Mb or heap, but then your perceived
performance drops and your cache system works in a 'saw-like' figure
cache size
^
| /| /|
| / | / |
| / | / |
| / |/ |/
+-----------------> time
^
GC kicks in
and since the cache size is linearly proportional with the perceived
efficiency of the cache, Cocoon will appear to be 'fast at times' (to be
kind) or 'awefully bumping' (to be more reasonable).
The solution I thought for this problem is simple but I don't know if it
works (never tested it real life):
1) partition the memory store into 'clusters' which are connected using
hard references.
2) these 'clusters' are the real containers of the stored entities and
such entities are weak-referenced from the 'clusters'
The idea is to have something like this:
store +==> cluster +---> entity
| +---> entity
| +---> entity
|
+==> cluster +---> entity
+---> entity
+---> entity
where:
===> hard reference
---> soft reference
and the key concept is that, whenever the GC needs to free some memory
that is occupied by weak references, the avalanche cleanup will be
'stopped' at a cluster level, saving the other clusters.
Now, I'm not sure this works, but if it does, we have a reasonable
solution to the problem.
> Sorry for all that crap with Store and everything.
Don't worry, it takes time to do it right but I'm sure we'll get there.
Probably we need to discuss its design *before* implementing it :)
--
Stefano Mazzocchi One must still have chaos in oneself to be
able to give birth to a dancing star.
<st...@apache.org> Friedrich Nietzsche
--------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org
RE: Store Janitor Hangs System
Posted by Gerhard Froehlich <g-...@gmx.de>.
Hi,
>From: Peter Hargreaves [mailto:pdh@totalise.co.uk]
>
>Hi Gerhard and Team,
>
>I'm posting in this group now I think I found a design problem with
>store-janitor.
Slowly but constant this Store issues are a PITA for me :-/. I don't know
why this is in Java that difficult to control a little bit memory.
That's the price for automatic Memory Management!
(Nothing against you Peter!)
>I think store-janitor works fine when it can free sufficient memory by
>calling the finalize and garbage collection. But if it needs to free the
>store it locks up!
>
>The reason it appears to lock up (I think), is because it calls the
>garbage collector too often - i.e. every time it frees an item from a
>store. Once called the store-janitor will free an item and call the
>garbage collector, repeating both until it has freed sufficient memory.
>If one item frees 4.44k and the garbage collector takes 2844ms then the
>time taken to free 20m will be 3.5 hours - during which time the system
>appears to be locked!
>
>The following is a brief summary of my analysis:
>
>With the following settings:
>Xms=0m
>Xmx=140m
>heapsize =100000000
>freememory=20000000
>
>Using Optimizeit I watched my java heap 'total' and 'in-use' growing.
>When total heapsize gets to 100m the store-janitor kicks in and frees a
>chunk of memory. This repeats every ten seconds but each time it frees
>less memory until it is no longer able to free memory and locks up. When
>locked up the garbage collector is running about 99% of the time.
>
>Looking at the store-janitor code and my debug log I can see exactly
>what happens when it locks.
>
>I notice, examining Store-janitorImpl.run() that, if the garbage
>collector alone manages to clear sufficient memory, no store items are
>cleared (as expected). This is possibly all that is happening when
>store-janitor appears to work! However if that is not sufficient the
>following loop is started.
>
> synchronized (this) {
> while (this.memoryLow() &&
>this.getStoreList().size() > 0) {
> this.freeMemory();
> }
> this.resetIndex();
> }
>
>this.memoryLow() tests to see if sufficient is free and prints Debug info.
>this.freeMemory() removes an item, runs garbage collection, and prints
>Debug info.
>
> From my log files I can see this loop being executed. Each time round
>the loop I can see how much memory is freed and how long it takes.
>Typically it can take seconds to free one item which can be only a few
>kb. So, in my case with 'freememory' set to 20m, it is likely to take a
>few hours to free sufficient memory!!
>
>I've noticed when running Optimizeit that although garbage collection
>can be quick, it sometimes takes a few seconds. If it has just been run,
>and you force it to run again, then it seems to take longer. If it can't
>find much to freeup, it seems to do a more time consuming search for
>garbage.
This all makes sense too me.
Then we need a limit how often the GC can be called. Maybe 100 loops
should be enough. After that it waits as configured (threadinterval)
before the next execution.
Maybe there is a more elegent solution.
I actually develop in jakarta-commons a store (again) with Weak References.
This is a much better solution. No Threads, no GC calls. When it is ready
to introduce I'll explain you!
Sorry for all that crap with Store and everything.
Gerhard
--------------------------
Hey! It compiles! Ship it!
--------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: cocoon-dev-unsubscribe@xml.apache.org
For additional commands, email: cocoon-dev-help@xml.apache.org