Status message slow rendering frame rate on Linux

[tic20@…]

Rendering a status message once per frame slows the frame rate from 55 frames per second to about 35 frames per second. Possibly Qt is slow doing updates with X11 server running in another process.

Begin forwarded message:

From: Tristan Croll
Subject: Re: (minor) Writing to status bar causes noticeable delay in main window
Date: December 17, 2016 at 4:04:57 AM PST
To: Tom Goddard

Hi Tom,

OK, it's definitely the printing to the status bar that's doing it - although it's smart enough to recognise when the string hasn't changed. The below code is sufficient to replicate the behaviour - it adds a trigger to do a 1 degree rotation every new frame, optionally printing a string including a random float to the status bar every fourth frame (to replicate the printing rate of the fps indicator). If I do (with 5mdz loaded with the standard on-loading representation):

r = Rotator()
r.rotations(180, print=False)

then three replicate runs give me:

Total time for 180 rotations was 3.3840367794036865
Total time for 180 rotations was 3.2539782524108887
Total time for 180 rotations was 3.275675058364868

r.rotations(180, print=True)
Total time for 180 rotations was 5.39902138710022
Total time for 180 rotations was 5.227720737457275
Total time for 180 rotations was 5.211796998977661

... so about a 50% loss of performance. As an alternative test, simply commenting out the final line of fps.py (so it calculates and formats the string, but doesn't actually try to print it) knocks out all the performance loss. With lighting set to simple:

r.rotations(180, False)

Total time for 180 rotations was 2.9913718700408936
Total time for 180 rotations was 2.9813802242279053
Total time for 180 rotations was 3.100327968597412

r.rotations(180, True)

Total time for 180 rotations was 4.670018434524536
Total time for 180 rotations was 4.486111879348755
Total time for 180 rotations was 4.49118185043335

... so about the same delay (roughly 33 ms per print event, by my reckoning).

class Rotator():

def init(self):

self.i = 0
self.max = None
self.handler = None

def rotate(self, *_):

from time import time
import random
session.view.rotate([0,0,1],1)
if self.print:

if self.i%4 == 0:

session.logger.status('Long test string with {} formatted number'.format(random.random()))

self.i += 1
if self.i >= self.max:

session.triggers.remove_handler(self.handler)
print('Total time for {} rotations was {}'.format(self.i, time()-self.start_time))

def rotations(self, num, print):

self.print = print
from time import time
self.start_time = time()
self.i = 0
self.max = num
self.handler = session.triggers.add_handler('new frame', self.rotate)

On 2016-12-16 19:25, Tom Goddard wrote:
It could be specific to Linux Qt. Let me know if you observe the
problem on the Mac. We are currently investigating status line — I
disabled immediate updates to the status line about 1 week ago in
ChimeraX because it involved reentering a limited Qt event loop for
each status message and that caused mouse up events to be lost in
volume viewer. So now status messages will only appear after returning
to the event loop. I have also found this past week that Qt seems to
give the graphics timer event low priority — if any mouse event is
pending then the timer will not fire. Maybe the status repaint events
also preempt the graphics timer from firing. With the mouse events
this was causing dragging the contour level of a map on the histogram
to show no updates of the surface until you stopped dragging. I fixed
that particular case. The priority of the graphics redraw timer versus
other Qt events may differ on different operating systems.
Tom
On Dec 16, 2016, at 11:13 AM, Tristan Croll wrote:
Hi Tom,
No special instructions. Moderately-sized (~1500 residue) structure,
the vanilla fps code, in Linux. Will try it on the home mac for
comparison.
Tristan Croll
Research Fellow
Cambridge Institute for Medical Research
University of Cambridge CB2 0XY
On 16 Dec 2016, at 19:09, Tom Goddard < wrote:
Hi Tristan,
Eric passed you framerate / status message slow down to me. I tried
this with the current ISOLDE fps code, current ChimeraX, and a
280,000 atom structure (4v50) on my 2012 iMac and saw no slow down
when framerate is shown versus not shown. Could you give specific
instructions on how to reproduce the problem? I did not look at your
code but if you were for instance to blast 100 status line messages
every graphics redraw I would expect that to slow things down, but
if it is just one per frame I would not expect a noticable effect.
Tom
On Dec 16, 2016, at 10:50 AM, Eric Pettersen
wrote:
As promised...
Begin forwarded message:
FROM: Tristan Croll
SUBJECT: (MINOR) WRITING TO STATUS BAR CAUSES NOTICEABLE DELAY IN
MAIN WINDOW
DATE: December 16, 2016 at 7:58:29 AM PST
TO: ChimeraX <ChimeraX-bugs-admin@…>
Hi all,
A very minor thing, I think, but it's something that wasn't there
before. If I start ISOLDE and then its framerate indicator ('fps
start' at the CLI), then rotation of the model in the main window
becomes noticeably jerky as if writing text to the status bar is
taking a non-trivial amount of time.
Cheers,
Tristan

[Tom Goddard]

On Mac there is negligible slowdown (1-2%)

Begin forwarded message:

From: Tristan Croll
Subject: Re: (minor) Writing to status bar causes noticeable delay in main window
Date: December 17, 2016 at 4:19:17 AM PST
To: Tom Goddard

... and for the same code, there's minimal difference on the Mac:

r.rotations(180, False)

Total time for 180 rotations was 4.943265914916992
Total time for 180 rotations was 4.495807886123657
Total time for 180 rotations was 4.481817960739136

r.rotations(180, True)

Total time for 180 rotations was 4.6964240074157715
Total time for 180 rotations was 4.551092147827148
Total time for 180 rotations was 4.541028022766113

[Tom Goddard]

Changed status message display code to use OpenGL (a horrendous hack) in order to avoid Qt processing events during status messages. This was necessary to avoid side-effects when showing progress status during a computation.

Not sure if this will make status messages on Linux faster or slower. Hope it is faster.