Surprising slowdown when drawing multiple drawings

[Tristan Croll]

I have a Distance_Restraint_Mgr class, where the relevant code for drawing the restraints looks like this:

class Distance_Restraint_Mgr(Model):
    def __init__(self, model, c_pointer=None):
        '''
        Prepare a distance restraint manager for a given atomic model.
        '''

        session = model.session
        if not hasattr(session, 'isolde_changes') or session.isolde_changes.deleted:
            ct = self._change_tracker = Restraint_Change_Tracker(session)
        else:
            ct = self._change_tracker = session.isolde_changes

        if c_pointer is None:
            f = c_function('distance_restraint_mgr_new',
                args=(ctypes.c_void_p, ctypes.c_void_p,),
                ret=ctypes.c_void_p)
            c_pointer =(f(model._c_pointer, ct._c_pointer))
        super().__init__('Distance Restraints', model, c_pointer)
        self._prepare_drawing()
        self.model = model
        model.add([self])
        self._model_update_handler = self.model.triggers.add_handler('changes', self._model_changes_cb)

   #SNIP#

    def _model_changes_cb(self, trigger_name, changes):
        update_needed = False
        changes = changes[1]
        if changes.num_deleted_atoms():
            update_needed = True
        atom_reasons = changes.atom_reasons()
        if 'display changed' in atom_reasons or 'hide changed' in atom_reasons:
            update_needed = True
        if 'coord changed' in atom_reasons:
            update_needed = True
        if update_needed:
            self._update_graphics()

    _show_bd = True
    _show_td = True

    def _update_graphics(self):
        bd = self._bond_drawing
        td = self._target_drawing
        visibles = self.visible_restraints
        n = len(visibles)
        if n==0:
            bd.display = False
            td.display = False
            return
        bd.display = self._show_bd
        td.display = self._show_td
        self._update_bond_drawing(bd, visibles, n)
        self._update_target_drawing(td, visibles, n)

    def _update_bond_drawing(self, bd, visibles, n):
        bd.positions = visibles._bond_cylinder_transforms

    def _update_target_drawing(self, td, visibles, n):
        td.positions = visibles._target_transforms

The two drawings are simple coaxial cylinders (one uncapped, with 20 triangles, the other capped, with 40 triangles). In my test case I have 50 restraints drawn. Under these circumstances, the _update_graphics() method takes about 160 microseconds.

If I have a live simulation of IGF-I running in stick representation (with ~32 coordinate updates per second on my Linux machine), the graphics runs at a steady 55-60 fps with just the molecule shown. Adding the Distance_Restraint_Mgr crashes it to 30 fps - meaning that about 15ms per frame is disappearing somewhere. Setting either one of _show_bd or _show_td to False brings the frame rate back to a somewhat variable 50-60fps, while setting both to false (so the transforms are calculated but the drawings aren't actually drawn) gives a framerate indistinguishable from that with only the molecule.

With just the molecule present and simulating, session.view.report_framerate() gives a value around 400. With both Distance_Restraint_Mgr drawings visible it drops to 275 - only about 1ms difference, so that's not the cause.

To thicken the plot I have my Position_Restraint_Mgr, which also has two drawings: a "pin" and a dashed pseudobond. The pin has 88 triangles and the bond 72, so with 533 restraints present they account for ~40,000 triangles. They're updated using the following methods:

    def _update_pin_drawing(self, pd, visibles, n):
        from chimerax.core.geometry import Places
        xyzr = numpy.ones((n,4), numpy.double)
        xyzr[:, :3] = visibles.targets
        pd.positions = Places(shift_and_scale=xyzr)

    def _update_bond_drawing(self, bd, visibles, n):
        from chimerax.core.geometry import Places
        bd.positions = Places(opengl_array = visibles._bond_cylinder_transforms)

... which combined time to ~200 microseconds in this case. Both are currently run on every coordinate update (although that's not actually necessary for the pin drawings, but I haven't gotten around to teasing out the specific cases where they need redrawing). With both shown, the framerate is down to 14 fps. With the pin drawing hidden, it's 14fps. With the bond drawing hidden and the pin drawing shown, it's 55-60 fps.

Visually, everything *looks* right, so I'm struggling to understand where this ~100-fold performance hit is coming from.

[Tom Goddard]

As a starting point the "graphics framerate true" command will output to the status line once per second the percentage of time spent in various aspects of drawing (draw, new_frame, atom_check_for_changes, drawing_change, clip). This may give some idea of what causes the slowdown.

It happens that I planned on looking into exactly this question of rendering speed dependence on the number of displayed models, because VR has problems with slow rendering with many models. I have not started yet, but my initial suspicion is that it has nothing to do with the geometry being rendered, how many triangles. The graphics card can easily keep the speed up. Instead the problem is likely in all the Python calls needed to draw one frame. Another possible issues is PyOpenGL doing error checks after every call. And another issue is that there are simply too many OpenGL calls showing small geometry and optimization is needed to batch things -- that can be very complex. When the code has to change the OpenGL shader to render different types of models (e.g. instanced vs non-instanced (ribbons)), having lots of shader switches could slow things down. On each shader switch a bunch of OpenGL calls from Python are needed to set the shader variables.

[tic20@…]

The following is my stab at a minimal test case that reproduces the 
problem. Assuming you have a single atomic structure loaded (my go-to 
toy is IGF-I (chain A of the first frame of 1pmx, 70 residues)):

{{{
from chimerax.core.models import Drawing, Model
from chimerax.core.surface.shapes import dashed_cylinder_geometry
from chimerax.core.geometry import Places
import numpy

d = Drawing('Test')
d.vertices, d.normals, d.triangles = dashed_cylinder_geometry(5)

m = Model('test', session)
m.add_drawing(d)

structure = session.models.list()[0]
structure.add([m])

class Model_Move:
     def __init__(self, session, structure, drawing, n_instances):
         self.session = session
         self.structure = structure
         self.drawing = drawing
         self.set_n_instances(n_instances)
         self.new_frame_handler = None
         self.model_change_handler = 
structure.triggers.add_handler('changes', self.model_change_cb)

     def set_n_instances(self, n):
         self.opengl_array = numpy.array([numpy.identity(4, 
numpy.double)]*n)

     def new_frame_cb(self, *_):
         s = self.structure
         s.atoms.coords += 0.001

     def model_change_cb(self, *_):
         d = self.drawing
         d.positions = Places(opengl_array = self.opengl_array)

     def start_moving(self):
         self.new_frame_handler = self.session.triggers.add_handler('new 
frame', self.new_frame_cb)

     def stop_moving(self):
         if self.new_frame_handler is not None:
             self.session.triggers.remove_handler(self.new_frame_handler)
         self.new_frame_handler = None
}}}

On my MacBook, I get:

n_instances     framerate
5               50 fps
50              32 fps
500             17 fps
5000            3.1 fps

... which would suggest to me that somewhere a rather expensive Python 
loop is running over every transform.

On 2018-02-20 20:07, ChimeraX wrote:

[goddard@…]

Every frame you are moving the structure atoms causing your model_change_cb() which sets drawing.positions to a new Places object.  Of course ChimeraX does not know that your positions array did not change.  So it will have to recompute the bounds of the entire scene.  I’m guessing copies_bounding_box() in core/geometry/bounds.py is being called, hitting the lines

        # TODO: Optimize instance matrix copies such as bond cylinders using C++.
        b = union_bounds(point_bounds(p * bounds.box_corners()) for p in positions)

which indeed iterates over every position in Python, probably quite slow.

[tic20@…]

Ok. I’d be happy to look into that tomorrow, if you like. Given that I have a bunch of pseudobond-like cases that’ll be hitting this, seems like it’ll be worth my while.

 
 
Tristan Croll
Research Fellow
Cambridge Institute for Medical Research
University of Cambridge CB2 0XY
 

 

[goddard@…]

I did a simple numpy optimization to copies_bounding_box() making it 80x faster using numpy instead of a Python loop.  This could be made probably 50x faster still using C++ and is probably worth the trouble if you have thousands of copies.

I do not know if this is related to your performance issue.  I’ll let you investigate that.

[Tom Goddard]

I optimized copies_bounding_box() using C++ and also point_bounds() since these are important for speed. The first routine is about 1000x faster than the previous Python version. Still this may not help the problem reported in this ticket.

[tic20@…]

Yep -that was it. Your changes haven't made it into the daily build yet, 
but I went through and rationalised which drawings actually have to be 
part of the bounds calculation, adding the 'skip_bounds' property to 
those that don't. Turns out it's really only my position restraint 
"pins" that need to calculate bounds - everything else will always be 
inside the bounds of other drawings. With everything but the pin drawing 
visible (533 position restraints, 50 distance restraints, 69 dihedral 
restraints, live rotamer and rama visualisation) - so 7 of my drawings 
plus the two AtomicStructure drawings, all updating on every coordinate 
update - I'm getting 31 coordinate updates a second and an average of 
45-50 graphics frames a second (with admittedly the occasional dip into 
the 30fps range). Throttling the simulation to 20 updates a second gives 
me a consistent >50 fps graphics.

Under the latter conditions, 'graphics framerate true' reports (typical 
values):

draw 43%, new_frame 1%, atomic_check_for_changes 6%, drawing_change 2%, 
clip 0%

On 2018-02-21 01:03, ChimeraX wrote:

[tic20@…]

Still a slight oddity here. I re-worked my position restraint code to 
ensure that the pin drawing positions are only updated when the 
restraint target changes, and added a print check to ensure that this 
drawing isn't being touched on normal atom coordinate updates. Yet 
having it visible still slows things by ~15ms per frame, suggesting it's 
still doing a bounds calculation on every update anyway.

Here's the hierarchy of models/drawings at present (stars indicate 
drawings with no bounds check):

AtomicStructure -- _atoms_drawing
  |              \- _bonds_drawing*
  |
  -- Proper_Dihedral_Restraint_Mgr -- _ring_drawing*
  |                                \- _post_drawing*
  |
  -- Position_Restraint_Mgr -- _pin_drawing
  |                         \- _bond_drawing*
  |
  -- Distance_Restraint_Mgr -- _bond_drawing*
  |                         \- _target_drawing*
  |
  -- Rotamer_Annotator -- _annotation_drawing*
  |
  |
  -- Rama_Annotator -- _ca_drawing*
                    \- _omega_drawing*

Everything *but* the Position_Restraint_Mgr pin drawing is updating with 
every coordinate update, but it's the pin drawing that's slowing things 
down. Obviously your new bounds code will effectively make the problem 
go away, but it's not clear to me why it should be there in the first 
place.

On 2018-02-21 09:30, ChimeraX wrote:

[goddard@…]

Is a pseudobond drawn between your pins and atoms?  If the atoms move the pseudobond has to be redrawn.  But if the pins are not shown then the pseudobonds are not drawn.  So my guess is the pin drawing slow-down is because of the pseudobonds.  I’m not sure what is slow about the pseudobond repositioning though.

[tic20@…]

There is (well... not a ChimeraX pseudobond, but my own implementation that does away with using fake atoms as pins. But that’s not the cause. I’m testing by using a flag that *just* hides the drawing, without affecting any other calculation. Will poke at it a bit more tomorrow, and see how reproducible it is.

To be frank, though, the speeds I’m getting even with that minor issue are more than adequate for mouse-and-keyboard interaction, and my test involves about ten times as many position restraints as I’d expect to see in reality. So not a big deal.

 
 
Tristan Croll
Research Fellow
Cambridge Institute for Medical Research
University of Cambridge CB2 0XY
 

 

[goddard@…]

Ok, don’t spend too much time debugging problems that are not problems.  But if you have some ideas that are easy to test it could allow us to optimize something that avoids future debugging when the same problem arises in a more severe form.

[Tom Goddard]

Seems performance was made adequate with some bounding box optimization.