Warning: Can't synchronize with repository "(default)" (/home/git/ome.git does not appear to be a Git repository.). Look in the Trac log for more information.
Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #10337 (closed)

Opened 11 years ago

Closed 10 years ago

Last modified 10 years ago

Bug: RE.renderCompressed() calling BF.setId()

Reported by: wmoore Owned by: jamoore
Priority: critical Milestone: 5.0.3
Component: Services Version: 5.0.1
Keywords: FS Cc: fs@…, cxallan
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: 0.0d
Sprint: n.a.

Description

With file FV1000.oib/aryeh.oib in FS, I run the following code, which initialises a Rendering Engine once, then renders all the planes in the image.

def renderPlanesNoBlitz(sf, pixelsId, sizeZ, sizeC, sizeT):

    planeCount = sizeZ * sizeC * sizeT

    re = sf.createRenderingEngine()
    re.lookupPixels(pixelsId)
    if not re.lookupRenderingDef(pixelsId):
        re.resetDefaults()
        re.lookupRenderingDef(pixelsId)
    re.load()

    for c in range(sizeC):
        re.setActive(c, False)

    now = time.time()
    pd = omero.romio.PlaneDef(omero.romio.XY)
    for c in range(sizeC):
        re.setActive(c, True)
        for z in range(sizeZ):
            for t in range(sizeT):
                pd.t = t
                pd.z = z
                data = re.renderCompressed(pd)

    duration = time.time() - now
    print "Rendered %s planes in %s secs. %s secs/plane" % (planeCount, duration, duration/planeCount)      # E.g. 0.27 secs / plane (1h.oib)

Looking at the Blitz logs I see this repeated (for every plane):

Seems like a lot of metadata parsing is happening for each call of re.renderCompressed().

2013-02-06 15:09:38,898 INFO  [              loci.formats.FormatHandler] (l.Server-0) Populating metadata
2013-02-06 15:09:38,900 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-0) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2013-02-06 15:09:38,901 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-0) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2013-02-06 15:09:38,901 WARN  [              loci.formats.FormatHandler] (l.Server-0) Expected positive value for EmissionWavelength; got 0
2013-02-06 15:09:38,901 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-0) Unknown LaserMedium value 'None' will be stored as "Other"
2013-02-06 15:09:38,913 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-0) taskCount: 8 delta: 128
2013-02-06 15:09:38,982 INFO  [                 org.perf4j.TimingLogger] (l.Server-0) start[1360163378698] time[284] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2013-02-06 15:09:38,982 INFO  [        ome.services.util.ServiceHandler] (l.Server-0)  Rslt:	[-1, -40, -1, ... 1 more]
2013-02-06 15:09:38,983 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Meth:	interface omeis.providers.re.RenderingEngine.renderCompressed
2013-02-06 15:09:38,983 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Args:	[Type: XY, z=0, t=11]
2013-02-06 15:09:38,983 INFO  [             omeis.providers.re.Renderer] (l.Server-9) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-06 15:09:39,177 INFO  [              loci.formats.FormatHandler] (l.Server-9) Initializing helper readers
2013-02-06 15:09:39,177 INFO  [              loci.formats.FormatHandler] (l.Server-9) Reading additional metadata
2013-02-06 15:09:39,185 INFO  [              loci.formats.FormatHandler] (l.Server-9) Populating metadata
2013-02-06 15:09:39,186 INFO  [              loci.formats.FormatHandler] (l.Server-9) Reading bitmap header
2013-02-06 15:09:39,186 INFO  [              loci.formats.FormatHandler] (l.Server-9) Populating metadata
2013-02-06 15:09:39,189 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-9) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2013-02-06 15:09:39,189 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-9) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2013-02-06 15:09:39,189 WARN  [              loci.formats.FormatHandler] (l.Server-9) Expected positive value for EmissionWavelength; got 0
2013-02-06 15:09:39,189 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-9) Unknown LaserMedium value 'None' will be stored as "Other"
2013-02-06 15:09:39,201 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-9) taskCount: 8 delta: 128
2013-02-06 15:09:39,264 INFO  [                 org.perf4j.TimingLogger] (l.Server-9) start[1360163378983] time[281] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2013-02-06 15:09:39,264 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Rslt:	[-1, -40, -1, ... 1 more]
2013-02-06 15:09:39,265 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Meth:	interface omeis.providers.re.RenderingEngine.renderCompressed
2013-02-06 15:09:39,265 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Args:	[Type: XY, z=0, t=12]
2013-02-06 15:09:39,265 INFO  [             omeis.providers.re.Renderer] (l.Server-3) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-06 15:09:39,451 INFO  [              loci.formats.FormatHandler] (l.Server-3) Initializing helper readers
2013-02-06 15:09:39,451 INFO  [              loci.formats.FormatHandler] (l.Server-3) Reading additional metadata
2013-02-06 15:09:39,460 INFO  [              loci.formats.FormatHandler] (l.Server-3) Populating metadata
2013-02-06 15:09:39,460 INFO  [              loci.formats.FormatHandler] (l.Server-3) Reading bitmap header
2013-02-06 15:09:39,460 INFO  [              loci.formats.FormatHandler] (l.Server-3) Populating metadata

Change History (20)

comment:1 Changed 11 years ago by wmoore

Using an FS image (as described above) the result I see printed at the end is

Rendered 48 planes in 13.5455179214 secs. 0.28219829003 secs/plane

If I use an image of the same size, with Pixels (generated by running Channel_Offsets.py script with the image above), and run the test again, I don't see the metadata statements in the log, and the result is 

Rendered 48 planes in 3.35520219803 secs. 0.0699000457923 secs/plane

comment:2 Changed 11 years ago by wmoore

Here's the full test code. NB: I haven't created an OmeroPy/test since I'd have to add the image to the code repo and also wait for an import to happen every time I run the test.

from omero.gateway import BlitzGateway, ProxyObjectWrapper
import omero
import time

imageId = 3
conn = BlitzGateway('root', 'omero')
conn.connect()
image = conn.getObject("Image", imageId)

def renderPlanesNoBlitz(sf, pixelsId, sizeZ, sizeC, sizeT):

    planeCount = sizeZ * sizeC * sizeT
    re = sf.createRenderingEngine()
    re.lookupPixels(pixelsId)
    if not re.lookupRenderingDef(pixelsId):
        re.resetDefaults()
        re.lookupRenderingDef(pixelsId)
    re.load()

    for c in range(sizeC):
        re.setActive(c, False)

    now = time.time()
    pd = omero.romio.PlaneDef(omero.romio.XY)
    for c in range(sizeC):
        re.setActive(c, True)
        for z in range(sizeZ):
            for t in range(sizeT):
                pd.t = t
                pd.z = z
                data = re.renderCompressed(pd)

    duration = time.time() - now
    print "Rendered %s planes in %s secs. %s secs/plane" % (planeCount, duration, duration/planeCount)      # E.g. 0.27 secs / plane (1h.oib)

renderPlanesNoBlitz(conn.c.sf, image.getPixelsId(), image.getSizeZ(), image.getSizeC(), image.getSizeT())

comment:3 Changed 11 years ago by wmoore

Just for comparison, rendering with webtest/render_performance, which creates a new RE for each plane, the FS image renders at 0.708 secs / plane (48 planes) and the Non-FS image is 0.535 / plane.

comment:4 Changed 11 years ago by wmoore

NB: I see the same issue when looking at this image in Insight. Once the main image-viewer is open, each click to display a new plane gives the following output in the server Blitz log:

2013-02-07 10:28:34,792 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Meth:	interface omeis.providers.re.RenderingEngine.setDefaultT
2013-02-07 10:28:34,792 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Args:	[9]
2013-02-07 10:28:34,792 INFO  [                 org.perf4j.TimingLogger] (l.Server-6) start[1360232914792] time[0] tag[omero.call.success.ome.services.RenderingBean.setDefaultT]
2013-02-07 10:28:34,792 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Rslt:	null
2013-02-07 10:28:34,794 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Meth:	interface omeis.providers.re.RenderingEngine.renderAsPackedInt
2013-02-07 10:28:34,794 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Args:	[Type: XY, z=0, t=9]
2013-02-07 10:28:34,794 INFO  [             omeis.providers.re.Renderer] (l.Server-4) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-07 10:28:34,995 INFO  [              loci.formats.FormatHandler] (l.Server-4) Initializing helper readers
2013-02-07 10:28:34,995 INFO  [              loci.formats.FormatHandler] (l.Server-4) Reading additional metadata
2013-02-07 10:28:35,009 INFO  [              loci.formats.FormatHandler] (l.Server-4) Populating metadata
2013-02-07 10:28:35,009 INFO  [              loci.formats.FormatHandler] (l.Server-4) Reading bitmap header
2013-02-07 10:28:35,009 INFO  [              loci.formats.FormatHandler] (l.Server-4) Populating metadata
2013-02-07 10:28:35,012 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-4) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2013-02-07 10:28:35,012 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-4) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2013-02-07 10:28:35,012 WARN  [              loci.formats.FormatHandler] (l.Server-4) Expected positive value for EmissionWavelength; got 0
2013-02-07 10:28:35,012 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-4) Unknown LaserMedium value 'None' will be stored as "Other"
2013-02-07 10:28:35,050 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-4) taskCount: 8 delta: 128
2013-02-07 10:28:35,071 INFO  [                 org.perf4j.TimingLogger] (l.Server-4) start[1360232914794] time[277] tag[omero.call.success.ome.services.RenderingBean.renderAsPackedInt]
2013-02-07 10:28:35,071 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Rslt:	[-15168488, -14307549, -13646550, ... 1 more]

comment:5 Changed 11 years ago by jmoore

I haven't looked at this in a debugger, but the following might be an issue (from BfPixelBuffer?.java):

    protected BfPixelsWrapper reader() {
        BfPixelsWrapper wrapper = reader.get();
        if (wrapper == null) {
            try {
                // Note: the call to bfReader.setid inside the BfPixelsWrapper
                // ctor should be a no-op since the filePath is the same for
                // both calls.
                if (reader.compareAndSet(null, new BfPixelsWrapper(filePath, bfReader))) {
                    wrapper = reader.get();
                }

comment:6 Changed 11 years ago by jmoore

  • Milestone changed from Unscheduled to OMERO-5
  • Sprint set to FS Demo 2

comment:7 Changed 11 years ago by wmoore

Some more logging info:

After calling re.load(), the next call to re.renderCompressed() only gives this in Blitz log

2013-02-07 12:00:06,035 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Meth:	interface omeis.providers.re.RenderingEngine.renderCompressed
2013-02-07 12:00:06,035 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Args:	[Type: XY, z=0, t=0]
2013-02-07 12:00:06,035 INFO  [             omeis.providers.re.Renderer] (l.Server-8) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-07 12:00:06,051 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-8) taskCount: 8 delta: 128
2013-02-07 12:00:06,132 INFO  [                 org.perf4j.TimingLogger] (l.Server-8) start[1360238406035] time[97] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2013-02-07 12:00:06,132 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Rslt:	[-1, -40, -1, ... 1 more]

Then, if I call re.renderCompressed() again, and on all subsequent calls to re.renderCompressed(), I see all the metadata statements in the log.

Code and logs below:

pd = omero.romio.PlaneDef(omero.romio.XY)
pd.t = 0
pd.z = 0

re = sf.createRenderingEngine()
re.lookupPixels(pixelsId)
if not re.lookupRenderingDef(pixelsId):
    re.resetDefaults()
    re.lookupRenderingDef(pixelsId)
re.load()

logs for this end with...
2013-02-07 12:00:00,804 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Meth:	interface omeis.providers.re.RenderingEngine.load
2013-02-07 12:00:00,804 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:	()
2013-02-07 12:00:00,804 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Executor.doWork -- ome.services.RenderingBean.getAllEnumerations
2013-02-07 12:00:00,804 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:	[null, InternalSF@156823327]
2013-02-07 12:00:00,805 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:	user=0,group=0,event=null(User),sess=6806d161-fdaf-4193-bf33-3c67077c6cf3
2013-02-07 12:00:00,806 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1360238400804] time[2] tag[omero.call.success.ome.services.RenderingBean$7.doWork]
2013-02-07 12:00:00,806 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:	(ome.model.enums.Family:Id_1, ome.model.enums.Family:Id_2, ome.model.enums.Family:Id_3, ... 1 more)
2013-02-07 12:00:00,806 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Executor.doWork -- ome.services.RenderingBean.getAllEnumerations
2013-02-07 12:00:00,806 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:	[null, InternalSF@156823327]
2013-02-07 12:00:00,807 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:	user=0,group=0,event=null(User),sess=6806d161-fdaf-4193-bf33-3c67077c6cf3
2013-02-07 12:00:00,808 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1360238400806] time[2] tag[omero.call.success.ome.services.RenderingBean$7.doWork]
2013-02-07 12:00:00,808 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:	(ome.model.enums.RenderingModel:Id_1, ome.model.enums.RenderingModel:Id_2)
2013-02-07 12:00:00,808 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Executor.doWork -- ome.services.RenderingBean.getPixelBuffer
2013-02-07 12:00:00,808 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:	[null, InternalSF@156823327]
2013-02-07 12:00:00,815 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:	user=0,group=0,event=1280(User),sess=6806d161-fdaf-4193-bf33-3c67077c6cf3
2013-02-07 12:00:00,815 INFO  [             ome.io.nio.FilePathResolver] (l.Server-5) Metadata only file, resulting path: /OMERO/ManagedRepository/system/root/2013-2-6/Users/will/Documents/biology-data/Test-Import-Images/FV1000.oib/aryeh/1h.oib
2013-02-07 12:00:01,019 INFO  [              loci.formats.FormatHandler] (l.Server-5) Initializing helper readers
2013-02-07 12:00:01,019 INFO  [              loci.formats.FormatHandler] (l.Server-5) Reading additional metadata
2013-02-07 12:00:01,028 INFO  [              loci.formats.FormatHandler] (l.Server-5) Populating metadata
2013-02-07 12:00:01,029 INFO  [              loci.formats.FormatHandler] (l.Server-5) Reading bitmap header
2013-02-07 12:00:01,029 INFO  [              loci.formats.FormatHandler] (l.Server-5) Populating metadata
2013-02-07 12:00:01,031 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-5) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2013-02-07 12:00:01,031 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-5) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2013-02-07 12:00:01,031 WARN  [              loci.formats.FormatHandler] (l.Server-5) Expected positive value for EmissionWavelength; got 0
2013-02-07 12:00:01,031 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-5) Unknown LaserMedium value 'None' will be stored as "Other"
2013-02-07 12:00:01,032 INFO  [                ome.io.nio.PixelsService] (l.Server-5) Creating BfPixelBuffer: /OMERO/ManagedRepository/system/root/2013-2-6/Users/will/Documents/biology-data/Test-Import-Images/FV1000.oib/aryeh/1h.oib Series: 0
2013-02-07 12:00:01,033 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1360238400808] time[225] tag[omero.call.success.ome.services.RenderingBean$12.doWork]
2013-02-07 12:00:01,033 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:	ome.io.bioformats.BfPixelBuffer@716069b9
2013-02-07 12:00:01,034 INFO  [             omeis.providers.re.Renderer] (l.Server-5) Enabling alphaless rendering.
2013-02-07 12:00:01,034 INFO  [             omeis.providers.re.Renderer] (l.Server-5) Disabling PriColor rendering, duplicate channel color.
2013-02-07 12:00:01,034 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1360238400804] time[230] tag[omero.call.success.ome.services.RenderingBean.load]
2013-02-07 12:00:01,034 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:	null


data = re.renderCompressed(pd)

2013-02-07 12:00:06,035 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Meth:	interface omeis.providers.re.RenderingEngine.renderCompressed
2013-02-07 12:00:06,035 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Args:	[Type: XY, z=0, t=0]
2013-02-07 12:00:06,035 INFO  [             omeis.providers.re.Renderer] (l.Server-8) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-07 12:00:06,051 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-8) taskCount: 8 delta: 128
2013-02-07 12:00:06,132 INFO  [                 org.perf4j.TimingLogger] (l.Server-8) start[1360238406035] time[97] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2013-02-07 12:00:06,132 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Rslt:	[-1, -40, -1, ... 1 more]


data = re.renderCompressed(pd)

2013-02-07 12:00:11,134 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Meth:	interface omeis.providers.re.RenderingEngine.renderCompressed
2013-02-07 12:00:11,134 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Args:	[Type: XY, z=0, t=0]
2013-02-07 12:00:11,134 INFO  [             omeis.providers.re.Renderer] (l.Server-1) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2013-02-07 12:00:11,332 INFO  [              loci.formats.FormatHandler] (l.Server-1) Initializing helper readers
2013-02-07 12:00:11,332 INFO  [              loci.formats.FormatHandler] (l.Server-1) Reading additional metadata
2013-02-07 12:00:11,344 INFO  [              loci.formats.FormatHandler] (l.Server-1) Populating metadata
2013-02-07 12:00:11,344 INFO  [              loci.formats.FormatHandler] (l.Server-1) Reading bitmap header
2013-02-07 12:00:11,344 INFO  [              loci.formats.FormatHandler] (l.Server-1) Populating metadata
2013-02-07 12:00:11,347 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-1) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2013-02-07 12:00:11,347 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-1) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2013-02-07 12:00:11,347 WARN  [              loci.formats.FormatHandler] (l.Server-1) Expected positive value for EmissionWavelength; got 0
2013-02-07 12:00:11,347 WARN  [el.enums.handlers.LaserMediumEnumHandler] (l.Server-1) Unknown LaserMedium value 'None' will be stored as "Other"
2013-02-07 12:00:11,363 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-1) taskCount: 8 delta: 128
2013-02-07 12:00:11,456 INFO  [                 org.perf4j.TimingLogger] (l.Server-1) start[1360238411134] time[322] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2013-02-07 12:00:11,456 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Rslt:	[-1, -40, -1, ... 1 more]

etc...

comment:8 Changed 11 years ago by jmoore

​https://github.com/chris-allan/openmicroscopy/commit/42db6f706550e09070897bd3e26d2a27e32ccf0a

-- branch from Chris (big-fish-specific) which goes towards fixing this. Might should also limit number of rendering engines server-side when/if we integrate this.

comment:9 Changed 11 years ago by jmoore

  • Sprint FS Demo 2 deleted

Not included in fs demo 2 tag. Removing from sprint

comment:10 Changed 11 years ago by jmoore

  • Sprint set to FS Demo 3

comment:11 Changed 11 years ago by jamoore

  • Sprint changed from FS Demo 3 to FS Demo 4

comment:12 Changed 10 years ago by jamoore

  • Milestone changed from 5.x to 5.0.3
  • Sprint FS demo 4.x deleted
  • Summary changed from RE.renderCompressed() calling BF.setId() to Bug: RE.renderCompressed() calling BF.setId()
  • Version set to 5.0.1

This should be briefly checked to see if it still occurs.

comment:13 Changed 10 years ago by jamoore

  • Cc cxallan added
  • Status changed from new to accepted

What I see as of 5.0.2 is:

2014-06-03 09:11:54,613 INFO  [             omeis.providers.re.Renderer] (.Server-26) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2014-06-03 09:11:54,645 DEBUG [                   loci.formats.Memoizer] (.Server-26) start[1401779514613] time[31] tag[loci.formats.Memoizer.loadMemo]
2014-06-03 09:11:54,650 INFO  [                loci.formats.ImageReader] (.Server-26) FV1000Reader initializing /home/data/ome2/ManagedRepository/root_0/2014-06/03/09-08-26.246/1h.oib
2014-06-03 09:11:54,682 INFO  [              loci.formats.FormatHandler] (.Server-26) Initializing helper readers
2014-06-03 09:11:54,683 INFO  [              loci.formats.FormatHandler] (.Server-26) Reading additional metadata
2014-06-03 09:11:54,688 INFO  [              loci.formats.FormatHandler] (.Server-26) Populating metadata
2014-06-03 09:11:54,689 INFO  [              loci.formats.FormatHandler] (.Server-26) Reading bitmap header
2014-06-03 09:11:54,689 INFO  [              loci.formats.FormatHandler] (.Server-26) Populating metadata
2014-06-03 09:11:54,690 WARN  [ o.x.m.e.handlers.LaserMediumEnumHandler] (.Server-26) Unknown LaserMedium value 'Rhodamine Green' will be stored as "Other"
2014-06-03 09:11:54,691 WARN  [ o.x.m.e.handlers.LaserMediumEnumHandler] (.Server-26) Unknown LaserMedium value 'TRITC' will be stored as "Other"
2014-06-03 09:11:54,691 WARN  [ o.x.m.e.handlers.LaserMediumEnumHandler] (.Server-26) Unknown LaserMedium value 'None' will be stored as "Other"
2014-06-03 09:11:54,691 DEBUG [                   loci.formats.Memoizer] (.Server-26) skipping save memo. elapsed millis: 46
2014-06-03 09:11:54,691 DEBUG [                   loci.formats.Memoizer] (.Server-26) start[1401779514613] time[77] tag[loci.formats.Memoizer.setId]
2014-06-03 09:11:54,698 INFO  [          omeis.providers.re.HSBStrategy] (.Server-26) taskCount: 8 delta: 128
2014-06-03 09:11:54,732 INFO  [                 org.perf4j.TimingLogger] (.Server-26) start[1401779514613] time[118] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2014-06-03 09:11:54,732 INFO  [        ome.services.util.ServiceHandler] (.Server-26)  Rslt:    [-1, -40, -1, ... 1 more]

with the script saying:

Rendered 48 planes in 6.44206190109 secs. 0.134209622939 secs/plane

If I lower omero.pixeldata.memoizer_wait to 10, I see:

2014-06-03 09:16:24,162 INFO  [             omeis.providers.re.Renderer] (l.Server-2) Using: 'omeis.providers.re.HSBStrategy' rendering strategy.
2014-06-03 09:16:24,192 DEBUG [                   loci.formats.Memoizer] (l.Server-2) loaded memo file: /home/data/ome2/BioFormatsCache/home/data/ome2/ManagedRepository/root_0/2014-06/03/09-08-26.246/.1h.oib.bfmemo (2902592 bytes)
2014-06-03 09:16:24,192 DEBUG [                   loci.formats.Memoizer] (l.Server-2) start[1401779784162] time[29] tag[loci.formats.Memoizer.loadMemo]
2014-06-03 09:16:24,192 DEBUG [                   loci.formats.Memoizer] (l.Server-2) start[1401779784162] time[29] tag[loci.formats.Memoizer.setId]
2014-06-03 09:16:24,199 INFO  [          omeis.providers.re.HSBStrategy] (l.Server-2) taskCount: 8 delta: 128
2014-06-03 09:16:24,231 INFO  [                 org.perf4j.TimingLogger] (l.Server-2) start[1401779784161] time[69] tag[omero.call.success.ome.services.RenderingBean.renderCompressed]
2014-06-03 09:16:24,231 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Rslt:    [-1, -40, -1, ... 1 more]

and

Rendered 48 planes in 4.47333788872 secs. 0.0931945393483 secs/plane

So, perhaps a win of ~40 ms per plane. If that's an argument for lowering memoizer_wait, I'm happy to open a PR. Otherwise, we should probably close.

comment:14 Changed 10 years ago by jamoore

Btw, just as a general sampling of data, here are the loadMemo and saveMemo times from the 5.0.2 version tested on gretzky:

omero@gretzky:~$ grep loadMemo OMERO.server-5.0.2-ice33-b26/var/log/Blitz-0.log | perl -pe 's/^.*time\[(\d+)\].*$/$1/' | sort -n | uniq -c
      4 0
      1 9
      1 12
      1 13
      1 17
      4 18
      3 19
      1 20
      2 21
      1 23
     12 24
     21 25
      9 26
      7 27
      6 28
      2 29
      6 30
     12 31
      6 32
      2 33
      6 34
     10 35
      8 36
      7 37
      6 38
      7 39
      4 40
      4 41
      4 42
      1 43
      5 44
     21 45
      8 46
      3 47
      3 48
      7 49
      3 50
      2 51
      1 52
      1 53
      1 62
      1 63
      1 65
      1 66
      2 67
      2 77
      2 103
      1 116
      1 123
      1 201

and

omero@gretzky:~$ grep saveMemo OMERO.server-5.0.2-ice33-b26/var/log/Blitz-0.log | perl -pe 's/^.*time\[(\d+)\].*$/$1/' | sort -n | uniq -c                                                                                              
      1 4
      4 15
      5 16
      1 18
      2 21
      1 23
      1 24
      3 28
      2 32
      1 37
      1 38
      1 44
      1 48
      1 49
      1 53
      1 240
      1 278
      1 306
      1 364
      1 421

comment:15 Changed 10 years ago by wmoore

Don't know much about what memoizer is, or what the potential downsides of lowering memoizer_wait , but if you can save one third of the rendering time, that's gotta be worth something? And you may save even more on images with more metadata?

comment:16 Changed 10 years ago by jamoore

In talking to Chris, the best way forward may be to set the timeout to 0 while coding 5.0.3 and see how things work. Melissa, can you think of a reason not to?

comment:17 Changed 10 years ago by mlinkert

No, that seems fine.

comment:18 Changed 10 years ago by jamoore

  • Resolution set to fixed
  • Status changed from accepted to closed

PR opened: ​https://github.com/openmicroscopy/openmicroscopy/pull/2593

comment:19 Changed 10 years ago by jmoore <josh@…>

  • Remaining Time set to 0

(In [b067b054c409c76de2a60e3d04ae551003109c53/ome.git] on branch develop) Reduce memoizer wait to 0 (Fix #10337)

For relatively fast setId alls, no bfmemo file
was being produced. Lowering this value to zero
shaved off 1/3 of the setId time, though, even
for fast files.

This should also prevent discrepancies when the
system is underload: now a memo file will always
be produced.

comment:20 Changed 10 years ago by Josh Moore <josh@…>

(In [9f5981f110b9d5b9470fa686d9bdc0d57f4114c3/ome.git] on branch develop) Merge pull request #2602 from joshmoore/rebased/develop/10337-no-memo-wait

Reduce memoizer wait to 0 (Fix #10337) (rebased onto develop)

Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.68942 sec.)

© 2000-2014 University of Dundee & Open Microscopy Environment. Creative Commons Attribution 3.0 Unported License
OME source code is available under the GNU General public license or through commercial license from Glencoe Software

We're Hiring!