Slow JPEG processing

[Gebhard]

Hi guys,

I've uploaded some 250 JPEGs from a meeting, which I wanted to share with some colleagues. I noticed however, that it takes awfully long to process the pyramids and thus to create the thumbnails (it's been over 6 hours by now and still not finished).
The Images themselves are nothing fancy, just JPEGs from a digital camera.

Browsing through the forum, I was wondering if this could be connected with these two issues:
1) https://www.openmicroscopy.org/community/viewtopic.php?f=4&t=8380
2) https://www.openmicroscopy.org/community/viewtopic.php?f=4&t=8387

We're running OMERO 5.4.0, on 16 cores and 24 GB of RAM...

Here's a snippet from the log (var/log/PixelData-0.log)

Code: Select all

2017-11-13 19:30:16,830 INFO  [                ome.io.nio.PixelsService] (2-thread-3) SUCCESS -- Pyramid created for pixels id:2660
2017-11-13 19:30:16,835 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-3) Reading IFDs
2017-11-13 19:30:16,835 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-3) Populating metadata
2017-11-13 19:30:16,835 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) Unknown JPEG 2000 box 0x290000 at 4408
2017-11-13 19:30:16,835 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) File is a raw codestream not a JP2.
2017-11-13 19:30:16,835 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) Unknown JPEG 2000 box 0x290000 at 6654365
2017-11-13 19:30:16,836 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) File is a raw codestream not a JP2.
2017-11-13 19:30:16,836 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) Unknown JPEG 2000 box 0x290000 at 13264810
2017-11-13 19:30:16,836 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) File is a raw codestream not a JP2.
2017-11-13 19:30:16,836 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-3) Unknown JPEG 2000 box 0x6e24480e at 1730299
2017-11-13 19:30:16,836 INFO  [              loci.formats.in.TiffReader] (2-thread-3) Checking comment style
2017-11-13 19:30:16,842 INFO  [          loci.formats.in.BaseTiffReader] (2-thread-3) Populating OME metadata
2017-11-13 19:30:19,005 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2663 741/741 (99%).
2017-11-13 19:30:19,152 INFO  [                ome.io.nio.PixelsService] (2-thread-2) SUCCESS -- Pyramid created for pixels id:2663
2017-11-13 19:30:19,154 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-2) Reading IFDs
2017-11-13 19:30:19,155 INFO  [       loci.formats.in.MinimalTiffReader] (2-thread-2) Populating metadata
2017-11-13 19:30:19,155 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) Unknown JPEG 2000 box 0x290000 at 4408
2017-11-13 19:30:19,155 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) File is a raw codestream not a JP2.
2017-11-13 19:30:19,155 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) Unknown JPEG 2000 box 0x290000 at 5361694
2017-11-13 19:30:19,155 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) File is a raw codestream not a JP2.
2017-11-13 19:30:19,156 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) Unknown JPEG 2000 box 0x290000 at 10629906
2017-11-13 19:30:19,156 INFO  [  loci.formats.in.JPEG2000MetadataParser] (2-thread-2) File is a raw codestream not a JP2.
2017-11-13 19:30:19,156 INFO  [              loci.formats.in.TiffReader] (2-thread-2) Checking comment style
2017-11-13 19:30:19,157 INFO  [          loci.formats.in.BaseTiffReader] (2-thread-2) Populating OME metadata
2017-11-13 19:31:37,050 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-2) Added StatsInfo:4348 for ome.model.core.Channel:Id_6153 - C:0 Max:255.0 Min:0.0
2017-11-13 19:31:37,051 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-2) Added StatsInfo:4349 for ome.model.core.Channel:Id_6154 - C:1 Max:255.0 Min:0.0
2017-11-13 19:31:37,052 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-2) Added StatsInfo:4350 for ome.model.core.Channel:Id_6155 - C:2 Max:255.0 Min:0.0
2017-11-13 19:31:37,052 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-2) HANDLED EventLog:148349(entityId=2663) [252864 ms.]
2017-11-13 19:31:37,057 ERROR [        ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork invocation took 252868
2017-11-13 19:31:49,404 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-3) Added StatsInfo:4351 for ome.model.core.Channel:Id_6144 - C:0 Max:255.0 Min:0.0
2017-11-13 19:31:49,406 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-3) Added StatsInfo:4352 for ome.model.core.Channel:Id_6145 - C:1 Max:255.0 Min:3.0
2017-11-13 19:31:49,407 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-3) Added StatsInfo:4353 for ome.model.core.Channel:Id_6146 - C:2 Max:255.0 Min:0.0
2017-11-13 19:31:49,408 INFO  [ ome.services.pixeldata.PixelDataHandler] (2-thread-3) HANDLED EventLog:148350(entityId=2660) [265218 ms.]
2017-11-13 19:31:49,411 ERROR [        ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 265223
2017-11-13 19:31:49,435 INFO  [             ome.io.nio.FilePathResolver] (2-thread-2) Metadata only file, resulting path: /OMERO/ManagedRepository/SPP1757_152/2017-11/13/13-49-56.498/IMG_6948.JPG
2017-11-13 19:31:49,437 INFO  [             ome.io.nio.FilePathResolver] (2-thread-5) Metadata only file, resulting path: /OMERO/ManagedRepository/SPP1757_152/2017-11/13/13-49-51.132/IMG_6946.JPG
2017-11-13 19:31:49,532 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Creating BfPixelBuffer: /OMERO/ManagedRepository/SPP1757_152/2017-11/13/13-49-56.498/IMG_6948.JPG Series: 0
2017-11-13 19:31:49,532 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Destination pyramid tile size: java.awt.Dimension[width=256,height=256]
2017-11-13 19:31:49,532 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 1/741 (0%).
2017-11-13 19:31:49,535 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Creating BfPixelBuffer: /OMERO/ManagedRepository/SPP1757_152/2017-11/13/13-49-51.132/IMG_6946.JPG Series: 0
2017-11-13 19:31:49,535 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Destination pyramid tile size: java.awt.Dimension[width=256,height=256]
2017-11-13 19:31:49,535 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 1/741 (0%).
2017-11-13 19:32:14,092 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 75/741 (9%).
2017-11-13 19:32:24,645 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 75/741 (9%).
2017-11-13 19:32:29,169 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 149/741 (19%).
2017-11-13 19:32:41,925 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 149/741 (19%).
2017-11-13 19:32:43,532 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 223/741 (29%).
2017-11-13 19:32:57,352 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 223/741 (29%).
2017-11-13 19:33:11,755 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 297/741 (39%).
2017-11-13 19:33:24,144 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 297/741 (39%).
2017-11-13 19:33:26,344 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 371/741 (49%).
2017-11-13 19:33:39,346 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 371/741 (49%).
2017-11-13 19:33:41,157 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 445/741 (59%).
2017-11-13 19:33:53,881 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 445/741 (59%).
2017-11-13 19:34:09,828 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 519/741 (69%).
2017-11-13 19:34:21,391 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 519/741 (69%).
2017-11-13 19:34:26,109 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 593/741 (79%).
2017-11-13 19:34:35,645 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 593/741 (79%).
2017-11-13 19:34:42,037 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 667/741 (89%).
2017-11-13 19:34:50,289 INFO  [                ome.io.nio.PixelsService] (2-thread-2) Pyramid creation for Pixels:2664 667/741 (89%).
2017-11-13 19:34:57,390 INFO  [                ome.io.nio.PixelsService] (2-thread-5) Pyramid creation for Pixels:2662 741/741 (99%).
2017-11-13 19:34:57,557 INFO  [                ome.io.nio.PixelsService] (2-thread-5) SUCCESS -- Pyramid created for pixels id:2662


Best,
Gebhard

[mtbc]

Dear Gebhard,

That many JPEGs may well take a good while for the pyramid-building because it is typically done in few threads. You may wish to experiment with https://docs.openmicroscopy.org/latest/ ... ta-threads to see if it brings any improvement. It may help if you could share with us,

• output from, bin/omero config get --hide-password
• upload your zipped var/log/ directory from the OMERO server (thanks for the extract though!)
• upload a representative sample of your JPEGs and/or
• give us an idea how large these JPEGs are (file size and pixels size)

then we'll be glad to check things on our side but I would guess our initial moves might be for you to check how many cores are actually busy with the pyramid generation and see if we can help you to increase that.

Cheers,
Mark

[Gebhard]

Hi Mark,

I have set the omero.pixeldata.threads to 8 just a second ago. Previously it was at its default value.

here's theoutput from bin/omero config get --hide-password

Code: Select all

omero.client.browser.thumb_default_size=192
omero.client.ui.tree.orphans.name=Not Assigned
omero.data.dir=/OMERO
omero.db.name=omerodb
omero.db.pass=********
omero.db.user=dbomero
omero.fs.dirImportWait=180
omero.fs.importArgs=--transfer=upload_rm
omero.mail.config=true
omero.mail.from=omero@kirchhoff-lab.de
omero.mail.port=25
omero.mail.smtp.auth=true
omero.mail.smtp.connectiontimeout=60000
omero.mail.smtp.socketFactory.fallback=true
omero.mail.smtp.starttls.enable=false
omero.mail.smtp.timeout=60000
omero.pixeldata.threads=8
omero.web.application_server=wsgi-tcp
omero.web.application_server.host=10.60.8.228
omero.web.application_server.port=4064
omero.web.apps=["tag_gallery", "omero_figure", "omero_iviewer"]
omero.web.login_logo=http://kirchhoff-lab.de/images/MolPhysiol-EN-s.jpg
omero.web.open_with=[["Image viewer", "webindex", {"supported_objects": ["image"], "script_url": "webclient/javascript/ome.openwith_viewer.js"}], ["omero_figure", "new_figure", {"supported_objects": ["images"], "target": "_blank", "label": "OMERO.figure"}], ["omero_iviewer", "omero_iviewer_index", {"supported_objects": ["image"], "script_url": "omero_iviewer/openwith.js", "label": "OMERO.iviewer"}]]
omero.web.public.enabled=True
omero.web.public.password=********
omero.web.public.url_filter=^/(webadmin/myphoto/|webclient/(?!(script_ui|ome_tiff|figure_script))|webgateway/(?!(archived_files|download_as)))
omero.web.public.user=Zons-public
omero.web.ui.top_links=[["Data", "webindex", {"title": "Browse Data via Projects, Tags etc"}], ["History", "history", {"title": "History"}], ["Help", "http://help.openmicroscopy.org/", {"target": "new", "title": "Open OMERO user guide in a new tab"}], ["Gallery", "tag_gallery_index", {"title": "Open Image Gallery"}], ["Figure", "figure_index", {"target": "_blank", "title": "Open Figure in new tab"}]]


the JPEGs have apixel size of 4752 x 3168 pixels and a typical data size of 5 to 7 MB.

Where can I upload the zipped var/log directory and the sample image? I tried to attach it to my post, but apparently the files are not valid for uploading...

Do you need the Blitz-0.log file? If not, I would exclude it from the zip, since it has a size of about 300 MB...

Best,
Gebhard

[mtbc]

Dear Gebhard,

Great, thank you. Let's hope that the increased thread count brings you a commensurate performance increase - do keep us posted. http://qa.openmicroscopy.org.uk/qa/upload/ should accept files ending *.zip and server logs usually compress pretty well so do include the Blitz log if you can.

Cheers,
Mark

[Gebhard]

Hi Mark,

I finally found some time to upload the logs and a sample image.


Best,
Gebhard

[mtbc]

Dear Gebhard,

Importing your sample image to a server with default configuration on my local not-new laptop works nicely, it takes under 17 seconds to twice-over make 741 256×256 tiles from a pair of your 6MB files. Whereas, when your server starts similar processing at 2017-11-13 22:51 it takes well over three minutes to build a similar pair of pyramids for IMG_6905.JPG and IMG_6906.JPG! I don't see any sign of anything dreadful happening in your logs around then. It might be worth carefully monitoring your server during such an import from a sysadmin's point of view to see if OMERO's PixelData process seems to have enough memory, what's going on with the I/O bandwidth, etc.: there may be some system bottleneck that makes itself obvious.

Cheers,
Mark