OMERO in place import, excesive memory requirements

[thusharaw]

I'm seeing an in place import of an ome.tiff fail even with 12G of memory given to the JVM. I will upload the image to the qa location.

It is not likely that we can increase the memory beyond 12G at the moment. Given that, is there anything we can do to the image to reduce the memory requirements?

thx,
thushara

[wmoore]

I'll try importing the file you uploaded...
Can you let us know the version of OMERO you're using and also the output of

$ bin/omero admin diagnostics

Many thanks,

Will.

[wmoore]

Hi, I've managed to reproduce your memory issues in the latest OMERO and Bio-Formats.

There are some recent fixes in Bio-Formats that might help.
We're continuing to investigate...

Regards,

Will.

[thusharaw]

Hi Will -
Thanks for looking into this. I'm on 5.3.3 and I could upgrade to 5.3.4, but if you are seeing the issue there as well, perhaps I will wait to hear from you.

Code: Select all

omero@prd-aics-dcv-006-omero_server:/omero$ OMERO.server/bin/omero admin diagnostics

================================================================================
OMERO Diagnostics 5.3.3-ice36-b63
================================================================================
       
WARNING:omero.util.UpgradeCheck:UPGRADE AVAILABLE:Please upgrade to 5.3.4. See http://downloads.openmicroscopy.org/latest/omero for the latest version.

Commands:   java -version                  1.8.0     (/usr/bin/java)
Commands:   python -V                      2.7.12    (/usr/bin/python)
Commands:   icegridnode --version          3.6.4     (/usr/bin/icegridnode)
Commands:   icegridadmin --version         3.6.4     (/usr/bin/icegridadmin)
Commands:   psql --version                 9.5.8     (/usr/bin/psql)

Server:     icegridnode                    running
Server:     Blitz-0                        active (pid = 889, enabled)
Server:     DropBox                        active (pid = 923, enabled)
Server:     FileServer                     active (pid = 999, enabled)
Server:     Indexer-0                      active (pid = 926, enabled)
Server:     MonitorServer                  active (pid = 916, enabled)
Server:     OMERO.Glacier2                 active (pid = 896, enabled)
Server:     OMERO.IceStorm                 active (pid = 929, enabled)
Server:     PixelData-0                    active (pid = 966, enabled)
Server:     Processor-0                    active (pid = 1023, enabled)
Server:     Tables-0                       active (pid = 1019, enabled)
Server:     TestDropBox                    inactive (enabled)

Log dir:    /omero/OMERO.server/var/log    exists
Log files:  Blitz-0.log                    14.0 MB       errors=0    warnings=125
Log files:  DropBox.log                    1.0 KB       
Log files:  FileServer.log                 0.0 KB       
Log files:  Indexer-0.log                  10.0 KB       errors=0    warnings=1   
Log files:  MonitorServer.log              1.0 KB       
Log files:  OMEROweb.log                   n/a
Log files:  PixelData-0.log                9.0 KB        errors=1    warnings=1   
Log files:  Processor-0.log                59.0 KB     
Log files:  Tables-0.log                   0.0 KB       
Log files:  TestDropBox.log                n/a
Log files:  master.err                     0.0 KB       
Log files:  master.out                     0.0 KB       
Log files:  Total size                     14.76 MB


Environment:OMERO_HOME=/omero/OMERO.server
Environment:OMERO_NODE=(unset)             
Environment:OMERO_MASTER=(unset)           
Environment:OMERO_USERDIR=(unset)         
Environment:OMERO_TMPDIR=(unset)           
Environment:PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
Environment:PYTHONPATH=(unset)             
Environment:ICE_HOME=(unset)               
Environment:LD_LIBRARY_PATH=(unset)       
Environment:DYLD_LIBRARY_PATH=(unset)     

OMERO SSL port:4064                           
OMERO TCP port:4063                           
OMERO data dir:'/omerodata/data'              Exists? True   Is writable? True
OMERO temp dir:'/home/omero/omero/tmp'        Exists? True   Is writable? True   (Size: 0)

JVM settings: Blitz-${index}                -Xmx2523m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: Indexer-${index}              -Xmx1682m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: PixelData-${index}            -Xmx2523m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: Repository-${index}           -Xmx1682m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions

OMERO.web not installed!
Django not installed!
omero@prd-aics-dcv-006-omero_server:/omero$

[wmoore]

I'll add notes on progress here for others in the OME team to access....

First, tried using the lasted DEV builds from https://ci.openmicroscopy.org/job/BIOFO ... rge-build/, downloading the formats-api.jar, formats-gpl.jar, formats-bsd.jar and turbojpeg.jar and placing these in both the lib/server and lib/client dirs of the 5.3.4 server.

This still gave the OOM error on CLI import (with the default 1024M of memory) so then I edited lib/python/omero/plugins/import.py to 4096M in this line:

Code: Select all

xargs = [logback, "-Xmx4096M", "-cp", os.pathsep.join(classpath)]


and repeated $ bin/omero import ppp.ome.xml which resulted in
java.lang.Exception: java.lang.NoClassDefFoundError: ome/codecs/CodecOptions


So, then Seb created a POM for updating the jars more thoroughly at https://github.com/sbesson/bio-formats-omero/

Code: Select all

$ git clone git@github.com:sbesson/bio-formats-omero.git
$ cd bio-formats-omero/
$ mvn clean package -Domero.home=/Users/wmoore/Desktop/OMERO.server-5.3.4-ice36-b69 -Dbioformats.version=5.7.1-SNAPSHOT -Dmaven.repo.local=/tmp/.m2/repository/
...
[INFO] Copying formats-bsd-5.7.1-SNAPSHOT.jar to /Users/wmoore/Desktop/OMERO.server-5.3.4-ice36-b69/lib/client/formats-bsd.jar
[INFO] Copying netcdf-4.3.22.jar to /Users/wmoore/Desktop/OMERO.server-5.3.4-ice36-b69/lib/client/netcdf.jar
[INFO] Copying jgoodies-common-1.7.0.jar to /Users/wmoore/Desktop/OMERO.server-5.3.4-ice36-b69/lib/client/jgoodies-common.jar
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 16.152 s
[INFO] Finished at: 2017-09-13T16:13:13+01:00
[INFO] Final Memory: 18M/276M
[INFO] ------------------------------------------------------------------------


Restarted OMERO and tried importing again...

Code: Select all

$ bin/omero import /Volumes/ome/apache_repo/17929/ppp.ome.tiff
...
2017-09-13 16:16:38,790 77637      [      main] INFO   ormats.importer.cli.LoggingImportMonitor - IMPORT_STARTED Logfile: 921
2017-09-13 16:17:06,291 105138     [l.Client-0] ERROR     ome.formats.importer.cli.ErrorHandler - INTERNAL_EXCEPTION: /Volumes/ome/apache_repo/17929/ppp.ome.tiff
java.lang.RuntimeException: Failure response on import!
Category: ::omero::grid::ImportRequest
Name: import-request-failure
Parameters: {stacktrace=Ice.SocketException
    error = 0
   at IceInternal.AsyncResultI.__wait(AsyncResultI.java:270)
   at omero.api.MetadataStorePrxHelper.end_updateObjects(MetadataStorePrxHelper.java:1104)
   at omero.api.MetadataStorePrxHelper.updateObjects(MetadataStorePrxHelper.java:986)
   at omero.api.MetadataStorePrxHelper.updateObjects(MetadataStorePrxHelper.java:973)
   at ome.formats.OMEROMetadataStoreClient.saveToDB(OMEROMetadataStoreClient.java:1810)
   at ome.services.blitz.repo.ManagedImportRequestI.importMetadata(ManagedImportRequestI.java:629)
   at ome.services.blitz.repo.ManagedImportRequestI.step(ManagedImportRequestI.java:501)
   at omero.cmd.HandleI.steps(HandleI.java:438)
   at omero.cmd.HandleI$1.doWork(HandleI.java:366)
   at omero.cmd.HandleI$1.doWork(HandleI.java:362)
   at sun.reflect.GeneratedMethodAccessor312.invoke(Unknown Source)
   ...
   at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Broken pipe
   at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
   ...
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
   ... 1 more
, message=java.io.IOException: Broken pipe}

   at ome.formats.importer.ImportLibrary$ImportCallback.onFinished(ImportLibrary.java:665)
   at omero.cmd.CmdCallbackI.finished(CmdCallbackI.java:334)
   ...
   at java.lang.Thread.run(Thread.java:745)

...
2017-09-13 16:17:06,295 105142     [      main] ERROR        ome.formats.importer.ImportLibrary - Error on import
java.lang.Exception: Import failure
   at ome.formats.importer.ImportLibrary.importImage(ImportLibrary.java:560) ~[blitz.jar:na]
   at ome.formats.importer.ImportLibrary.importCandidates(ImportLibrary.java:289) ~[blitz.jar:na]
   at ome.formats.importer.cli.CommandLineImporter.start(CommandLineImporter.java:289) [blitz.jar:na]
   at ome.formats.importer.cli.CommandLineImporter.main(CommandLineImporter.java:958) [blitz.jar:na]
2017-09-13 16:17:06,295 105142     [      main] INFO         ome.formats.importer.ImportLibrary - Exiting on error

==> Summary
1 file uploaded, 0 filesets created, 0 images imported, 1 error in 0:00:54.748
!! 09/13/17 16:17:06.800 error: communicator not destroyed during global destruction.ls31618:OMERO.server-5.3.4-ice36-b69 wmoore$


Log in Managed Repo:

Code: Select all

2017-09-13 16:16:38,720 INFO  [    ome.formats.OMEROMetadataStoreClient] (2-thread-3) Call context: {omero.logfilename:will_2/2017-09/13/16-16-11.678.log}
2017-09-13 16:16:38,728 INFO  [         ome.security.basic.EventHandler] (l.Server-0)  Auth:   user=2,group=3,event=null(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:00,736 INFO  [                loci.formats.ImageReader] (2-thread-3) OMETiffReader initializing /OMERO52/ManagedRepository/will_2/2017-09/13/16-16-11.678/ppp.ome.tiff
2017-09-13 16:17:03,680 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-3) Reading IFDs
2017-09-13 16:17:03,709 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-3) Populating metadata
2017-09-13 16:17:04,407 WARN  [    ome.formats.OMEROMetadataStoreClient] (2-thread-3) No annotators linked. Ignoring setXMLAnnotationAnnotator(null, 0(
...
...
2017-09-13 16:17:04,638 INFO  [         ome.security.basic.EventHandler] (l.Server-1)  Auth:   user=2,group=3,event=null(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:05,876 DEBUG [                   loci.formats.Memoizer] (2-thread-3) saved to temp file: /OMERO52/BioFormatsCache/OMERO52/ManagedRepository/will_2/2017-09/13/16-16-11.678/.ppp.ome.tiff.bfmemo4343434822006500334
2017-09-13 16:17:05,876 DEBUG [                   loci.formats.Memoizer] (2-thread-3) start[1505315824695] time[1181] tag[loci.formats.Memoizer.saveMemo]
2017-09-13 16:17:05,876 DEBUG [                   loci.formats.Memoizer] (2-thread-3) saved memo file: /OMERO52/BioFormatsCache/OMERO52/ManagedRepository/will_2/2017-09/13/16-16-11.678/.ppp.ome.tiff.bfmemo (147072801 bytes)
2017-09-13 16:17:05,876 DEBUG [                   loci.formats.Memoizer] (2-thread-3) start[1505315798775] time[27101] tag[loci.formats.Memoizer.setId]
2017-09-13 16:17:05,876 DEBUG [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) Image Count: 490
2017-09-13 16:17:05,877 INFO  [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) File format: OME-TIFF
2017-09-13 16:17:05,877 INFO  [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) Base reader: loci.formats.in.OMETiffReader
2017-09-13 16:17:05,878 DEBUG [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) Step 0
2017-09-13 16:17:05,886 INFO  [    ome.formats.OMEROMetadataStoreClient] (2-thread-3) Handling # of containers: 1009
2017-09-13 16:17:06,193 INFO  [  o.s.b.r.ManagedImportRequestI.@3f11b7d] (2-thread-3) Cancelled
2017-09-13 16:17:06,197 INFO  [         ome.security.basic.EventHandler] (l.Server-8)  Auth:   user=2,group=3,event=null(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:06,214 INFO  [         ome.security.basic.EventHandler] (l.Server-7)  Auth:   user=2,group=3,event=4920(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:06,218 INFO  [       ome.security.basic.CurrentDetails] (l.Server-7) Adding log:UPDATE,class ome.model.core.OriginalFile,921
2017-09-13 16:17:06,239 INFO  [         ome.security.basic.EventHandler] (l.Server-9)  Auth:   user=2,group=3,event=4921(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:06,239 DEBUG [                omero.util.ServantHolder] (l.Server-9) Removed omero.api._RawFileStoreTie@c91c9efc from omero.util.ServantHolder@6e600408 as 93385a62-6f0e-42d7-963e-6412db74319bomero.api.RawFileStore
2017-09-13 16:17:06,239 INFO  [                      omero.cmd.SessionI] (l.Server-9) Unregistered servant:9247fe9d-0d28-42f7-8c18-242204b50244/93385a62-6f0e-42d7-963e-6412db74319bomero.api.RawFileStore(omero.api._RawFileStoreTie@c91c9efc)
2017-09-13 16:17:06,246 INFO  [         ome.security.basic.EventHandler] (l.Server-6)  Auth:   user=2,group=3,event=4922(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:06,247 DEBUG [                omero.util.ServantHolder] (l.Server-6) Removed omero.api._RawPixelsStoreTie@b5ac3860 from omero.util.ServantHolder@6e600408 as 7742f14b-705b-41bd-8ec8-d51c0f230357omero.api.RawPixelsStore
2017-09-13 16:17:06,247 INFO  [                      omero.cmd.SessionI] (l.Server-6) Unregistered servant:9247fe9d-0d28-42f7-8c18-242204b50244/7742f14b-705b-41bd-8ec8-d51c0f230357omero.api.RawPixelsStore(omero.api._RawPixelsStoreTie@b5ac3860)
2017-09-13 16:17:06,248 INFO  [         ome.security.basic.EventHandler] (l.Server-4)  Auth:   user=2,group=3,event=null(User),sess=9247fe9d-0d28-42f7-8c18-242204b50244
2017-09-13 16:17:06,249 DEBUG [                omero.util.ServantHolder] (l.Server-4) Removed omero.api._ThumbnailStoreTie@f4081c58 from omero.util.ServantHolder@6e600408 as 07b1abc3-04b9-4c63-9b6f-876d25ea5902omero.api.ThumbnailStore
2017-09-13 16:17:06,249 INFO  [                      omero.cmd.SessionI] (l.Server-4) Unregistered servant:9247fe9d-0d28-42f7-8c18-242204b50244/07b1abc3-04b9-4c63-9b6f-876d25ea5902omero.api.ThumbnailStore(omero.api._ThumbnailStoreTie@f4081c58)
2017-09-13 16:17:06,249 DEBUG [                omero.util.ServantHolder] (l.Server-2) Removed omero.api._MetadataStoreTie@98e0fc7e from omero.util.ServantHolder@6e600408 as 8c773a50-c7b7-4105-8e6d-a7590b279062omero.api.MetadataStore
2017-09-13 16:17:06,249 INFO  [                      omero.cmd.SessionI] (l.Server-2) Unregistered servant:9247fe9d-0d28-42f7-8c18-242204b50244/8c773a50-c7b7-4105-8e6d-a7590b279062omero.api.MetadataStore(omero.api._MetadataStoreTie@98e0fc7e)
2017-09-13 16:17:06,251 INFO  [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) Finalizing log file.


So, some progress but not there yet!

[wmoore]

Adding server logs for that last failed import....

[mtbc]

The server logs are frustratingly short of clues. All I find of relevance is in Blitz-0.log:

Code: Select all

2017-09-13 16:17:05,877 INFO  [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) File format: OME-TIFF
2017-09-13 16:17:05,877 INFO  [    o.s.blitz.repo.ManagedImportRequestI] (2-thread-3) Base reader: loci.formats.in.OMETiffReader
2017-09-13 16:17:05,886 INFO  [    ome.formats.OMEROMetadataStoreClient] (2-thread-3) Handling # of containers: 1009
2017-09-13 16:17:06,193 INFO  [  o.s.b.r.ManagedImportRequestI.@3f11b7d] (2-thread-3) Cancelled
...
2017-09-13 16:17:06,228 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1505315825878] time[350] tag[omero.request.step.0]
2017-09-13 16:17:06,228 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1505315798683] time[27545] tag[omero.request]
2017-09-13 16:17:06,228 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1505315798677] time[27551] tag[omero.call.exception]
2017-09-13 16:17:06,228 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Excp:   omero.cmd.HandleI$Cancel: import-request-failure
2017-09-13 16:17:06,228 ERROR [        ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 27551
2017-09-13 16:17:06,228 DEBUG [  o.s.b.r.ManagedImportRequestI.@3f11b7d] (2-thread-3) Request cancelled by Ice.SocketException
    error = 0


Mark

[mtbc]

even with 12G of memory given to the JVM

Among the diagnostics output I note,

Code: Select all

JVM settings: Blitz-${index}                -Xmx2523m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: Indexer-${index}              -Xmx1682m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: PixelData-${index}            -Xmx2523m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions
JVM settings: Repository-${index}           -Xmx1682m -XX:MaxPermSize=1g -XX:+IgnoreUnrecognizedVMOptions


You may find that experimenting with the settings described at https://docs.openmicroscopy.org/latest/ ... figuration may assist.

Cheers,
Mark

[thusharaw]

Well, the heap error I got was from the CommandLineImporter which is its own process, so I only changed its JVM settings. I could never get it past that so I did not tinker with the memory settings for Blitz etc.

[mtbc]

I'm sorry, you are quite right, I confused myself by also considering Will's investigation with a later version of Bio-Formats. Once v5.7.1 is released, probably next week, we will deploy an OMERO with that and experiment further with your file.

Separately, you should note that the OME-XML in your file seems rather broken, according to the validator, but I do not yet see any reason to think that this invalid OME-XML is why you are seeing these issues.

Cheers,
Mark