[SCIFIO] SCIFIO does not seem to release memory of closed images
Burkhard Höckendorf
burkhard.hoeckendorf at web.de
Wed Jul 23 13:41:45 CDT 2014
Dear Mark,
Thanks for looking into this. The bug report seems involved indeed,
which also means that I can be of little help. I hope you'll find a good
(and relatively pain-free) solution and that the grant work is going well.
Best,
Burkhard
On 7/15/2014 12:18 PM, Mark Hiner wrote:
> Hello again Burkhard,
>
> Thank you for your persistence in this issue. After looking at it again
> today, I realized that there must be a memory leak in how we try to map
> and synchronize ImageJ 1.x ImagePluses with ImageJ2 data structures.
>
> Indeed, that was exactly what I found... however, the solution is
> non-trivial.
>
> I have filed a new issue for this here:
> https://github.com/imagej/imagej-legacy/issues/67. It is something I
> would like to resolve quickly, but because it is an involved issue that
> requires additional investigation and discussion, it's at a lower
> priority than some necessary grant work this week.
>
> Thanks again for the report - it is, at least, good to know where the
> problem is now.
> - Mark
>
>
> On Mon, Jul 14, 2014 at 1:39 PM, Burkhard Höckendorf
> <burkhard.hoeckendorf at web.de <mailto:burkhard.hoeckendorf at web.de>> wrote:
>
> Hi Mark,
>
> Thanks for the speedy response. I've rewritten my macro to perhaps
> illustrate my point more clearly. It now opens the file and
> immediately closes it again, for 50 iterations.
>
> With scifio enabled I do not get an out of memory error, but it
> still accumulates memory to the point that it can not open the
> entire image anymore but instead opens virtual stacks. Without
> scifio this does not occur.
>
> Also note that reading the full image into memory without scifio is
> performance-wise much closer to opening a scifio virtual image than
> reading the full image with scifio.
>
> Below is the macro and its output.
> Best,
> Burkhard
>
> nOpenTimes = 50;
> file = "/path/to/image";
>
> for (i=1; i<=nOpenTimes; i+=1) {
> msToOpen = getTime();
> open(file);
> msToOpen = getTime() - msToOpen;
>
> msg = ""+ i +": "+ IJ.currentMemory() +" mem, "+ msToOpen
> +" ms";
> if (is("Virtual Stack"))
> msg += " (virtual)";
> print(msg);
>
> close();
> }
>
> Using SCIFIO:
> 1: 3822648536 mem, 15984 ms
> 2: 7572956280 <tel:7572956280> mem, 14986 ms
> 3: 9998931400 mem, 14821 ms
> 4: 13784264296 mem, 14895 ms
> 5: 16885256128 mem, 15019 ms
> 6: 19656427040 mem, 15036 ms
> 7: 24079096808 mem, 15212 ms
> 8: 27510832552 mem, 15179 ms
> 9: 32077394688 mem, 15427 ms
> 10: 34409304040 mem, 15482 ms
> 11: 36859610432 mem, 15227 ms
> 12: 43061552320 mem, 15607 ms
> 13: 42104714576 mem, 15359 ms
> 14: 47910156296 mem, 15073 ms
> 15: 48044651592 mem, 3053 ms (virtual)
> 16: 48170004824 mem, 2502 ms (virtual)
> 17: 48295208256 mem, 2522 ms (virtual)
> 18: 48422832064 mem, 2495 ms (virtual)
> 19: 48550863920 mem, 2504 ms (virtual)
> 20: 48228290696 mem, 2615 ms (virtual)
> 21: 48343976264 mem, 2482 ms (virtual)
> 22: 48461224352 mem, 2495 ms (virtual)
> 23: 48577275224 mem, 2482 ms (virtual)
> 24: 48696021320 mem, 2493 ms (virtual)
> 25: 48815302152 mem, 2513 ms (virtual)
> 26: 48512671680 mem, 2682 ms (virtual)
> 27: 48624380048 mem, 2493 ms (virtual)
> 28: 48734321624 mem, 2487 ms (virtual)
> 29: 48847280096 mem, 2504 ms (virtual)
> 30: 48958189928 mem, 2491 ms (virtual)
> 31: 49069385672 mem, 2499 ms (virtual)
> 32: 48787137328 mem, 2614 ms (virtual)
> 33: 48896061816 mem, 2500 ms (virtual)
> 34: 49004784912 mem, 2488 ms (virtual)
> 35: 49116572664 mem, 2516 ms (virtual)
> 36: 49226035440 mem, 2497 ms (virtual)
> 37: 49334418896 mem, 2500 ms (virtual)
> 38: 49074728512 mem, 2660 ms (virtual)
> 39: 49183254768 mem, 2506 ms (virtual)
> 40: 49290891152 mem, 2491 ms (virtual)
> 41: 49399382336 mem, 2499 ms (virtual)
> 42: 49505843008 mem, 2487 ms (virtual)
> 43: 49613438808 mem, 2487 ms (virtual)
> 44: 49721198184 mem, 2481 ms (virtual)
> 45: 49441266864 mem, 2709 ms (virtual)
> 46: 49548934656 mem, 2485 ms (virtual)
> 47: 49656785920 mem, 2501 ms (virtual)
> 48: 49764127512 mem, 2480 ms (virtual)
> 49: 49872069552 mem, 2495 ms (virtual)
> 50: 49979814216 mem, 2482 ms (virtual)
>
> Not using SCIFIO:
> 1: 3107094592 <tel:3107094592> mem, 3921 ms
> 2: 3109153032 <tel:3109153032> mem, 3837 ms
> 3: 3109836568 <tel:3109836568> mem, 3631 ms
> 4: 3109512264 <tel:3109512264> mem, 3581 ms
> 5: 3109478728 <tel:3109478728> mem, 3633 ms
> 6: 3123692656 <tel:3123692656> mem, 4145 ms
> 7: 3112714624 mem, 3301 ms
> 8: 3128373632 <tel:3128373632> mem, 3202 ms
> 9: 3117798216 mem, 3235 ms
> 10: 3133595872 <tel:3133595872> mem, 3190 ms
> 11: 3123048664 <tel:3123048664> mem, 3229 ms
> 12: 5754899128 <tel:5754899128> mem, 3404 ms
> 13: 3128308704 <tel:3128308704> mem, 3307 ms
> 14: 3117759024 mem, 3219 ms
> 15: 5910573440 mem, 3112 ms
> 16: 5488969832 mem, 3222 ms
> 17: 3112824736 mem, 3273 ms
> 18: 3128647888 <tel:3128647888> mem, 3147 ms
> 19: 3118094280 mem, 3208 ms
> 20: 5902184440 mem, 3281 ms
> 21: 3123372736 <tel:3123372736> mem, 3224 ms
> 22: 3112825408 mem, 3259 ms
> 23: 3128648960 <tel:3128648960> mem, 3146 ms
> 24: 3118100760 mem, 3230 ms
> 25: 3133941888 <tel:3133941888> mem, 3119 ms
> 26: 5488982136 mem, 3225 ms
> 27: 3112820248 mem, 3249 ms
> 28: 3128655064 <tel:3128655064> mem, 3154 ms
> 29: 3118110296 mem, 3241 ms
> 30: 3133956392 <tel:3133956392> mem, 3176 ms
> 31: 3123381976 <tel:3123381976> mem, 3220 ms
> 32: 3112831584 mem, 3264 ms
> 33: 3128664576 <tel:3128664576> mem, 3170 ms
> 34: 3118103400 mem, 3209 ms
> 35: 3133956744 <tel:3133956744> mem, 3163 ms
> 36: 3123387312 <tel:3123387312> mem, 3233 ms
> 37: 3112827304 mem, 3279 ms
> 38: 3128664688 <tel:3128664688> mem, 3158 ms
> 39: 3118115152 mem, 3256 ms
> 40: 3133956432 <tel:3133956432> mem, 3128 ms
> 41: 5488994224 mem, 3214 ms
> 42: 5746873888 <tel:5746873888> mem, 3266 ms
> 43: 3128666592 <tel:3128666592> mem, 3174 ms
> 44: 3118109984 mem, 3215 ms
> 45: 3133949360 <tel:3133949360> mem, 3131 ms
> 46: 3123388320 <tel:3123388320> mem, 3207 ms
> 47: 3112843792 mem, 3269 ms
> 48: 3128683960 <tel:3128683960> mem, 3144 ms
> 49: 5617941896 <tel:5617941896> mem, 3201 ms
> 50: 5902216016 mem, 3131 ms
>
>
> Date: Mon, 14 Jul 2014 08:34:45 -0500
> From: Mark Hiner <hinerm at gmail.com <mailto:hinerm at gmail.com>>
> To: Burkhard H?ckendorf <burkhard.hoeckendorf at web.de
> <mailto:burkhard.hoeckendorf at web.de>>
> Cc: "scifio at scif.io <mailto:scifio at scif.io>" <scifio at scif.io
> <mailto:scifio at scif.io>>
> Subject: Re: [SCIFIO] SCIFIO does not seem to release memory of
> closed
> images
> Message-ID:
>
> <CA+B=mGqx47SkUzM___FHGkoyAy3vbpf8+__NMMbURUOSJ65UfeCf3w at mail.__gmail.com
> <mailto:mGqx47SkUzM_FHGkoyAy3vbpf8%2BNMMbURUOSJ65UfeCf3w at mail.gmail.com>>
> Content-Type: text/plain; charset="utf-8"
>
> Hi Burkhard,
>
> > run("Collect Garbage");
>
> This just calls System.gc().. twice, actually. There are many
> articles and
> StackOverflow posts about why System.gc() is unreliable
> <http://stackoverflow.com/__questions/2414105/why-is-it-a-__bad-practice-to-call-system-gc
> <http://stackoverflow.com/questions/2414105/why-is-it-a-bad-practice-to-call-system-gc>__>.
> I personally have seen endlessly repeated System.gc() calls
> effectively do
> nothing, necessitating the creation of large objects to force
> memory to be
> released.
>
> Also, the JVM should automatically attempt to run the garbage
> collector
> when memory is requested for allocation in excess of the JVM's
> memory
> limits. So the best way to test if SCIFIO has a memory leak
> would be:
>
> 1) Open datasets that occupy slightly less than the max memory
> allocated to
> your Fiji
> 2) Close these datasets
> 3) Try opening more datasets (of a size such that, if the
> original datasets
> not released, the total memory used would exceed the max allocation)
>
> If you see OutOfMemory errors then there could quite possibly be
> a leak.
>
> Note also that we have unit tests in place designed to catch
> these leaks:
> https://github.com/scifio/__scifio/blob/master/src/test/__java/io/scif/img/cell/cache/__utests/CacheServiceTest.java
> <https://github.com/scifio/scifio/blob/master/src/test/java/io/scif/img/cell/cache/utests/CacheServiceTest.java>.
> An excellent way to demonstrate the memory error would be to
> come up with
> another test in this class that fails.
>
> Thanks,
> Mark
>
>
> On Sat, Jul 12, 2014 at 1:54 PM, Burkhard H?ckendorf <
> burkhard.hoeckendorf at web.de
> <mailto:burkhard.hoeckendorf at web.de>> wrote:
>
> Dear List,
>
> First of all thanks for developing scifio and doing that
> open source. I
> have started to use it with ImageJ, since Fiji now offers
> the option to use
> it. Having said that, I may also have stumbled upon an
> issue. I'm unsure
> when (or whether) scifio releases the corresponding memory
> after images are
> closed. To look at this in a somewhat systematic way, I ran
> a macro (see
> below) to repeatedly open and close a 3GB single file
> uncompressed TIFF
> stack (2048x2048x367x16bits) and record some performance
> stats along the
> way. I ran this using a new download of Fiji.
>
> Here are the results with scifio disabled:
> 11450 ms to open files
> 28578184 mem before opening files
> 9282667288 <tel:9282667288> mem after opening files
> 9272732560 mem after opening files & GC
> 9272780080 mem after closing files
> 24220936 mem after closing files & GC
>
> And here with scifio enabled:
> 43715 ms to open files
> 26765224 mem before opening files
> 10517954400 mem after opening files
> 9327459480 mem after opening files & GC
> 9327506440 mem after closing files
> 9314822896 <tel:9314822896> mem after closing files & GC
>
> I have also checked, whether memory is freed a couple of
> minutes after
> closing the images, which does not appear to be the case.
>
> Note that scifio is also somewhat slower, although I'm a bit
> hesitant to
> bring this up, because it is still relatively young and I
> can see a few
> "improve ... performance" tickets in the issue tracker.
>
> Below is the macro.
> Kind regards,
> Burkhard
>
>
> nOpenTimes = 3;
> file = "/path/to/stack";
>
> run("Collect Garbage");
> memBefore = IJ.currentMemory();
>
> msToOpen = getTime();
> for (i=0; i<nOpenTimes; i+=1) {
> open(file);
> }
> msToOpen = getTime() - msToOpen;
>
> memFilesOpen = IJ.currentMemory();
> run("Collect Garbage");
> memFilesOpenGC = IJ.currentMemory();
>
> for (i=0; i<nOpenTimes; i+=1) {
> close();
> }
> memFilesClosed = IJ.currentMemory();
> run("Collect Garbage");
> memFilesClosedGC = IJ.currentMemory();
>
> print(""+ msToOpen + " ms to open files");
> print(""+ memBefore + " mem before opening files");
> print(""+ memFilesOpen + " mem after opening files");
> print(""+ memFilesOpenGC + " mem after opening files & GC");
> print(""+ memFilesClosed + " mem after closing files");
> print(""+ memFilesClosedGC + " mem after closing files & GC");
>
> _________________________________________________
> SCIFIO mailing list
> SCIFIO at scif.io <mailto:SCIFIO at scif.io>
> http://scif.io/mailman/__listinfo/scifio
> <http://scif.io/mailman/listinfo/scifio>
>
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL:
> <http://scif.io/pipermail/__scifio/attachments/20140714/__0e7f8b63/attachment-0001.html
> <http://scif.io/pipermail/scifio/attachments/20140714/0e7f8b63/attachment-0001.html>>
>
> ------------------------------
>
> _________________________________________________
> SCIFIO mailing list
> SCIFIO at scif.io <mailto:SCIFIO at scif.io>
> http://scif.io/mailman/__listinfo/scifio
> <http://scif.io/mailman/listinfo/scifio>
>
>
> End of SCIFIO Digest, Vol 11, Issue 5
> ******************************__*******
>
>
> _________________________________________________
> SCIFIO mailing list
> SCIFIO at scif.io <mailto:SCIFIO at scif.io>
> http://scif.io/mailman/__listinfo/scifio
> <http://scif.io/mailman/listinfo/scifio>
>
>
More information about the SCIFIO
mailing list