bfconvert very slow when converting to ome.tiff to a disk where writing is "slow"

[anntzer]

I have a metamorph nd acquisition (a nd file and "many" tiff files: 27 positions x 55 time points, each of the 512x1024 16-bit pixels -- overall ~1.5Gb) on a network drive.
Downloading the acquisition to my local disk takes 22s, converting that acquisition to an ome.tiff with bfconvert takes ~1min, then reuploading the resulting single ome.tiff to the network drive takes 45s.
In fact, I don't even need to pre-download the data: I can also let bfconvert directly take the data on the network drive as input and write the ome.tiff on my local disk; this takes essentially the same amount of time as if the data has been downloaded first.

On the other hand, if I try to make bfconvert directly write the resulting ome.tiff file on the network drive, then things become extremely slow: the conversion takes ~30min. My entirely unsubstantiated guess is that this may be because bfconvert perhaps tries to make many short writes, rather than buffering the output internally and emit bigger blocks at once?

[dgault]

Thanks @anntzer for raising the issue, this is something we will likely have to profile to determined exactly which operations are causing the reduced performance.

[anntzer]

Let me know if I can help with that.

[anntzer]

@dgault Anything I can do to move this forward? I can try profiling if you can point me to instructions on how to do that.

[dgault]

Hi @anntzer, if you were able to do some profiling that would be a great help. One tool I would recommend using would be VisualVM.

If you open VisualVM and start the bfconvert tool, you should see loci.formats.tools.ImageConverter under the list of applications.

If you click on loci.formats.tools.ImageConverter and then select profiler. From here you can select CPU, Memory or JDBC. If you select CPU, then this should give you a list which you can expand to show which calls are taking the most time. If you expand the list of the most time consuming calls as far down as you can you will start to see something similar to below:

If you could save that profile snapshot or get a good screen grab of the expanded list of calls, that should be a good starting point to highlight the root cause of the issue.

[anntzer]

There it is.

Looking at it, I guess AbstractNIOHandle.setLength (https://github.com/ome/ome-common-java/blob/eafa3055e12e450b14a85f878a31b6a1ce6e81a2/src/main/java/loci/common/NIOFileHandle.java#L227) is perhaps a bit inefficient in that it only reserves exactly the amount of space requested, and allocating that space in bigger chunks (with some slack) could perhaps help. (But I don't know how to build the library to try...)

[dgault]

Thanks @anntzer, was that for the full file? If so it looks like the majority of the time is spent writing the metadata values rather than the pixel data, so it seems to be the large number of writes for the metadata that is the bottleneck. Actually, looking back it seems we had tried to solve a similar issue with the pixel data previously, so a similar solution may be possible for the metadata values as well: #3239

[anntzer]

The previous run was not for a full file (I ctrl-c'd at some point), because it takes so long; here's a full run:

setLength seems to account for ~2/3 of the total runtime.

[imagesc-bot]

This issue has been mentioned on Image.sc Forum. There might be relevant details there:

https://forum.image.sc/t/pyramidometiffwriter-really-bad-performance-when-closing-the-writer/95294/9

[sbesson]

Closing as per #4242, the writing improvements should be included in the upcoming Bio-Formats 8 release