nicost / micro-manager

Microscope control and image acquisition integrated with ImageJ.
http://www.micro-manager.org
16 stars 11 forks source link

Memory Leak #16

Closed nanthony21 closed 6 years ago

nanthony21 commented 6 years ago

I'm Micromanager Gamma using the acquire multiple regions plugin and I notice that the RAM is filling up and causing an error.

The plugin runs the acquisition engine several times. Each time, it recieves the Datastore from the acquisition and then calls freeze() and close().

Datastore store = gui.acquisitions().runAcquisition(currRegion.filename, currRegion.directory); store.freeze(); gui.displays().closeDisplaysFor(store); store.close();

However it doesn't appear that any memory gets freed at store.close(). Even thought the data store is being saved to disk the data store gets up to around 2GB in the ram. But after the store is closed and the store variable is closed this memory sticks around until micromanager is closed.

Thanks, Nick

nicost commented 6 years ago

This may be a real memory leak, or it may not be. There are many different types of memory being used by Micro-Manager and not everything gets automatically released all the time. For instance, the JVM manages memory itself, and does not like to give it back to the OS once it has memory allocate.

First. How do you measure memory? You can easily follow memory being used in the JVM itself using ImageJ > Tools > Utilities > Monitor Memory. Clicking the "bar" in the ImageJ windows invokes the JVM garbage collector, always do this a couple of times to force the JVM memory down. However, even when it garbage collects, it does not necessarily release memory back to the OS. So, when you follow memory usage using Windows tools, you may get a false idea that there is a memory leak. On the other hand, images (pixel data) are allocated by Micro-Manager outside of the JVM, and it is potentially possible that these are not garbage collected. That will also show up in the Windows tools. Try running your script multiple times, to see if the application indeed runs out of memory.

Of course, if the memory can not be re-used, then that is a sure sign that something is not right. I would be helped by a fully reproducible test case (using the demo configuration and an acquisition that I can easily reproduce). I ran a test acquisition (using the GUI rather than by script), and saw nothing out of the ordinary (which does not mean nothing as wrong).

nanthony21 commented 6 years ago

Monitoring the memory through ImageJ's utility shows a fairly stable memory usage around 300mb. However, the Windows Task Manager shows an increase in memory each time that an image is added to an album.

I did some further testing on this and found that I couldn't reproduce this using the Demo Camera. When using the MDA the memory usage constantly climbs. However it gets to well above 16Gb without causing an error like I saw before and it appears that the memory could still be freed if it was needed.

It also seems like the demo camera doesn't fill up the memory nearly as quickly as the PICAM camera that I was using before. This makes me think that maybe it is specific to the PICAM adapters.

I will keep looking into it and see if I can consistently reproduce the issue.

nicost commented 6 years ago

It also seems like the demo camera doesn't fill up the memory nearly as quickly as the PICAM camera that I was using before. This makes me think that maybe it is specific to the PICAM adapters. Are you using the same image size? One way to test the adapter code is run start live mode (from a script):

mmc.startSequenceAcquisition(10000000, 0.0,false);

To test memory usage while snapping images, use:

for (int i = 0; i < 1000000; i++) { mmc.snapImage(); mmc.getImage(); }

nanthony21 commented 6 years ago

I've tracked the issue down to the MultipageTiffWriter. More specifically the ByteBuffer that it uses.

Here is a relevant link. https://stackoverflow.com/questions/1854398/how-to-garbage-collect-a-direct-buffer-java

Here is the traceback from the CoreLog I used to track it down.

2018-10-19T18:11:30.934839 tid14884 [IFO,App] java.lang.OutOfMemoryError: Direct buffer memory
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at java.nio.Bits.reserveMemory(Bits.java:694)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.MultipageTiffWriter.allocateByteBuffer(MultipageTiffWriter.java:219)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.MultipageTiffWriter.allocateByteBufferMemo(MultipageTiffWriter.java:238)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.MultipageTiffWriter.getPixelBuffer(MultipageTiffWriter.java:654)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.MultipageTiffWriter.writeIFD(MultipageTiffWriter.java:564)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.MultipageTiffWriter.writeImage(MultipageTiffWriter.java:444)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.FileSet.writeImage(FileSet.java:161)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.StorageMultipageTiff.startWritingTask(StorageMultipageTiff.java:397)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.StorageMultipageTiff.writeImage(StorageMultipageTiff.java:340)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.StorageMultipageTiff.writeImage(StorageMultipageTiff.java:310)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.multipagetiff.StorageMultipageTiff.putImage(StorageMultipageTiff.java:291)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.DefaultDatastore.putImage(DefaultDatastore.java:222)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.pipeline.BaseContext.outputImage(BaseContext.java:57)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.imageflipper.FlipperProcessor.processImage(FlipperProcessor.java:73)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.pipeline.AsynchronousContext.monitorQueue(AsynchronousContext.java:89)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.pipeline.AsynchronousContext.access$000(AsynchronousContext.java:29)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at org.micromanager.data.internal.pipeline.AsynchronousContext$1.run(AsynchronousContext.java:41)
2018-10-19T18:11:30.934839 tid14884 [IFO,App]   at java.lang.Thread.run(Thread.java:748)
2018-10-19T18:11:32.354920 tid13244 [IFO,App] 
                                    [       ] java.lang.OutOfMemoryError: Direct buffer memory in Thread[TaggedImage sink thread,6,main]
                                    [       ]   at java.nio.Bits.reserveMemory(Bits.java:694)
                                    [       ]   at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
                                    [       ]   at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
                                    [       ]   at org.micromanager.internal.utils.DirectBuffers.bufferFromShorts(DirectBuffers.java:24)
                                    [       ]   at org.micromanager.internal.utils.DirectBuffers.bufferFromArray(DirectBuffers.java:75)
                                    [       ]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:129)
                                    [       ]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:81)
                                    [       ]   at org.micromanager.acquisition.internal.DefaultTaggedImageSink$1.run(DefaultTaggedImageSink.java:68)
2018-10-19T18:11:32.450926 tid13244 [IFO,App] 166 images stored in 238478 ms.
2018-10-19T18:11:40.973413 tid5340 [IFO,App] EDTHangLogger: Missed heartbeat; waiting to see if we are stuck on a single event
2018-10-19T18:11:41.975471 tid5340 [IFO,App] EDTHangLogger: Event handling has exceeded at least 1001 ms (currently 5502 ms since heartbeat timebase)
                                   [       ] Stack traces follow (note: thread states queried later than stack traces)
                                   [       ] Thread 2 [Reference Handler] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.Object.wait(Object.java:502)
                                   [       ]   at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
                                   [       ]   at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
                                   [       ] Thread 3 [Finalizer] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
                                   [       ]   at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
                                   [       ] Thread 4 [Signal Dispatcher] RUNNABLE
                                   [       ] Thread 5 [Attach Listener] RUNNABLE
                                   [       ] Thread 24 [GC Daemon] TIMED_WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at sun.misc.GC$Daemon.run(GC.java:117)
                                   [       ] Thread 25 [RMI TCP Accept-0] RUNNABLE
                                   [       ]   at java.net.DualStackPlainSocketImpl.accept0(Native Method)
                                   [       ]   at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
                                   [       ]   at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
                                   [       ]   at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
                                   [       ]   at java.net.ServerSocket.implAccept(ServerSocket.java:545)
                                   [       ]   at java.net.ServerSocket.accept(ServerSocket.java:513)
                                   [       ]   at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
                                   [       ]   at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 26 [RMI Reaper] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
                                   [       ]   at sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:351)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 27 [Java2D Disposer] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
                                   [       ]   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
                                   [       ]   at sun.java2d.Disposer.run(Disposer.java:148)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 28 [AWT-Shutdown] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.Object.wait(Object.java:502)
                                   [       ]   at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:295)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 29 [AWT-Windows] RUNNABLE
                                   [       ]   at sun.awt.windows.WToolkit.eventLoop(Native Method)
                                   [       ]   at sun.awt.windows.WToolkit.run(WToolkit.java:313)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 31 [AWT-EventQueue-0] RUNNABLE
                                   [       ]   at org.micromanager.acquisition.internal.DefaultTaggedImageSink$2.run(DefaultTaggedImageSink.java:109)
                                   [       ]   at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:311)
                                   [       ]   at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:758)
                                   [       ]   at java.awt.EventQueue.access$500(EventQueue.java:97)
                                   [       ]   at java.awt.EventQueue$3.run(EventQueue.java:709)
                                   [       ]   at java.awt.EventQueue$3.run(EventQueue.java:703)
                                   [       ]   at java.security.AccessController.doPrivileged(Native Method)
                                   [       ]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
                                   [       ]   at java.awt.EventQueue.dispatchEvent(EventQueue.java:728)
                                   [       ]   at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:205)
                                   [       ]   at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
                                   [       ]   at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
                                   [       ]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
                                   [       ]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
                                   [       ]   at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)
                                   [       ] Thread 34 [org.netbeans.modules.debugger.jpda.visual AWT Access Loop] TIMED_WAITING
                                   [       ]   at java.lang.Thread.sleep(Native Method)
                                   [       ]   at org.netbeans.modules.debugger.jpda.visual.remote.RemoteAWTService$AWTAccessLoop.run(RemoteAWTService.java:236)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 35 [D3D Screen Updater] TIMED_WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at sun.java2d.d3d.D3DScreenUpdateManager.run(D3DScreenUpdateManager.java:423)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 36 [DestroyJavaVM] RUNNABLE
                                   [       ] Thread 37 [EDTHangLogger timer] RUNNABLE
                                   [       ]   at java.lang.Thread.dumpThreads(Native Method)
                                   [       ]   at java.lang.Thread.getAllStackTraces(Thread.java:1610)
                                   [       ]   at org.micromanager.internal.diagnostics.EDTHangLogger.checkForHang(EDTHangLogger.java:233)
                                   [       ]   at org.micromanager.internal.diagnostics.EDTHangLogger.access$200(EDTHangLogger.java:34)
                                   [       ]   at org.micromanager.internal.diagnostics.EDTHangLogger$4.run(EDTHangLogger.java:220)
                                   [       ]   at java.util.TimerThread.mainLoop(Timer.java:555)
                                   [       ]   at java.util.TimerThread.run(Timer.java:505)
                                   [       ] Thread 40 [User Profile Saver Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 41 [TimerQueue] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.DelayQueue.take(DelayQueue.java:211)
                                   [       ]   at javax.swing.TimerQueue.run(TimerQueue.java:174)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 44 [Thread-6] TIMED_WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at bsh.util.JConsole$BlockingPipedInputStream.read(JConsole.java:771)
                                   [       ]   at java.io.PipedInputStream.read(PipedInputStream.java:377)
                                   [       ]   at java.io.InputStream.read(InputStream.java:101)
                                   [       ]   at bsh.util.JConsole.inPipeWatcher(JConsole.java:667)
                                   [       ]   at bsh.util.JConsole.run(JConsole.java:677)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 45 [BeanShell interpreter] TIMED_WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.io.PipedInputStream.read(PipedInputStream.java:326)
                                   [       ]   at java.io.PipedInputStream.read(PipedInputStream.java:377)
                                   [       ]   at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
                                   [       ]   at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
                                   [       ]   at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
                                   [       ]   at java.io.InputStreamReader.read(InputStreamReader.java:184)
                                   [       ]   at bsh.JavaCharStream.FillBuff(JavaCharStream.java:160)
                                   [       ]   at bsh.JavaCharStream.ReadByte(JavaCharStream.java:188)
                                   [       ]   at bsh.JavaCharStream.readChar(JavaCharStream.java:289)
                                   [       ]   at bsh.JavaCharStream.BeginToken(JavaCharStream.java:209)
                                   [       ]   at bsh.ParserTokenManager.getNextToken(ParserTokenManager.java:2072)
                                   [       ]   at bsh.Parser.jj_ntk(Parser.java:6022)
                                   [       ]   at bsh.Parser.Line(Parser.java:163)
                                   [       ]   at bsh.Interpreter.Line(Interpreter.java:1011)
                                   [       ]   at bsh.Interpreter.run(Interpreter.java:462)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 54 [Swing-Shell] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at sun.awt.shell.Win32ShellFolderManager2$ComInvoker$3.run(Win32ShellFolderManager2.java:547)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 72 [SnapLiveManager Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 78 [PlaneMetadataInspectorPanel Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 3684 [Thread-3515] TIMED_WAITING
                                   [       ]   at java.lang.Thread.sleep(Native Method)
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:139)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
                                   [       ] Thread 4130 [AbstractDataViewer Pool Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4134 [pool-10-thread-1] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4135 [AnimationController Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
                                   [       ]   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4136 [Stats Compute Queue Compute Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4137 [Stats Compute Queue Bypass Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4138 [Stats Compute Queue Result Pool Thread 0] WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
                                   [       ]   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
                                   [       ]   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4139 [ImageStatsProcessor Pool Thread 0] TIMED_WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
                                   [       ]   at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
                                   [       ]   at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
                                   [       ]   at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4140 [ImageStatsProcessor Pool Thread 1] TIMED_WAITING
                                   [       ]   at sun.misc.Unsafe.park(Native Method)
                                   [       ]   at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
                                   [       ]   at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
                                   [       ]   at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
                                   [       ]   at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
                                   [       ]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
                                   [       ] Thread 4141 [zSelector] WAITING
                                   [       ]   at java.lang.Object.wait(Native Method)
                                   [       ]   at java.lang.Object.wait(Object.java:502)
                                   [       ]   at ij.gui.StackWindow.run(StackWindow.java:229)
                                   [       ]   at java.lang.Thread.run(Thread.java:748)
2018-10-19T18:12:45.783120 tid1588 [IFO,App] EDTHangLogger: First heartbeat after miss (69308 ms since timebase)
2018-10-19T18:12:56.489733 tid1588 [IFO,App] Thread 31 (AWT-EventQueue-0) terminated with uncaught exception
2018-10-19T18:12:56.489733 tid1588 [IFO,App] java.lang.OutOfMemoryError: Direct buffer memory
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at java.nio.Bits.reserveMemory(Bits.java:694)
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at org.micromanager.internal.utils.DirectBuffers.bufferFromShorts(DirectBuffers.java:24)
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at org.micromanager.internal.utils.DirectBuffers.bufferFromArray(DirectBuffers.java:75)
2018-10-19T18:12:56.489733 tid1588 [IFO,App]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:129)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:81)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.snap(DefaultAcquisitionManager.java:245)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at org.micromanager.internal.SnapLiveManager.snap(SnapLiveManager.java:800)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at org.micromanager.quickaccess.internal.controls.SnapButton$2.actionPerformed(SnapButton.java:102)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:2022)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2348)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:402)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:259)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:252)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Component.processMouseEvent(Component.java:6539)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at javax.swing.JComponent.processMouseEvent(JComponent.java:3324)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Component.processEvent(Component.java:6304)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Container.processEvent(Container.java:2239)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Component.dispatchEventImpl(Component.java:4889)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Container.dispatchEventImpl(Container.java:2297)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Component.dispatchEvent(Component.java:4711)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4904)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4535)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4476)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Container.dispatchEventImpl(Container.java:2283)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Window.dispatchEventImpl(Window.java:2746)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.Component.dispatchEvent(Component.java:4711)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:760)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue.access$500(EventQueue.java:97)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue$3.run(EventQueue.java:709)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue$3.run(EventQueue.java:703)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.security.AccessController.doPrivileged(Native Method)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:84)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue$4.run(EventQueue.java:733)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue$4.run(EventQueue.java:731)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.security.AccessController.doPrivileged(Native Method)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventQueue.dispatchEvent(EventQueue.java:730)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:205)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
2018-10-19T18:12:56.490733 tid1588 [IFO,App]   at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)
2018-10-19T18:13:04.692202 tid1588 [IFO,App] Thread 31 (AWT-EventQueue-0) terminated with uncaught exception
2018-10-19T18:13:04.692202 tid1588 [IFO,App] java.lang.OutOfMemoryError: Direct buffer memory
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.nio.Bits.reserveMemory(Bits.java:694)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.internal.utils.DirectBuffers.bufferFromShorts(DirectBuffers.java:24)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.internal.utils.DirectBuffers.bufferFromArray(DirectBuffers.java:75)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:129)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.data.internal.DefaultImage.<init>(DefaultImage.java:81)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.snap(DefaultAcquisitionManager.java:245)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.internal.SnapLiveManager.snap(SnapLiveManager.java:800)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at org.micromanager.quickaccess.internal.controls.SnapButton$2.actionPerformed(SnapButton.java:102)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:2022)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2348)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:402)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:259)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:252)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Component.processMouseEvent(Component.java:6539)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at javax.swing.JComponent.processMouseEvent(JComponent.java:3324)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Component.processEvent(Component.java:6304)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Container.processEvent(Container.java:2239)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Component.dispatchEventImpl(Component.java:4889)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Container.dispatchEventImpl(Container.java:2297)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Component.dispatchEvent(Component.java:4711)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4904)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4535)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4476)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Container.dispatchEventImpl(Container.java:2283)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Window.dispatchEventImpl(Window.java:2746)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.Component.dispatchEvent(Component.java:4711)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:760)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue.access$500(EventQueue.java:97)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue$3.run(EventQueue.java:709)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue$3.run(EventQueue.java:703)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.security.AccessController.doPrivileged(Native Method)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:84)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue$4.run(EventQueue.java:733)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue$4.run(EventQueue.java:731)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.security.AccessController.doPrivileged(Native Method)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventQueue.dispatchEvent(EventQueue.java:730)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:205)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
2018-10-19T18:13:04.692202 tid1588 [IFO,App]   at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)
2018-10-19T18:14:07.859815 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:07.882816 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:07.882816 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:07.883816 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:07.898817 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:07.906818 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:07.913818 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:07.929819 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:07.944820 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:07.959821 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:07.974821 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:07.989822 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:08.004823 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:08.019824 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:08.034825 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:08.049826 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:08.064827 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:08.080827 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:08.080827 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:08.080827 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:09.874930 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:14:09.887931 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:09.909932 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:09.909932 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:09.910932 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:09.924933 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:09.931933 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:09.940934 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:09.955935 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:09.969936 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:09.985936 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:10.000937 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:10.015938 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:10.031939 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:10.046940 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:10.061941 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:10.076942 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:10.091943 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:10.107943 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:10.107943 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:10.107943 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:13.330128 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:14:13.337128 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:13.360129 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:13.360129 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:13.361130 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:13.378130 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:13.385131 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:13.393131 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:13.408132 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:13.423133 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:13.438134 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:13.453135 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:13.469136 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:13.484137 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:13.499137 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:13.514138 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:13.530139 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:13.545140 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:13.559141 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:13.559141 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:13.559141 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:14.778211 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:14:14.784211 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:14.807212 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:14.807212 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:14.808212 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:14.819213 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:14.827213 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:14.834214 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:14.849215 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:14.864215 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:14.880216 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:14.895217 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:14.910218 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:14.925219 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:14.940220 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:14.955221 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:14.971222 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:14.986222 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:15.001223 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:15.001223 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:15.001223 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:19.642489 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:14:19.649489 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:19.666490 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:19.666490 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:19.667490 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:19.681491 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:19.689491 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:19.695492 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:19.711493 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:19.726494 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:19.742494 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:19.757495 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:19.772496 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:19.787497 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:19.802498 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:19.817499 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:19.832500 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:19.847501 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:19.862501 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:19.862501 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:19.862501 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:20.339529 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:14:20.346529 tid1312 [IFO,App] Updating GUI; config pad = true; from cache = false
2018-10-19T18:14:20.371530 tid1312 [IFO,Core] Default autofocus set to TIPFSStatus
2018-10-19T18:14:20.372531 tid1312 [IFO,App] Rebuilding config group table
2018-10-19T18:14:20.372531 tid1312 [IFO,App] Finished rebuilding config group table
2018-10-19T18:14:20.388531 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Calib Time: 0
2018-10-19T18:14:20.394532 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Lamp Hours: 2556
2018-10-19T18:14:20.403532 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Get Power Factor: 100
2018-10-19T18:14:20.418533 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Alarm State: OFF
2018-10-19T18:14:20.433534 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: CLF Mode State: OFF
2018-10-19T18:14:20.448535 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Exacte Mode State: ON
2018-10-19T18:14:20.463536 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Front Panel State: LOCKED
2018-10-19T18:14:20.478537 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Home State: PASS
2018-10-19T18:14:20.493537 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Iris Moving State: TRUE
2018-10-19T18:14:20.508538 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp Ready State: READY
2018-10-19T18:14:20.523539 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Lamp State: ON
2018-10-19T18:14:20.537540 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Light Guide Inserted State: TRUE
2018-10-19T18:14:20.554541 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Power Mode State: INTENSITY
2018-10-19T18:14:20.569542 tid1312 [IFO,dev:XCite-Exacte] XCiteExacte: Unit Status: Shutter State: CLOSED
2018-10-19T18:14:20.569542 tid1312 [IFO,Core] Did update system state cache
2018-10-19T18:14:20.569542 tid1312 [IFO,App] Finished updating GUI
2018-10-19T18:14:21.027568 tid1312 [IFO,App] 
                                   [       ] java.lang.NullPointerException in Thread[Thread-4533,6,main]
                                   [       ]   at org.micromanager.acquisition.internal.DefaultAcquisitionManager.runAcquisition(DefaultAcquisitionManager.java:138)
                                   [       ]   at org.micromanager.acquiremultipleregions.AcquireMultipleRegionsForm$acqThread.run(AcquireMultipleRegionsForm.java:264)
2018-10-19T18:15:53.357849 tid1588 [IFO,App] EDTHangLogger: Stopping monitoring of EDT hangs
2018-10-19T18:15:53.574861 tid1588 [IFO,dev:PWSCam] pl_pvcam_uninit (line 857)
2018-10-19T18:15:56.916053 tid1588 [IFO,Core] Did unload all devices
2018-10-19T18:15:56.916053 tid1588 [IFO,Core] System reset
2018-10-19T18:15:56.949054 tid1588 [IFO,Core] Core session ended
nanthony21 commented 6 years ago

This issue can be reproduced with the demo camera. By using the AcquireMultipleRegions plugin. You may need to run in a few times before the problem appears, after that you will no longer be able to take any images.

You can make the problem appear quicker by increasing the number of pixels in the demo camera

nicost commented 6 years ago

I need better instructions to reproduce the issue. I just started a MDA acquisition with the Demo camera (set to 2048 x 2048 pixels, 16 bits). 84 time points, 21 z-slices, 3 channels, for a total of 41.3 GB (my Windows machine has 32GB of RAM). While running this I see the RAM usage of the JVM sawtooth between about 300 and 900 MB, but no serous accumulation happens, and the total RAM usage of the machine sawtooth between 13.1 GB and 15.4 GB. It is very clear when the JVM does its garbage collection, and there are no signs that significant amounts of RAM are wasted. At the end of the (successful) acquisition, the JVM uses 119MB, and total memory usage on the machine is 13.4GB (lots of apps open), very similar to the beginning. Quitting ImageJ/MM brings it down to 11.4GB.

I don't understand:

"I've tracked the issue down to the MultipageTiffWriter. More specifically the ByteBuffer that it uses."

Clearly something is not releasing memory in your case, and when the MuliPageTiffWriter tries to allocate memory while none is available, it runs into an error. MM uses Direct Buffers for performance reasons (it was impossible to keep up with fast cameras without using them). They are garbage collected like all other objects in Java, by making sure that no more references to them exist. So, it seems that you run into a situation where references to the Direct Buffers (and/or other objects) are kept when they should not be kept. But why do you think that the MultiPageTiffWriter us causing these?

To trouble shoot that problem, one needs to know exactly what situation leads to the problem. So far, I have not been able to replicate the issue, so precise instructions (in the form of set Democamera to 2048x208, 16 bits), set the MDA to these settings, use plugin x with these settings, and see this happen.

nanthony21 commented 6 years ago

It appears that I can't get this problem to occur on a fully compiled version of the MM, only when I am debugging the Java code Maybe it's just an issue in the debugger.

nicost commented 6 years ago

Could be. Java garbage collection is complicated, and Netbeans adds its own layer of tracking stuff (and may be holding onto objects that the Micro-Manager code already let go). Nevertheless, always good to be on the lookout for issues like this.

nicost commented 6 years ago

Also, Mark made some changes in 2.0-beta that should severely lower the memory footprint of the saving code when using multiple positions. I just applied that change to 2.0-gamma.