Session save/restore slow

[Tom Goddard]

Session save of 3j3q takes 44 seconds and restore takes 26 seconds (on my office iMac, late 2012), and session file size is 57 Mbytes.

This seems quite slow compared to the 13 seconds it takes to open the mmCIF file (file size 266 Mbytes).

[Tom Goddard]

Eric reports that the AtomicStructure save (4 seconds) and restore (6 seconds) for 3j3q is much faster, timing only the data structures that get pickled.

From: Eric Pettersen
Subject: Re: 3j3q session save performance
Date: January 14, 2016 at 11:42:18 AM PST
To: Tom Goddard <goddard@…>

By my measurement, saving the AtomicStructure takes 4.03 seconds. Restoring the AtomicStructure takes 5.87 seconds, 4.18 of which is the C++ restore.

[pett]

These timings remain largely unchanged as of this date (19 April 2016).  In the form: command time + draw time = total time…

open 3j3q:  11.5 + .3 = 11.8
save 3j3q.cxs:  41.9
close:  4.9 + .0 = 4.9
open 3j3q.cxs.gz:  26.1 + 1.0 = 27.1

Session size is still 57MB.

—Eric

[pett]

gzipping the 402MB session file takes about 8 seconds, leaving ~34 seconds.

[pett]

The bulk of the time used in session.save is in two sections of the routine (19 seconds each):  mgr.discovery(self._state_containers), and in the mgr.walk() loop.

Looking at the loop, almost all of the 19 seconds is in serializing AtomicStructure.  Since the only calls in the loop are to serialize.serialize(), and that’s a thin veneer over pickle, the pickling is taking somewhere between 11 and 19 seconds (depending on how much of the time is for compressing the data).

As for mgr.discovery, almost all the time is in mgr.process() for the AtomicStructure state manager.  As reported earlier in the ticket, take_snapshot() takes about 4 seconds, whereas copy_state() of the state returned by take_snapshot takes 15 seconds.  Is there any way to mark the state data as “ready to go” and not needing copying?  Greg?

—Eric

[Greg Couch]

Currently, the copy state protocol does not know when it doesn't have to copy. So that is definitely something to work on.

[Tom Goddard]

Here's another test case using a 3.8 million atom nuclear pore model containing 746 models in one PDB file. It takes 15 seconds to open and display the PDB as spheres. Saving the session takes 75 seconds, and restoring the session takes 38 seconds. So it is 2.5x slower to open the session versus opening the PDB. Because the session is binary I would expect it to be faster than opening the PDB. And writing the session took 5x longer than the PDB open.

[Tom Goddard]

PyMol took 40 seconds to open a nuclear pore session that includes the same models and in addition an EM density map (EMDB 3103).

I haven't attached the nuclear pore data because it is large (300 Mbyte PDB file, 90 Mbyte ChimeraX gzip session file).

[pett]

I implemented a FinalizedState class that alerts the session-saving mechanism that the contained data is all Python primitives and does not need to be examined further. I made the molecular data use FinalizedState and that dropped the session-save time from 44.23 seconds to 27.57.

--Eric

[Greg Couch]

Putting FinalizedState into the session files allows them to be restored quicker. So it is now faster than before -- resolving object references on restore went from 85% to ~2% of the time for session of 4v8r for a 6X speed up. msgpack version was 4X faster than pickle.

[pett]

Just FYI, current timings with my build is 13 seconds to open the 3j3q mmCIF file, 20 seconds to save the session (399 MB!) and 9 seconds to restore it.