18th June 2019 - Performance

README.md

Startup Performance

Startup time is currently the main bottleneck and comes in two parts.

1. Showing the window (reading Python, Qt and Rez off of disk)
2. Showing the apps (resolving all contexts)

(1) can be improved be localising software like Python and Qt onto disk, but even then I expect a 1-2 second delay from asking LA2 to boot up and actually seeing it on screen. There are a lot of files being requested.

(2) is already being improved via memcached, however it typically won't take effect until after the first resolve. Each resolve can take anywhere between 1-20 seconds.

• The goal is getting startup time unhindered by IO
• Which should cut down the time from 10 seconds to 1 second

So let's have a look.

1h later

Ok, so here are timings as of right now.

$ launchapp2
shell to python: 1.09 s
==============================
 launchapp2 (1.1.62)
==============================
- Loading Rez.. ok - 0.25s
- Loading Qt.. ok - 0.14s
- Loading launchapp2.. ok - 0.19s
- Loading preferences.. ok - 0.00s
------------------------------
- Resolving contexts.. ok 0.50s

Breakdown

• shell to python This is total time spent between calling Python and having it run launchapp2.__main__.py, before having imported any modules (other than built-in like os and sys).
• Loading Rez Importing relevant Rez modules
• Loading Qt Importing Qt.py along with a given binding, such as PySide2
• Loading launchapp2 Importing relevant modules from launchapp2
• Loading preferences Loading and populating a QSettings instance, stored as a .ini file on the local disk (regardless of whether LA2 runs off a network)
• Resolving contexts For each application in a given project, a context is resolved. This is where memcached shines, as without it this would take significantly longer, possibly minutes.

Roughly 2 seconds total, under ideal circumstances.

winsat disk -drive c
Windows System Assessment Tool
# Running: Feature Enumeration ''
# ...
# Dshow Video Encode Time                      0.00000 s
# Dshow Video Decode Time                      0.00000 s
# Media Foundation Decode Time                 0.00000 s
# Disk  Random 16.0 Read                       341.88 MB/s          8.1
# Disk  Sequential 64.0 Read                   565.21 MB/s          8.1
# Disk  Sequential 64.0 Write                  70.85 MB/s           6.0
# Average Read Time with Sequential Writes     1.197 ms             7.5
# Latency: 95th Percentile                     7.800 ms             6.0
# Latency: Maximum                             20.726 ms            7.9
# Average Read Time with Random Writes         1.575 ms             6.9

The critical feature here is Random 16.0 Read which is what Python and friends spend most of their time doing, as each file is relatively small (bytes to kilobytes). The final scenario we're working with is that of a mechanical disk, with these numbers.

winsat disk -drive d
Windows System Assessment Tool
# Running: Feature Enumeration ''
# ...
# Dshow Video Encode Time                      0.00000 s
# Dshow Video Decode Time                      0.00000 s
# Media Foundation Decode Time                 0.00000 s
# Disk  Random 16.0 Read                       1.37 MB/s           3.7
# Disk  Sequential 64.0 Read                   98.10 MB/s          6.5
# Disk  Sequential 64.0 Write                  120.22 MB/s         6.9
# Average Read Time with Sequential Writes     5.200 ms            5.9
# Latency: 95th Percentile                     16.652 ms           4.9
# Latency: Maximum                             88.878 ms           7.7
# Average Read Time with Random Writes         6.580 ms            5.5
# Total Run Time 00:00:45.42

Not great. Odds are we'll have to invest in greater hardware once this becomes the bottleneck.

Before then, the first scenario is optimising for disk access over a network, for which winsat unfortunately doesn't apply, but it's safe to assume random access is far worse than even that of the mechanical disk.