BUG: multi-z images tile loading

[pwalczysko]

TILE LOADING:
Both on 5.1.4 and 5.2.2 servers, default jvm settings, default tile size.

By eye for fake image z=12000, y=3000, c=3:

• open an image in Full viewer, make sure you are on the lowest zoom
• drag the zoom to highest and count slowly, stop counting when the image in Insight becomes interactive again
• z=1 -> less than a second
• z=400 -> 4 seconds
• z=800 -> 6 seconds

By CLI metrics
Experiment 1

• open an image in Full viewer of Insight, be in the lowest zoom (always the case in 522, not the case in 514)
• in case you are not in the lowest zoom, drag the slider to lowest zoom and wait till operation finishes
• drag the slider to zoom in into the highest zoom
• take jstacks every second starting before you open the image in Full Viewer and finishing when the image is again interactive in Full Viewer in Insight and in full zoom
• take also logs after these actions

The results, jstacks and logs of Experiment1 are on team/pwalczysko/Experiment1

It is clear, that the amount of z planes has detrimental influence on the tile loading.
Further metrics (514 and web) to come).

[pwalczysko]

see also ​https://trello.com/c/cO0va6Ni/48-big-images-testing

[jamoore]

In general:

jamoore@necromancer /ome/team/pwalczysko/Experiment1/522-bigtiff-fiji-400z/522server-bigtiff-jstacks/tmp $ grep -l BfPixelBuffer *
server522-bigtiff-z400jstack-1
server522-bigtiff-z400jstack-11
server522-bigtiff-z400jstack-13
server522-bigtiff-z400jstack-14
server522-bigtiff-z400jstack-15
server522-bigtiff-z400jstack-2
server522-bigtiff-z400jstack-3
server522-bigtiff-z400jstack-5
server522-bigtiff-z400jstack-6
server522-bigtiff-z400jstack-7

For example:

# /ome/team/pwalczysko/Experiment1/522-bigtiff-fiji-400z/522server-bigtiff-jstacks/tmp/server522-bigtiff-z400jstack-11
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.NativeThread.current(Native Method)
        at sun.nio.ch.NativeThreadSet.add(NativeThreadSet.java:46)
        at sun.nio.ch.FileChannelImpl.readInternal(FileChannelImpl.java:727)
        at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:716)
        at loci.common.NIOByteBufferProvider.allocateDirect(NIOByteBufferProvider.java:127)
        at loci.common.NIOByteBufferProvider.allocate(NIOByteBufferProvider.java:112)
        at loci.common.NIOFileHandle.buffer(NIOFileHandle.java:602)
        at loci.common.NIOFileHandle.seek(NIOFileHandle.java:293)
        at loci.common.RandomAccessInputStream.seek(RandomAccessInputStream.java:174)
        at loci.formats.tiff.OnDemandLongArray.get(OnDemandLongArray.java:70)
        at loci.formats.tiff.IFD.getStripOffsets(IFD.java:752)
        at loci.formats.in.MinimalTiffReader.initFile(MinimalTiffReader.java:476)
        at loci.formats.FormatReader.setId(FormatReader.java:1426)
        at ome.io.bioformats.OmeroPixelsPyramidReader.setId(OmeroPixelsPyramidReader.java:88)
        at ome.io.bioformats.BfPixelsWrapper.<init>(BfPixelsWrapper.java:49)
        at ome.io.bioformats.BfPixelBuffer.reader(BfPixelBuffer.java:68)
        at ome.io.bioformats.BfPixelBuffer.isLittleEndian(BfPixelBuffer.java:93)
        at ome.io.bioformats.BfPyramidPixelBuffer.initializeReader(BfPyramidPixelBuffer.java:209)
        - locked <0x000000064fc4ecb0> (a ome.io.bioformats.BfPyramidPixelBuffer)
        at ome.io.bioformats.BfPyramidPixelBuffer.delegate(BfPyramidPixelBuffer.java:482)
        at ome.io.bioformats.BfPyramidPixelBuffer.setResolutionLevel(BfPyramidPixelBuffer.java:1240)
        - locked <0x000000064fc4ecb0> (a ome.io.bioformats.BfPyramidPixelBuffer)
        at omeis.providers.re.Renderer.setResolutionLevel(Renderer.java:881)

# /ome/team/pwalczysko/Experiment1/522-bigtiff-fiji-400z/522server-bigtiff-jstacks/tmp/server522-bigtiff-z400jstack-15
"Blitz-0-Ice.ThreadPool.Server-223" prio=10 tid=0x00007f25c4014000 nid=0x3765 runnable [0x00007f2605db1000]
   java.lang.Thread.State: RUNNABLE
        at jj2000.j2k.wavelet.synthesis.SynWTFilterInt.synthetize_lpf(SynWTFilterInt.java:199)
        at jj2000.j2k.wavelet.synthesis.InvWTFull.wavelet2DReconstruction(InvWTFull.java:475)
        at jj2000.j2k.wavelet.synthesis.InvWTFull.waveletTreeReconstruction(InvWTFull.java:577)
        at jj2000.j2k.wavelet.synthesis.InvWTFull.getInternCompData(InvWTFull.java:314)
        at jj2000.j2k.image.ImgDataConverter.getData(ImgDataConverter.java:280)
        at jj2000.j2k.image.ImgDataConverter.getInternCompData(ImgDataConverter.java:236)
        at jj2000.j2k.image.invcomptransf.InvCompTransf.getInternCompData(InvCompTransf.java:391)
        at com.sun.media.imageioimpl.plugins.jpeg2000.J2KReadState.readSubsampledRaster(J2KReadState.java:862)
        at com.sun.media.imageioimpl.plugins.jpeg2000.J2KReadState.readAsRaster(J2KReadState.java:437)
        at com.sun.media.imageioimpl.plugins.jpeg2000.J2KImageReader.readRaster(J2KImageReader.java:556)
        at loci.formats.services.JAIIIOServiceImpl.readRaster(JAIIIOServiceImpl.java:176)
        at loci.formats.codec.JPEG2000Codec.decompress(JPEG2000Codec.java:290)
        at loci.formats.tiff.TiffCompression.decompress(TiffCompression.java:279)
        at loci.formats.tiff.TiffParser.getTile(TiffParser.java:743)
        at loci.formats.tiff.TiffParser.getSamples(TiffParser.java:986)
        at loci.formats.tiff.TiffParser.getSamples(TiffParser.java:783)
        at loci.formats.in.MinimalTiffReader.openBytes(MinimalTiffReader.java:299)
        at ome.io.bioformats.BfPixelsWrapper.getTile(BfPixelsWrapper.java:343)
        at ome.io.bioformats.BfPixelBuffer.getTile(BfPixelBuffer.java:470)
        at ome.io.bioformats.BfPyramidPixelBuffer.getTile(BfPyramidPixelBuffer.java:1013)
        - locked <0x000000064fcbd058> (a ome.io.bioformats.BfPyramidPixelBuffer)
        at omeis.providers.re.data.PlaneFactory.createPlane(PlaneFactory.java:186)
        at omeis.providers.re.HSBStrategy.getWavelengthData(HSBStrategy.java:103)
        at omeis.providers.re.HSBStrategy.makeRenderingTasks(HSBStrategy.java:217)
        at omeis.providers.re.HSBStrategy.render(HSBStrategy.java:312)
        at omeis.providers.re.HSBStrategy.renderAsPackedInt(HSBStrategy.java:276)
        at omeis.providers.re.Renderer.renderAsPackedInt(Renderer.java:507)

[pwalczysko]

Attached 4 screenshots which show the result from devtools in Chrome on 5.2.2 release server of Experiment1 (in the open image zoomed out to minimum level, twice zoom in). The same screenshots are also on team/pwalczysko/Experiment1/
The screenshot capture just a fraction of what the developer tool can do, but then again it is not easy to get the outputs from the tool in preservable form.

[pwalczysko]

The 5.1.4 release server metrics for Insight and server are now added under team/pwalczysko/Experiment1/514-bigtiff... and team/pwalczysko/Experiment1/514-fake-images-row...

[pwalczysko]

5.1.4 web metrics screenshots attached here as well as on team/pwalczysko/Experiment1...

I consider the work here to finished, is there anything to do more ?
@joshmoore

[pwalczysko]

Note that the z-seciton loaded during the experiment is always the one which is loaded by default by clients, which is the "middle" one.
so it is the middle one, which would be for z=400 approx z200
for z=800 approx z400
for z=1 of course z1

[mlinkert]

Had discussed this briefly with Josh yesterday, and tried to reproduce locally. With the 1200x3000x400Z fake image, I do see a ~90 minute pyramid generation time and >10sec loading times when switching zoom levels or Z sections. What I don't see though is any indication in the logs of Memoizer being called on the pyramid file, and 'find / -name .*.bfmemo' (on my local server) doesn't turn up anything that corresponds to the pyramid file. The imported .fake gets a memo file, but not the generated pyramid.

Unless I'm completely missing something here, maybe just adding Memoizer to the OmeroPixelsPyramidReader? stack will resolve this?

[jamoore]

Should be simple enough that it would certainly be worth someone's trying it.