I am using JDK 1.4.1 After some further testing I beleive I found the problem. The purgatory is not being emptied quickly enough.
To determine this, I modified AbstractDiskCache and added log statements by the purgatory.remove() calls in the code to log which key is being removed. I also lessened that amount of available memory to the jvm to arrive at an OutOfMemoryError quicker. These were the last of my results: i=200000 i=201000 i=202000 i=203000 i=204000 removing from purg key = testkey751 removing from purg key = testkey752 removing from purg key = testkey753 i=205000 i=206000 java.lang.OutOfMemoryError What you can see is that even when got to i=204000, only keys 751, 752 and 753 was being removed from the purgatory at that time. The cache event queue is not firing events nearly fast enough to keep up with this loop. When I added a 100 ms delay though into this loop after each put the remove events show up more in sync with the current i and memory seems to be stable. I suppose this is not too bad, since in real life it would be rare that objects would be put into a cache as rapidly as they were in my loop. There would typically be a delay between putting things into the cache. So this test fails, but it doesn't indicate that there would be a memory leak in a real world application. Another option is to modify the code to fire cache events more often. This may be good to satisfy this test but probably would degrade performance in a real world app if the events get fired too often. hmmmm :-) Daniel --- Amy Wang <[EMAIL PROTECTED]> wrote: > what jvm you are using? > > > -----Original Message----- > > From: Daniel Rosenbaum [mailto:[EMAIL PROTECTED] > > Sent: Thursday, September 11, 2003 10:01 AM > > To: Turbine JCS Users List > > Subject: RE: Memory test > > > > > > By the way I also removed the Thread.sleep(10) code and ran > > without the indexed disk cache. Memory was stable and > within 10 > > minutes I already cached more than 150 million items. I am > sure > > if I would have let it keep running it would have completed > the > > loop to 2 billion. Go garbage collection is working by > memory > > only, but still not be indexed disk. > > > > Daniel > > > > --- Daniel Rosenbaum <[EMAIL PROTECTED]> wrote: > > > Setting the memory shrinker to false had no effect, memory > was > > > still leaking. > > > > > > When I switched off the aux disk cache though memory is > very > > > stable. This seems to indicate a problem with the disk > cache. > > > > > > Daniel > > > > > > --- Aaron Smuts <[EMAIL PROTECTED]> wrote: > > > > If turning off the memory shrinker doesn't work, try not > > > using > > > > a disk > > > > cache at all. > > > > > > > > I want to isolate the issue. > > > > > > > > Aaron > > > > > > > > > -----Original Message----- > > > > > From: Daniel Rosenbaum [mailto:[EMAIL PROTECTED] > > > > > Sent: Thursday, September 11, 2003 9:39 AM > > > > > To: Turbine JCS Users List > > > > > Subject: RE: Memory test > > > > > > > > > > As a follow up, I let my test run for a while and > after > > > > about 5 > > > > > hours my JVM crashed with a > java.lang.OutOfMemoryError, > > > > after > > > > > putting somewhere bewtween 3087000-3088000 items into > the > > > > cache. > > > > > My system has 512 megs of ram. Following are the > last > > > few > > > > > lines of my log: > > > > > > > > > > Sep 10 21:00:35 2003: i=3086000 > > > > > Sep 10 21:00:35 2003: avail = 2757728 > > > > > Sep 10 21:00:35 2003: total = 524025856 > > > > > Sep 10 21:00:35 2003: [GC > > > > > Sep 10 21:00:35 2003: 509217K->507306K(511744K) > > > > > Sep 10 21:00:35 2003: , 0.0695549 secs] > > > > > Sep 10 21:00:35 2003: > > > > > Sep 10 21:00:36 2003: [GC > > > > > Sep 10 21:00:36 2003: 509354K->507447K(511744K) > > > > > Sep 10 21:00:36 2003: , 0.0713898 secs] > > > > > Sep 10 21:00:36 2003: > > > > > Sep 10 21:00:37 2003: [Full GC > > > > > Sep 10 21:17:39 2003: 509495K->507573K(511744K) > > > > > Sep 10 21:17:39 2003: , 1019.7951857 secs] > > > > > Sep 10 21:17:39 2003: > > > > > Sep 10 21:17:41 2003: i=3087000 > > > > > Sep 10 21:17:44 2003: avail = 3737904 > > > > > Sep 10 21:17:44 2003: total = 524025856 > > > > > Sep 10 21:17:45 2003: [Full GC > > > > > Sep 10 21:30:07 2003: 511743K->509584K(511744K) > > > > > Sep 10 21:30:07 2003: , 739.8379643 secs] > > > > > Sep 10 21:30:07 2003: > > > > > Sep 10 21:30:07 2003: [Full GC > > > > > Sep 10 21:43:08 2003: 509584K->509584K(511744K) > > > > > Sep 10 21:43:08 2003: , 798.5084294 secs] > > > > > Sep 10 21:43:08 2003: > > > > > Sep 10 21:43:09 2003: java.lang.OutOfMemoryError > > > > > Sep 10 21:43:12 2003: <<no stack trace available>> > > > > > > > > > > Notice especially the Full GCs, which took 739 and 798 > > > > seconds > > > > > to complete. You could see there was probably alot of > > > > virtual > > > > > memory swapping at that point, the system trying to > stay > > > > alive > > > > > until it quit. > > > > > > > > > > Seems there is a memory leak somewhere, doesn't it? > > > > > > > > > > I wonder if it has anything to do with the > > > IndexedDiskCache > > > > file > > > > > itself. The documentation says "Depending on the key > > > size, > > > > > 500,000 disk entries will probably only require about > 1 MB > > > > of > > > > > memory." This has not been my experience though with > my > > > > test. > > > > > According to the logs I posted before, 1000 elements > > > between > > > > > i=2000 and i=3000 required 4341272-3843352=497920, or > an > > > > average > > > > > of 497.92 bytes per element. (I looked for a log entry > in > > > > which > > > > > there was no GC between two log writings and the total > > > > memory > > > > > had the same number). Later on, I had this: > > > > > > > > > > Sep 10 18:49:52 2003: i=1531000 > > > > > Sep 10 18:49:52 2003: avail = 90172696 > > > > > Sep 10 18:49:52 2003: total = 382328832 > > > > > Sep 10 18:49:53 2003: [GC > > > > > Sep 10 18:49:53 2003: 286864K->284953K(373368K) > > > > > Sep 10 18:49:53 2003: , 0.0060882 secs] > > > > > Sep 10 18:49:53 2003: > > > > > Sep 10 18:49:54 2003: [GC > > > > > Sep 10 18:49:54 2003: 287001K->285095K(373368K) > > > > > Sep 10 18:49:54 2003: , 0.0062273 secs] > > > > > Sep 10 18:49:54 2003: > > > > > Sep 10 18:49:54 2003: i=1532000 > > > > > Sep 10 18:49:54 2003: avail = 89255520 > > > > > Sep 10 18:49:54 2003: total = 382328832 > > > > > > > > > > So between i=1531000 and i=1532000, there was > > > > > 90172696-89255520=917176, or an average of 917.176 > bytes > > > per > > > > > item! Grew almost 2x! This is even with two GCs > between > > > > them. > > > > > > > > > > The bottom line is, something is definately eating up > > > > memory. > > > > > > > > > > Daniel > > > > > > > > > > > > > > > --- Daniel Rosenbaum <[EMAIL PROTECTED]> wrote: > > > > > > Thanks Wayne and Amy for your help. > > > > > > > > > > > > Firstly with the -verbose:gc option, I modified my > code > > > as > > > > > > follows: > > > > > > > > > > > > for(int i=0; i < 200000000; i++) { > > > > > > Vector vec = new Vector(); > > > > > > testCache.put(key+i, vec); > > > > > > if (i%1000==0) { > > > > > > System.out.println("i=" + i); > > > > > > System.out.println("avail = " + > > > > > > Runtime.getRuntime().freeMemory()); > > > > > > System.out.println("total = " + > > > > > > Runtime.getRuntime().totalMemory()); > > > > > > } > > > > > > } > > > > > > > > > > > > so info would be dumped out every 1000 elements. > > > Partial > > > > > > results are: > > > > > > > > > > > > Sep 10 10:22:46 2003: i=0 > > > > > > Sep 10 10:22:46 2003: avail = 500208 > > > > > > Sep 10 10:22:46 2003: total = 7782400 > > > > > > Sep 10 10:22:46 2003: [GC > > > > > > Sep 10 10:22:46 2003: 7431K->7237K(7856K) > > > > > > Sep 10 10:22:46 2003: , 0.0086215 secs] > > > > > > Sep 10 10:22:46 2003: > > > > > > Sep 10 10:22:46 2003: i=1000 > > > > > > Sep 10 10:22:46 2003: avail = 443920 > > > > > > Sep 10 10:22:46 2003: total = 8044544 > > > > > > Sep 10 10:22:46 2003: [Full GC > > > > > > Sep 10 10:22:47 2003: 7749K->5441K(9840K) > > > > > > Sep 10 10:22:47 2003: , 0.1197119 secs] > > > > > > Sep 10 10:22:47 2003: > > > > > > Sep 10 10:22:47 2003: i=2000 > > > > > > Sep 10 10:22:47 2003: avail = 4341272 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: i=3000 > > > > > > Sep 10 10:22:47 2003: avail = 3843352 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: [GC > > > > > > Sep 10 10:22:47 2003: 6145K->5949K(9840K) > > > > > > Sep 10 10:22:47 2003: , 0.0081893 secs] > > > > > > Sep 10 10:22:47 2003: > > > > > > Sep 10 10:22:47 2003: i=4000 > > > > > > Sep 10 10:22:47 2003: avail = 3570144 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: [GC > > > > > > Sep 10 10:22:47 2003: 6653K->6451K(9840K) > > > > > > Sep 10 10:22:47 2003: , 0.0078136 secs] > > > > > > Sep 10 10:22:47 2003: > > > > > > Sep 10 10:22:47 2003: i=5000 > > > > > > Sep 10 10:22:47 2003: avail = 3255256 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: i=6000 > > > > > > Sep 10 10:22:47 2003: avail = 2781920 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: [GC > > > > > > Sep 10 10:22:47 2003: 7155K->6964K(9840K) > > > > > > Sep 10 10:22:47 2003: , 0.0088930 secs] > > > > > > Sep 10 10:22:47 2003: > > > > > > Sep 10 10:22:47 2003: i=7000 > > > > > > Sep 10 10:22:47 2003: avail = 2503968 > > > > > > Sep 10 10:22:47 2003: total = 10076160 > > > > > > Sep 10 10:22:47 2003: [GC > > > > > > Sep 10 10:22:47 2003: 7668K->7465K(9840K) > > > > > > Sep 10 10:22:47 2003: , 0.0070875 secs] > > > > > > > > > > > > So we see that the GC messages are appearing. Yet > as > > > you > > > > > > could > > > > > > see memory keeps going down. > > > > > > > > > > > > Afterward I put in a 10ms delay between puts: > > > > > > > > > > > > for(int i=0; i < 200000000; i++) { > > > > > > Vector vec = new Vector(); > > > > > > testCache.put(key+i, vec); > > > > > > if (i%1000==0) { > > > > > > System.out.println("i=" + i); > > > > > > System.out.println("avail = " + > > > > > > Runtime.getRuntime().freeMemory()); > > > > > > System.out.println("total = " + > > > > > > Runtime.getRuntime().totalMemory()); > > > > > > } > > > > > > Thread.sleep(10); > > > > > > } > > > > > > > > > > > > Now it is going much slower but memory is still > > > noticably > > > > > > still > > > > > > going down. > > > > > > > > > > > > Any other ideas? > > > > > > > > > > > > Thanks, > > > > > > Daniel > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > --- "Young, Wayne" <[EMAIL PROTECTED]> wrote: > > > > > > > Do you know if garbage collections are happening? > Try > > > > > > running > > > > > > > with the > > > > > > > -verbose:gc option. It could be that the objects > ARE > > > > being > > > > > > > dereferenced, but > > > > > > > just aren't being collected before your loop ends. > > > > > > > > > > > > > > Wayne > > > > > > > > > > > > > > -----Original Message----- > > > > > > > From: Daniel Rosenbaum > [mailto:[EMAIL PROTECTED] > > > > > > > Sent: Tuesday, September 09, 2003 8:26 PM > > > > > > > To: [EMAIL PROTECTED] > > > > > > > Subject: Memory test > > > > > > > > > > > > > > > > > > > > > Hi all, > > > > > > > > > > > > > > I am testing JCS to see how it handles memory. > The > > > > > > following > > > > > > > is > > > > > > > a snippet of my code and config file: > > > > > > > > > > > > > > for(int i=0; i < 200000000; i++) { > > > > > > > Vector vec = new Vector(); > > > > > > > testCache.put("testkey"+i, vec); > > > > > > > } > > > > > > > > > > > > > > # DEFAULT CACHE REGION (memory cache) > > > > > > > jcs.default=DC > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.default.cacheattributes=org.apache.jcs.engine.CompositeCac > > heAttribut > > > > es > > > > > > > jcs.default.cacheattributes.MaxObjects=2000 > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.default.cacheattributes.MemoryCacheName=org.apache.jcs.eng > > ine.memory > > > > .l > > > > > ru > > > > > > > .LRUMemoryCache > > > > > > > jcs.default.cacheattributes.UseMemoryShrinker=true > > > > > > > > jcs.default.cacheattributes.ShrinkerIntervalSeconds=60 > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.default.elementattributes=org.apache.jcs.engine.ElementAttributes > > > > > > > jcs.default.elementattributes.IsEternal=false > > > > > > > jcs.default.elementattributes.MaxLifeSeconds=43200 > > > > > > > jcs.default.elementattributes.IsSpool=true > > > > > > > jcs.default.elementattributes.IsRemote=false > > > > > > > jcs.default.elementattributes.IsLateral=false > > > > > > > > > > > > > > #Auxiliary CACHE (disk cache) > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.auxiliary.DC=org.apache.jcs.auxiliary.disk.indexed.Indexed > > DiskCacheF > > > > ac > > > > > to > > > > > > > ry > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.auxiliary.DC.attributes=org.apache.jcs.auxiliary.disk.inde > > xed.Indexe > > > > dD > > > > > is > > > > > > > kCacheAttributes > > > > > > > jcs.auxiliary.DC.attributes.DiskPath=jcscache > > > > > > > > > > > > > > jcs.region.testCache=DC > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.region.testCache.cacheattributes=org.apache.jcs.engine.Com > > positeCach > > > > eA > > > > > tt > > > > > > > ributes > > > > > > > jcs.region.testCache.cacheattributes.MaxObjects=50 > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.region.testCache.cacheattributes.MemoryCacheName=org.apach > > e.jcs.engi > > > > ne > > > > > .m > > > > > > > emory.lru.LRUMemoryCache > > > > > > > > > > > > jcs.region.testCache.cacheattributes.UseMemoryShrinker=true > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.region.testCache.cacheattributes.ShrinkerIntervalSeconds=60 > > > > > > > > > > > > > > > > > > > > > > > > > > > > jcs.region.testCache.elementattributes=org.apache.jcs.engine.E > > lementAttr > > > > ib > > > > > ut > > > > > > > es > > > > > > > > jcs.region.testCache.elementattributes.IsEternal=false > > > > > > > > > > > > jcs.region.testCache.elementattributes.MaxLifeSeconds=43200 > > > > > > > > jcs.region.testCache.elementattributes.IdleTime=43200 > > > > > > > > jcs.region.testCache.elementattributes.IsSpool=true > > > > > > > > jcs.region.testCache.elementattributes.IsRemote=false > > > > > > > > jcs.region.testCache.elementattributes.IsLateral=false > > > > > > > > > > > > > > When I run this code the memory on my system goes > down > > > > very > > > > > > > quickly. I expected that after the first 50 > elements > > > it > > > > > > would > > > > > > > start putting items on disk and removing them from > > > > memory > > > > > > but > > > > > > > this does not seem to be happening. I see the > file on > > > > disk > > > > > > > getting increasingly bigger but memory still keeps > > > > going, > > > > > > > leading me to believe that the elements are not > > > getting > > > > > > > garbage > > > > > > > collected or was never freed. Am I doing > something > > > > > > > incorrectly? > > > > > > > > > > > > > > Thanks, > > > > > > > Daniel > > > > > > > > > > > > > > > > > > > > > __________________________________ > > > > > > > Do you Yahoo!? > > > > > > > Yahoo! SiteBuilder - Free, easy-to-use web site > design > > > > > > > software > > > > > > > http://sitebuilder.yahoo.com > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > --------------------------------------------------------------------- > > > > > > > To unsubscribe, e-mail: > > > > > > > [EMAIL PROTECTED] > > > > > > > For additional commands, e-mail: > > > > > > > [EMAIL PROTECTED] > > > > > > > > > > > > > > > > > > > > > > > > > __________________________________ > > > > > > Do you Yahoo!? > > > > > > Yahoo! SiteBuilder - Free, easy-to-use web site > design > > > > > > software > > > > > > http://sitebuilder.yahoo.com > > > > > > > > > > > > > > > > > > > > > > > > > > > --------------------------------------------------------------------- > > > > > > To unsubscribe, e-mail: > > > > > > [EMAIL PROTECTED] > > > > > > For additional commands, e-mail: > > > > > > [EMAIL PROTECTED] > > > > > > > > > > > > > > > > > > > > > __________________________________ > > > > > Do you Yahoo!? > > > > > Yahoo! SiteBuilder - Free, easy-to-use web site design > > > > software > > > > > http://sitebuilder.yahoo.com > > > > > > > > > > > > > > > > > > > > --------------------------------------------------------------------- > > > > > To unsubscribe, e-mail: > > > > [EMAIL PROTECTED] > > > > > For additional commands, e-mail: > > > > [EMAIL PROTECTED] > > > > > > > > > > > > > > > > > > --------------------------------------------------------------------- > > > > To unsubscribe, e-mail: > > > > [EMAIL PROTECTED] > > > > For additional commands, e-mail: > > > > [EMAIL PROTECTED] > > > > > > > > > > > > > __________________________________ > > > Do you Yahoo!? > > > Yahoo! SiteBuilder - Free, easy-to-use web site design > > > software > > > http://sitebuilder.yahoo.com > > > > > > > > > --------------------------------------------------------------------- > > > To unsubscribe, e-mail: > > > [EMAIL PROTECTED] > > > For additional commands, e-mail: > > > [EMAIL PROTECTED] > > > > > > > > > __________________________________ > > Do you Yahoo!? > > Yahoo! SiteBuilder - Free, easy-to-use web site design > software > > http://sitebuilder.yahoo.com > > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: > > [EMAIL PROTECTED] > > For additional commands, e-mail: > > [EMAIL PROTECTED] > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: > [EMAIL PROTECTED] > For additional commands, e-mail: > [EMAIL PROTECTED] > __________________________________ Do you Yahoo!? Yahoo! SiteBuilder - Free, easy-to-use web site design software http://sitebuilder.yahoo.com --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
