Opened 5 years ago

Closed 5 years ago

Last modified 5 years ago

#3285 closed defect (fixed)

Slow graphics updates

Reported by: Tristan Croll Owned by: pett
Priority: normal Milestone:
Component: Performance Version:
Keywords: Cc: Tristan Croll, Tom Goddard
Blocked By: Blocking:
Notify when closed: Platform: all
Project: ChimeraX

Description 

The following bug report has been submitted:
Platform:        Linux-3.10.0-1062.9.1.el7.x86_64-x86_64-with-centos-7.7.1908-Core
ChimeraX Version: 1.0 (2020-05-09)
Description
I've run into a curious problem with the current model I'm working on (a new one, whose biggest defining feature is that it has *lots* of chains - 85, although most of them are fairly short. The model has 4713 residues in total). I suspect it's something that's gone awry with this particular session, since if I open the same model/map in a fresh ChimeraX instance it doesn't seem to happen. I *have* seen it before, though (again, on a really big model). In short, adding a new residue or deleting one triggers an *enormous* delay on the next redraw:

isolde add ligand MYR

... freezes ChimeraX for well over a minute. If I then delete the residue I just added:

delete sel

... and then select a random atom and go to start a simulation, that also takes forever. In the shell:

from chimerax.core.commands import run
%prun run(session, 'isolde sim start sel')

         721612 function calls (716898 primitive calls) in 67.161 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  508/406   61.573    0.121   61.683    0.152 molc.py:189(get_prop)
        1    4.050    4.050    4.050    4.050 {built-in method _openmm.new_Context}
        1    0.099    0.099    0.108    0.108 forcefield.py:1925(createForce)
     1559    0.088    0.000    0.163    0.000 molarray.py:101(__init__)
        1    0.082    0.082    0.195    0.195 forcefield.py:2030(createForce)
        6    0.074    0.012    0.094    0.016 molobject.py:1606(polymers)
        1    0.072    0.072    0.579    0.579 forcefield.py:1026(createSystem)
      543    0.060    0.000    0.060    0.000 forcefield.py:1717(_matchImproper)
       24    0.056    0.002    0.057    0.002 molc.py:202(set_prop)
        1    0.053    0.053    0.108    0.108 openmm_interface.py:2670(create_openmm_topology)
      406    0.052    0.000    0.052    0.000 {simtk.openmm.app.internal.compiled.matchResidueToTemplate}
      131    0.045    0.000    0.046    0.000 molarray.py:656(num_selected)
      135    0.026    0.000    0.026    0.000 molarray.py:300(_cpp_table_pointer)

 ... but when I stop that simulation and carry on, everything is back to normal. When it's in that slow state, even something as simple as `selected_residues(session)` becomes really slow (and, bizarrely, proportional to the number of residues selected). With a single residue selected:

%prun selected_residues(session)

         539 function calls (533 primitive calls) in 0.012 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3    0.006    0.002    0.006    0.002 molarray.py:656(num_selected)
        3    0.003    0.001    0.003    0.001 molarray.py:903(num_selected)
        6    0.001    0.000    0.002    0.000 molc.py:160(get_prop)
        3    0.000    0.000    0.001    0.000 molc.py:189(get_prop)
 
with all residues selected:

%prun selected_residues(session)

         2920449 function calls (2920443 primitive calls) in 20.521 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   547446   14.452    0.000   14.452    0.000 {built-in method builtins.dir}
   547446    2.613    0.000   17.064    0.000 attr_registration.py:60(get_attr)
        1    1.255    1.255   20.498   20.498 structure.py:2156(selected_bonds)
  1094915    1.109    0.000    1.109    0.000 {built-in method builtins.hasattr}
   547446    0.964    0.000   19.137    0.000 attr_registration.py:35(_getattr_)
        2    0.056    0.028    0.096    0.048 molarray.py:150(<listcomp>)
   182482    0.040    0.000    0.040    0.000 {chimerax.atomic.cymol.c_ptr_to_py_inst}

Any clues?

Log:
> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

19 atoms, 18 bonds, 1 model selected  

> select up

33 atoms, 32 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> save working.cif #1

Not saving entity_poly_seq for non-authoritative sequences  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

10 atoms, 9 bonds, 1 model selected  

> select up

158 atoms, 159 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

19 atoms, 18 bonds, 1 model selected  

> select up

33 atoms, 32 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> clipper set contourSensitivity 0.25

> clipper set contourSensitivity 0.25

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

14 atoms, 13 bonds, 1 model selected  

> select up

33 atoms, 32 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> select up

10 atoms, 9 bonds, 1 model selected  

> select up

158 atoms, 159 bonds, 1 model selected  

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

19 atoms, 18 bonds, 1 model selected  

> select up

33 atoms, 32 bonds, 1 model selected  

> select up

48 atoms, 46 bonds, 1 model selected  

> select up

536 atoms, 545 bonds, 1 model selected  

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> select up

19 atoms, 18 bonds, 1 model selected  

> select up

33 atoms, 32 bonds, 1 model selected  

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto sel

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

24 atoms, 23 bonds, 1 model selected  

> select up

103 atoms, 105 bonds, 1 model selected  

> color sel bychain

> color sel byhetero

> delete sel

> color sel bychain

> color sel byhetero

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> save working.cif #1

Not saving entity_poly_seq for non-authoritative sequences  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> select clear

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> save working.cif #1

Not saving entity_poly_seq for non-authoritative sequences  

> show #!2 models

> isolde restrain distances #1/C templateAtoms #2/C

RMSD between 270 pruned atom pairs is 1.421 angstroms; (across all 280 pairs:
2.748)  
RMSD between 5 pruned atom pairs is 3.735 angstroms; (across all 10 pairs:
26.905)  
No further alignments of 3 or more residues found.  

> isolde release distances #1

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

14 atoms, 13 bonds, 1 model selected  

> select up

121 atoms, 121 bonds, 1 model selected  

> select up

128 atoms, 127 bonds, 1 model selected  

> select up

188 atoms, 189 bonds, 1 model selected  

> select clear

> select clear

> show #!2 models

> hide #!2 models

> show #!2 models

> select up

7 atoms, 6 bonds, 1 model selected  

> select up

434 atoms, 443 bonds, 1 model selected  

> hide #!2 models

> show #!2 models

> color #2 tan

> color #2 byhetero

> select clear

> hide #!2 models

> isolde stepto sel

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

14 atoms, 13 bonds, 1 model selected  

> select up

261 atoms, 264 bonds, 1 model selected  

> isolde stepto

> isolde stepto sel

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

22 atoms, 21 bonds, 1 model selected  

> select up

169 atoms, 170 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> sequence chain #1/C

Alignment identifier is 1.2.C  

> hide #!2 models

> isolde stepto sel

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> save working.cif #1

Not saving entity_poly_seq for non-authoritative sequences  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> select #2/L:26-29

32 atoms, 34 bonds, 1 model selected  

> ~cartoon sel

> select clear

> hide #!2 models

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!3 models

> hide #!3 models

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

401 atoms, 406 bonds, 1 model selected  

> select up

4716 atoms, 4825 bonds, 1 model selected  

> select down

401 atoms, 406 bonds, 1 model selected  

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> save working.cxs

Traceback (most recent call last):  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 280, in process  
data = sm.take_snapshot(obj, session, self.state_flags)  
File "/home/tic20/.local/share/ChimeraX/1.0/site-
packages/chimerax/clipper/symmetry.py", line 1120, in take_snapshot  
from chimerax.core.state import CORE_STATE_VERSION  
ImportError: cannot import name 'CORE_STATE_VERSION' from
'chimerax.core.state' (/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/state.py)  
  
The above exception was the direct cause of the following exception:  
  
Traceback (most recent call last):  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 817, in save  
session.save(output, version=version, include_maps=include_maps)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 568, in save  
mgr.discovery(self._state_containers)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 259, in discovery  
self.processed[key] = self.process(obj, parents)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 283, in process  
raise RuntimeError(msg) from e  
RuntimeError: Error while saving session data for 'custom_attr_preserver' ->
<chimerax.atomic.attr_registration.CustomizedInstanceManager object at
0x7f2eb010e550> -> <chimerax.atomic.molobject.Residue object at
0x7f2df802dfa0> 'GPC' -> <chimerax.atomic.structure.AtomicStructure object at
0x7f2e4c178a10> 'gprc-dlh1-car.cif' ->
<chimerax.clipper.symmetry.SymmetryManager object at 0x7f2eb202a190> 'Data
manager (gprc-dlh1-car.cif)'  
  
RuntimeError: Error while saving session data for 'custom_attr_preserver' ->
-> 'GPC' -> 'gprc-dlh1-car.cif' -> 'Data manager (gprc-dlh1-car.cif)'  
  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 283, in process  
raise RuntimeError(msg) from e  
  
See log for complete Python traceback.  
  
Traceback (most recent call last):  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 280, in process  
data = sm.take_snapshot(obj, session, self.state_flags)  
File "/home/tic20/.local/share/ChimeraX/1.0/site-
packages/chimerax/clipper/symmetry.py", line 1120, in take_snapshot  
from chimerax.core.state import CORE_STATE_VERSION  
ImportError: cannot import name 'CORE_STATE_VERSION' from
'chimerax.core.state' (/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/state.py)  
  
The above exception was the direct cause of the following exception:  
  
Traceback (most recent call last):  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/cmd_line/tool.py", line 258, in execute  
cmd.run(cmd_text)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/commands/cli.py", line 2849, in run  
result = ci.function(session, **kw_args)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/save_command/cmd.py", line 66, in cmd_save  
Command(session, registry=registry).run(provider_cmd_text, log=log)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/commands/cli.py", line 2849, in run  
result = ci.function(session, **kw_args)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/save_command/cmd.py", line 79, in provider_save  
mgr).save(session, path, **provider_kw)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core_formats/__init__.py", line 79, in save  
return cxs_save(session, path, **kw)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 817, in save  
session.save(output, version=version, include_maps=include_maps)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 568, in save  
mgr.discovery(self._state_containers)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 259, in discovery  
self.processed[key] = self.process(obj, parents)  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 283, in process  
raise RuntimeError(msg) from e  
RuntimeError: Error while saving session data for 'custom_attr_preserver' ->
<chimerax.atomic.attr_registration.CustomizedInstanceManager object at
0x7f2eb010e550> -> <chimerax.atomic.molobject.Residue object at
0x7f2df802dfa0> 'GPC' -> <chimerax.atomic.structure.AtomicStructure object at
0x7f2e4c178a10> 'gprc-dlh1-car.cif' ->
<chimerax.clipper.symmetry.SymmetryManager object at 0x7f2eb202a190> 'Data
manager (gprc-dlh1-car.cif)'  
  
RuntimeError: Error while saving session data for 'custom_attr_preserver' ->
-> 'GPC' -> 'gprc-dlh1-car.cif' -> 'Data manager (gprc-dlh1-car.cif)'  
  
File "/opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/session.py", line 283, in process  
raise RuntimeError(msg) from e  
  
See log for complete Python traceback.  
  

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> select up

43 atoms, 42 bonds, 1 model selected  

> isolde ignore ~sel

ISOLDE: currently ignoring 4713 residues in model 1.2  
ISOLDE: currently ignoring 4713 residues in model 3  
ISOLDE: currently ignoring 3824 residues in model 2  
Loading residue template for MYR from internal database  

> isolde ~ignore

Tugging of non-polar hydrogens is not enabled. Applying tug to the nearest
bonded heavy atom.  

> delete sel

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> isolde stepto

> isolde stepto

> isolde stepto

> select up

21 atoms, 21 bonds, 1 model selected  

> select up

71 atoms, 71 bonds, 1 model selected  

> select clear

> isolde add ligand MYR

> color sel bychain

Profile for last activation of changes trigger:  
563 function calls (526 primitive calls) in 0.001 seconds  
  
Ordered by: internal time  
List reduced from 95 to 20 due to restriction <20>  
  
ncalls tottime percall cumtime percall filename:lineno(function)  
9/3 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/graphics/drawing.py:227(__setattr__)  
15 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/atomic/molc.py:319(pointer)  
25 0.000 0.000 0.000 0.000
/opt/UCSF/ChimeraX/lib/python3.7/weakref.py:567(__call__)  
2 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/numpy/lib/arraysetops.py:298(_unique1d)  
1 0.000 0.000 0.001 0.001 /home/tic20/.local/share/ChimeraX/1.0/site-
packages/chimerax/isolde/validation/rota_annotation.py:155(_update_graphics_if_needed)  
15 0.000 0.000 0.000 0.000
/opt/UCSF/ChimeraX/lib/python3.7/ctypes/__init__.py:497(cast)  
9 0.000 0.000 0.000 0.000
/opt/UCSF/ChimeraX/lib/python3.7/weakref.py:530(__init__)  
9 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/atomic/molarray.py:1420(remove_deleted_pointers)  
6 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/atomic/molc.py:189(get_prop)  
1 0.000 0.000 0.000 0.000 /home/tic20/.local/share/ChimeraX/1.0/site-
packages/chimerax/isolde/validation/rama_annotation.py:191(_update_graphics_if_needed)  
9 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/atomic/molarray.py:101(__init__)  
3 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/atomic/changes.py:165(_created_objects)  
2 0.000 0.000 0.000 0.000 {built-in method builtins.sum}  
15 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/numpy/core/_internal.py:251(__init__)  
2 0.000 0.000 0.000 0.000 {method 'argsort' of 'numpy.ndarray' objects}  
11 0.000 0.000 0.000 0.000 {built-in method numpy.empty}  
1 0.000 0.000 0.001 0.001 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/triggerset.py:197(_activate)  
68/46 0.000 0.000 0.000 0.000 {built-in method builtins.len}  
10 0.000 0.000 0.001 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/chimerax/core/triggerset.py:128(invoke)  
15 0.000 0.000 0.000 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-
packages/numpy/core/_internal.py:268(data_as)  
  
  
  

> color sel byhetero

> select up

44 atoms, 43 bonds, 1 model selected  

> delete sel

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select up

11 atoms, 10 bonds, 1 model selected  

> select up

309 atoms, 313 bonds, 1 model selected  

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> show #!2 models

> hide #!2 models

> show #!2 models

> hide #!2 models

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> close #1.2.11

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> isolde stepto

> select clear

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> isolde sim start sel

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> isolde sim start sel

> isolde sim start sel

> select clear

> isolde add ligand MYR

> color sel bychain

> color sel byhetero

> delete sel

> isolde stepto

> select /M

15002 atoms, 15173 bonds, 28 pseudobonds, 6 models selected  

> select #1/M

5833 atoms, 5950 bonds, 8 pseudobonds, 2 models selected  

> select clear

> select #1/M

5833 atoms, 5950 bonds, 8 pseudobonds, 2 models selected  

> select clear

> select clear

> select #1

89287 atoms, 91241 bonds, 354 pseudobonds, 23 models selected  

> select clear

> select clear

> select #1

89287 atoms, 91241 bonds, 354 pseudobonds, 23 models selected  




OpenGL version: 3.3.0 NVIDIA 440.33.01
OpenGL renderer: TITAN Xp/PCIe/SSE2
OpenGL vendor: NVIDIA Corporation
Manufacturer: Dell Inc.
Model: Precision T5600
OS: CentOS Linux 7 Core
Architecture: 64bit ELF
CPU: 32 Intel(R) Xeon(R) CPU E5-2687W 0 @ 3.10GHz
Cache Size: 20480 KB
Memory:
	              total        used        free      shared  buff/cache   available
	Mem:            62G         10G         40G        383M         11G         50G
	Swap:          4.9G          0B        4.9G

Graphics:
	03:00.0 VGA compatible controller [0300]: NVIDIA Corporation GP102 [TITAN Xp] [10de:1b02] (rev a1)	
	Subsystem: NVIDIA Corporation Device [10de:11df]	
	Kernel driver in use: nvidia

Change History (29)

comment:1 by Tristan Croll, 5 years ago

Platform: → all
Project: → ChimeraX

Hmm... seems there are two different things going on here. The call to selected_residues(session) just *is* that slow for large models (loaded in a fresh session, no ISOLDE), due to its call to selected_bonds(session, inter_residue=False). selected_atoms(session).unique_residues is still effectively instantaneous.

comment:2 by Tristan Croll, 5 years ago

Split the selected_residues issue into a separate ticket (#3290).

comment:3 by Tristan Croll, 5 years ago

A little more clarity appearing. I've narrowed down the slow step on starting a simulation immediately after deleting an atom:

            atoms = atoms[atoms.idatm_types != 'HC']

... takes about 10 seconds in my current test case, independent of the number of atoms - I guess the deletion triggers a recalculation over the entire model? The line exists because in ISOLDE non-polar hydrogens are not tuggable by default. The same call is also used in a few places in Clipper's visualisation code, which probably explains the delay on redraw.

So I can see the problem now - I hadn't realised that adding or deleting atoms triggers invalidation of the idatm_types for the *entire* structure, causing them to be recalculated from scratch on the next call. I guess the simple thing for me to do here would be to replace my checks based on idatm_type with a little jiffy function to see if the hydrogen is bonded to a carbon.

comment:4 by Tristan Croll, 5 years ago

Ok, added a simple C++ method to Clipper that returns a binary mask (True if an atom is both hydrogen and bonded to carbon) and have expunged all use of idatm_type in both Clipper and ISOLDE. Gets rid of most of the delays.

comment:5 by Tristan Croll, 5 years ago

... or not. After a few hours working on the model in ISOLDE (not sure if that's actually relevant) I'm seeing big delays on adding residues again. Specifically, if I do:

def add_and_profile():
    session.triggers.profile_trigger('graphics update', sort_by='cumulative')
    run(session, 'isolde add lig MYR')

add_and_profile()

I get:

Profile for last activation of graphics update trigger:
76065 function calls (75058 primitive calls) in 21.418 seconds

Ordered by: cumulative time
List reduced from 358 to 20 due to restriction <20>

ncalls tottime percall cumtime percall filename:lineno(function)
2/1 0.000 0.000 21.418 21.418 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:197(_activate)
6/3 0.000 0.000 21.418 7.139 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:128(invoke)
1 0.000 0.000 21.418 21.418 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:1556(_update_graphics_if_needed)
1 0.000 0.000 21.352 21.352 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:294(_update_graphics_if_needed)
964/879 21.103 0.022 21.126 0.024 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molc.py:189(get_prop)
1 0.000 0.000 21.108 21.108 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:324(_update_graphics)
1 0.000 0.000 21.089 21.089 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:333(_update_atom_graphics)
2 0.000 0.000 21.087 10.544 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:371(_atom_display_radii)
2 0.000 0.000 21.087 10.544 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molarray.py:601(display_radii)
1 0.000 0.000 0.239 0.239 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:545(_create_ribbon_graphics)
1 0.001 0.001 0.239 0.239 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:583(compute_ribbons)
1 0.004 0.004 0.234 0.234 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:31(_make_ribbon_graphics)
1 0.000 0.000 0.063 0.063 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:312(activate_trigger)
1 0.000 0.000 0.063 0.063 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:180(activate)
1 0.000 0.000 0.063 0.063 /home/tic20/.local/share/ChimeraX/1.0/site-packages/chimerax/isolde/isolde.py:1030(_selection_changed)
3 0.030 0.010 0.038 0.013 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molobject.py:1606(polymers)
85 0.000 0.000 0.038 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:430(_ribbon_geometry)
85 0.037 0.000 0.037 0.000 {built-in method chimerax.atomic._ribbons.ribbon_extrusions}
85 0.034 0.000 0.036 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:248(_ribbon_ranges)
2 0.000 0.000 0.031 0.015 /home/tic20/.local/share/ChimeraX/1.0/site-packages/chimerax/isolde/util.py:13(is_continuous_protein_chain)

... which is a bit of a surprise. *Deleting* a single atom is also really slow, but deleting a whole residue is fast. For the single atom case:

 
def delete_atom_and_profile():
    session.triggers.profile_trigger('graphics update', sort_by='cumulative')
    run(session, 'del sel')
    

delete_atom_and_profile()

leads to:

Profile for last activation of graphics update trigger:
2139 function calls (2062 primitive calls) in 21.614 seconds

Ordered by: cumulative time
List reduced from 158 to 20 due to restriction <20>

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 21.614 21.614 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:197(_activate)
3 0.000 0.000 21.614 7.205 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:128(invoke)
1 0.000 0.000 21.614 21.614 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:1556(_update_graphics_if_needed)
1 0.000 0.000 21.611 21.611 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:294(_update_graphics_if_needed)
1 0.000 0.000 21.596 21.596 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:324(_update_graphics)
21 21.583 1.028 21.584 1.028 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molc.py:189(get_prop)
2 0.000 0.000 21.577 10.789 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:371(_atom_display_radii)
2 0.000 0.000 21.577 10.789 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molarray.py:601(display_radii)
1 0.000 0.000 21.574 21.574 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:333(_update_atom_graphics)
1 0.000 0.000 0.014 0.014 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:571(_update_ribbon_tethers)
1 0.000 0.000 0.014 0.014 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:656(update_tethers)
1 0.000 0.000 0.014 0.014 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/ribbon.py:733(update_tethers)
1 0.000 0.000 0.013 0.013 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:374(_update_bond_graphics)
2 0.009 0.004 0.009 0.005 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molarray.py:610(maximum_bond_radii)
2 0.000 0.000 0.005 0.002 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/pbgroup.py:189(_update_graphics)
1 0.000 0.000 0.004 0.004 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:416(_update_chain_trace_graphics)
1 0.004 0.004 0.004 0.004 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molobject.py:1417(chain_trace_atoms)
2 0.000 0.000 0.004 0.002 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/pbgroup.py:227(_update_positions)
4 0.002 0.001 0.003 0.001 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molarray.py:792(pb_coords)
1 0.000 0.000 0.003 0.003 {built-in method builtins.sum}

... which appears identical to the add-residue case.

comment:6 by pett, 5 years ago

Component: Unassigned → Performance
Owner: set to Tom Goddard
Status: new → assigned
Summary: ChimeraX bug report submission → Slow graphics updates

comment:7 by Tristan Croll, 5 years ago

This *seems* to be triggered by edits (addition or removal of atoms) to the model, but I still don't understand exactly what. I've been working on the same model today, and added a couple of dozen residues in a new chain (using the peptide builder for the first 12 or so, then extending one by one with ISOLDE). Actually ran a few simulations without any real hitch afterwards, but it's suddenly fallen into a state where selecting/deselecting a large number of atoms takes a *crazy* amount of time (on the order of 5-10 minutes). I'm trying to capture a profile of the graphics update trigger now, to see what's hanging it up.

comment:8 by Tristan Croll, 5 years ago

Well, the profile on the graphics update trigger after running sel ~H reports 28 seconds going into selected_bonds() - covered by #3290 - but that's a tiny fraction of the total delay. I guess the next most likely culprit is something on the changes trigger?

comment:9 by Tristan Croll, 5 years ago

Here's the profile on graphics update, for what it's worth (ran it a second time to sort by cumulative time, and it only just finished).

select ~H73663 atoms, 121517 bonds, 633 pseudobonds, 25 models selected
Profile for last activation of graphics update trigger:
3899747 function calls (3899700 primitive calls) in 28.531 seconds

Ordered by: cumulative time
List reduced from 209 to 20 due to restriction <20>

ncalls tottime percall cumtime percall filename:lineno(function)
2/1 0.000 0.000 28.531 28.531 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:197(_activate)
7/3 0.000 0.000 28.531 9.510 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:128(invoke)
1 0.000 0.000 28.531 28.531 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:1556(_update_graphics_if_needed)
1 0.000 0.000 28.508 28.508 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:312(activate_trigger)
1 0.000 0.000 28.508 28.508 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py:180(activate)
1 0.000 0.000 28.461 28.461 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/seq-view/region_browser.py:1726(_sel_change_cb)
1 0.001 0.001 28.461 28.461 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/seq-view/region_browser.py:1133(show_chimerax_selection)
1 0.000 0.000 28.454 28.454 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:2177(selected_residues)
1 1.697 1.697 28.432 28.432 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/structure.py:2156(selected_bonds)
729105 1.260 0.000 26.616 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/attr_registration.py:35(_getattr_)
729105 3.524 0.000 23.865 0.000 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/attr_registration.py:60(get_attr)
729105 20.340 0.000 20.340 0.000 {built-in method builtins.dir}
1458299 1.491 0.000 1.491 0.000 {built-in method builtins.hasattr}
13 0.000 0.000 0.116 0.009 /opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/molarray.py:146(__iter__)

comment:10 by Tristan Croll, 5 years ago

... and nothing to note on the changes trigger (316 calls in 0.004 seconds). I get the impression that there's something accumulating - each call seems to take significantly longer than the last (I set off this test immediately after making the last post, and it only just finished - that's almost 20 minutes).

comment:11 by Tristan Croll, 5 years ago

Cc: Tom Goddard added
Owner: changed from Tom Goddard to Tristan Croll

Looks like most of this is my fault. I don't have all the answers yet, but in a fresh ISOLDE session:

def sel_and_update():
    run(session, 'sel ~H')
    session.update_loop.draw_new_frame()
    

%prun -s cumulative sel_and_update()

         188275 function calls (183055 primitive calls) in 3.022 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.024    3.024 {built-in method builtins.exec}
        1    0.000    0.000    3.024    3.024 <string>:1(<module>)
        1    0.000    0.000    3.024    3.024 <ipython-input-8-ee63b8b94cbe>:1(sel_and_update)
        1    0.000    0.000    2.828    2.828 run.py:14(run)
        1    0.000    0.000    2.828    2.828 cli.py:2769(run)
    61/56    0.000    0.000    2.504    0.045 triggerset.py:312(activate_trigger)
    61/56    0.000    0.000    2.504    0.045 triggerset.py:180(activate)
    61/56    0.001    0.000    2.504    0.045 triggerset.py:197(_activate)
  229/209    0.001    0.000    2.502    0.012 triggerset.py:128(invoke)
        1    0.000    0.000    2.486    2.486 select.py:14(select)
       51    0.003    0.000    2.408    0.047 isolde.py:1030(_selection_changed)
       52    0.000    0.000    2.355    0.045 gui.py:337(thread_safe)
       50    0.001    0.000    2.352    0.047 models.py:204(_selection_changed)
      102    0.010    0.000    2.185    0.021 util.py:13(is_continuous_protein_chain)
      102    0.001    0.000    1.987    0.019 util.py:34(find_polymer)
  556/214    0.008    0.000    1.920    0.009 drawing.py:227(__setattr__)

... so changing the selection once causes ISOLDE's _selection_changed callback to run 51 times over (and putting a simple counter callback on the "selection changed" trigger shows it's actually getting fired 51 times). So somewhere ISOLDE's responding to a change in selection by changing the selection (which makes me wonder: why isn't it just getting stuck in an infinite loop??). On each run of the callback, ot Will do some sleuthing.

... And the reason it suddenly got so *crazy* slow in the other session is that I had a sequence viewer window open - and each of those selection changes was triggering its _sel_change_cb, which calls selected_residues(session) at a cost of 20-something seconds per call. So if selected_residues() is sped up and I track down and fix whatever in ISOLDE is causing the repeated selections, this should all go away.

comment:12 by Tristan Croll, 5 years ago

Cc: Tristan Croll added; Tom Goddard removed
Owner: changed from Tristan Croll to Tom Goddard

... ah. It looks like it's not me after all. It looks like each Model subclass that's loaded individually fires the global "selection changed" trigger once when selected. In a brand new session:

class TriggerCounter:
    def __init__(self, session, trigger_name):
        self.counter=0
        self.session=session
        self.handler = session.triggers.add_handler(trigger_name, self._cb)
    def _cb(self, *_):
        self.counter+=1
        

tc = TriggerCounter(session, 'selection changed')

# Open a single volume, then do "select #1" in the command line

tc.counter
Out[3]: 3

Wouldn't it be better to concatenate all of these into a single firing per GUI update?

comment:13 by Tom Goddard, 5 years ago

Cc: Tom Goddard added
Owner: changed from Tom Goddard to pett

Eric added the per-model selection changed trigger to allow Model Panel to update its selection checkbuttons buttons. It does seem pretty expensive even for the original use, if you select all of your 300 open models, Model Panel may try to update its checkbuttons 300 times. Maybe that is fast.

Eric can figure out what to do.

comment:14 by pett, 5 years ago

So what is the recipe here exactly? "sel ~H" does not cause the per-model selection trigger to fire.

comment:15 by pett, 5 years ago

Nor does "select #1" with 1gcn open.

in reply to:  16 ; comment:16 by Tristan Croll, 5 years ago 

I *think* what's happening is that every model subordinate to the 
AtomicStructure fires - which in an ISOLDE scenario makes for quite a 
large number. Will try to probe to identify exactly which ones fire in 
different scenarios.

On 2020-05-27 18:08, ChimeraX wrote:

in reply to:  17 ; comment:17 by Tristan Croll, 5 years ago 

Trying to find where in the code the "selection changed" trigger 
actually gets fired, so I can report which model is responsible. Can 
only find the one in structure.py right now.

On 2020-05-27 18:08, ChimeraX wrote:

comment:18 by pett, 5 years ago

With 1www, which has a "missing structure" submodes, "select #1" does not fire the trigger.

With 1mtx, an NMR ensemble, "select #1" fires the trigger once, for the grouping model.

comment:19 by pett, 5 years ago

The per-model trigger is fired in Model._selection_changed, defined in core/models.py

in reply to:  20 ; comment:20 by Tristan Croll, 5 years ago 

Yep, found it. If I modify it to:

{{{

     def _selection_changed(self):
         from chimerax.core.selection import SELECTION_CHANGED
         
self.session.ui.thread_safe(self.session.triggers.activate_trigger,
                                     SELECTION_CHANGED, self._id)

}}}

... and add a simple reporter in the shell:

{{{
def print_changed_model(trigger_name, mid):
     print('Selection changed for {}'.format(mid))


h = session.triggers.add_handler('selection changed', 
print_changed_model)
}}}

... then after running "isolde demo crystal_intro" to load a model, 
clearing the selection gives:

{{{
select clearSelection changed for (1,)
Selection changed for (1, 2)
Selection changed for (1, 2)
Selection changed for (1, 2, 3)
Selection changed for None
}}}

... and "sel ~H" gives:

{{{
select ~HSelection changed for (1,)
Selection changed for (1, 1)
Selection changed for (1, 1, 1)
Selection changed for (1, 1, 1, 1)
Selection changed for (1, 1, 1, 1, 1)
Selection changed for (1, 1, 1, 1, 2)
Selection changed for (1, 1, 1, 1, 2, 1)
Selection changed for (1, 1, 1, 1, 2, 2)
Selection changed for (1, 1, 1, 1, 3)
Selection changed for (1, 1, 1, 2)
Selection changed for (1, 1, 1, 2, 1)
Selection changed for (1, 1, 1, 2, 1)
Selection changed for (1, 1, 1, 3)
Selection changed for (1, 1, 1, 3, 1)
Selection changed for (1, 1, 1, 3, 2)
Selection changed for (1, 1, 1, 3, 1)
Selection changed for (1, 1, 1, 3, 2)
Selection changed for (1, 1, 1, 4)
Selection changed for (1, 1, 1, 4, 1)
Selection changed for (1, 1, 1, 4, 1)
Selection changed for (1, 1, 1, 5)
Selection changed for (1, 1, 1, 5, 1)
Selection changed for (1, 1, 1, 5, 1)
Selection changed for (1, 1, 1, 5, 2)
Selection changed for (1, 2, 1)
Selection changed for (1, 2, 2)
Selection changed for (1, 2, 2, 1)
Selection changed for (1, 2, 3)
Selection changed for (1, 3)
1658 atoms, 3371 bonds, 25 models selected
Selection changed for None
}}}

... so then the question becomes: what am I doing differently (or *not* 
doing) that causes this different behaviour?


On 2020-05-27 18:36, ChimeraX wrote:

in reply to:  21 ; comment:21 by Tristan Croll, 5 years ago 

Same essential behaviour if I just do "open 3io0 structureFactors true", 
without loading ISOLDE. I've grepped through Clipper's code for "select" 
to double-check that I haven't forgotten doing anything funky with 
selection, and there's nothing there that jumps out at me.

On 2020-05-27 18:48, ChimeraX wrote:

in reply to:  22 ; comment:22 by Tristan Croll, 5 years ago 

Weird. After doing "sel ~H", if I do:

{{{
for m in session.models.list():
     print('{}: {}'.format(m.id_string, m.highlighted))

}}}

... then everything *except* the atomic model reports as highlighted 
(but the symmetry model doesn't actually *draw* highlighted). 
"highlight" doesn't appear anywhere in Clipper's Python code, so I don't 
think it's me doing that.



On 2020-05-27 18:57, ChimeraX wrote:

in reply to:  23 ; comment:23 by Tristan Croll, 5 years ago 

OK, fairly minimal recipe:

{{{
from chimerax.core.models import Model
m = Model('top', session)
session.models.add([m])
models = []
for i in range(10):
     models.append(Model('child{}'.format(i), session))
m.add(models)
from chimerax.open_command.cmd import provider_open
am = provider_open(session, ['3io0'], from_database='pdb', 
_add_models=False)[0]
m.add([am])

}}}

... then any selection command in the command line will fire the 
"selection changed" trigger for *all* models.

On 2020-05-27 19:15, ChimeraX wrote:

comment:24 by pett, 5 years ago

I couldn't install Clipper into my current build, so couldn't try the "open 3io0 structureFactors true" thing, but opening an IHM model produces much the same thing: a hierarchy that contains many non-molecular models. Selecting the IHM model fires the selection-changed trigger multiple times.

There are two approaches to a fix. One would be to modify core/models.py to try to do some sneaky/ugly collation of the triggers. Given that the triggers aren't fired directly but are instead fired later via a ui_safe() call, that approach is even harder than it sounds and is rife with possibilities for additional bugs and/or unintended consequences. The other approach is to modify the select command to block the "selection changed" trigger until it's completely done. I've tried this and it reduces the trigger firings from N down to 2 (one from what the command does directly, and one from when the atomic 'changes' trigger fires later). While not a 100% solution, the latter is much more tractable and probably a 99% solution. The latter approach also has the upside of being in a bundle rather than the core, so I can deploy it immediately after the 1.0 release rather than some indefinite time in the future, so I am going to go with this approach.

in reply to:  25 ; comment:25 by goddard@…, 5 years ago 

I'd suggest looking at how not to use block_trigger().  This creates hard to debug code.  Also any code can set selection state -- if the trigger blocking is in the select command it just solves one case.  Maybe a better design is needed.

Tristan asked whether all these should be batched  to occur once per frame as many ChimeraX triggers are batched.  This particular Model selection changed trigger is an especially weird one in that it is neither synchronous nor batched once per frame drawing because it mysteriously defers trigger firing to execute in the main thread.  This is worrisome, how is this selection change being called in a non-main thread?  Whatever code is calling in a non-main thread could cause all kinds of hard to reproduce problems. If for instance a Qt callback is being invoked in a different thread the fix to get back to the main thread should be in that callback, not downstream.

At any rate, I think Tristan's problem needs more thought, and block_trigger() use should be a last resort.

comment:26 by pett, 5 years ago

Unfortunately, blocking the trigger is probably the best short-term solution. It would be nice if the Model merely requested that the trigger be fired, and then later the trigger got fired more or less when the atomic changes trigger gets fired, but right now the actual firing of the trigger is a mess. It is defined in session.selection (a.k.a. core/selection.py) but fired by atomic.structure.StructureGraphicsChangeManager._update_graphics_if_needed(!) (and by the Model.selected property of course). Some kind of non-trivial revamp would be required to make this better, and it would involve the core.

I’ll put the revamp on my to-do list, but I’m sticking with trigger-blocking in the short term. FYI, ui.thread_safe() does not delay the trigger at all if you are in the main thread already. It don’t know if any threads are setting Model.selected. It may have been implemented that way out of an abundance of caution.

—Eric

Last edited 5 years ago by pett (previous) (diff)

comment:27 by pett, 5 years ago

Resolution: → fixed
Status: assigned → closed

Well, fixed with the crudest trigger-blocking solution (and made that API experimental). Further refinements will be going to a context-manager trigger blocking scheme, and then to eliminate trigger blocking in this particular situation by collating model selection-changed trigger requests. The former will happen soon, and the latter is more medium-term.

comment:28 by pett, 5 years ago

Implemented the second-phase solution of context-manager trigger blocking

comment:29 by pett, 5 years ago

Okay, made both Models and the graphics update set a boolean in session.selection so that the "selection changed" trigger only fires once per changes cycle. Removed the trigger-blocking code from the "select" command.

Note: See TracTickets for help on using tickets.