Improve startup time

[willingc]

Context
Currently on MacOS 10.15.3, the CLI is slow to display after typing augur.

Description
Investigate if there is an optimization that can be made.

[groutr]

@willingc I'll dig into this.

[jasongrout]

Just curious, are you seeing it being slow on Linux too?

[groutr]

I guess the question is how slow is "slow"? Running my processor at 2.4Ghz, it takes 1.073s to run augur. How slow it is on Mac OS?

If my laptop processor is running with dynamic frequency scaling, the augur command can take between 1.5-2s.

EDIT: This is with Python 3.7, btw.

[groutr]

I notice that augur imports the entire library every time it is run or even imported.
https://github.com/nextstrain/augur/blob/master/augur/__init__.py#L40

Ideally, all this code should live __main__.py. There is no need to be executing this in __init__.py

[willingc]

The specific start case that I was seeing was typing augur with no options after. It takes a long time on my Mac to present any information.

[groutr]

@willingc can you post the output of time <augur command>?

[willingc]

Hi @groutr,

Whelp in true software fashion it's not slow today. lol

Here's the output requested: augur 0.94s user 0.18s system 114% cpu 0.983 total

If you want feel free to close now.

[jasongrout]

As another data point, on macOS 2.4 GHz Intel Core i5: augur 1.27s user 0.23s system 106% cpu 1.415 total

[groutr]

Thanks @willingc and @jasongrout. I'm going to experiment with restructuring the cli to import things lazily.

[groutr]

Looks like the help pages are probably the worst case scenario. However, I would argue that if the help pages aren't fast, it gives the impression that the program itself is slow.

Fortunately, the help pages are easy to speed up. I was able to drop the time from >1s to about < .1s on my machine.
The benefit of this reorganization is that we only import the module that is needed instead of all of them.

[groutr]

Example

(augur-dev) ❯ time python -m augur.__main__ version
augur 6.4.3
python -m augur.__main__ version  0.83s user 0.08s system 99% cpu 0.913 total

(augur-dev) ❯ time python -m augur.cli version
augur 6.4.3
python -m augur.cli version  0.05s user 0.00s system 98% cpu 0.048 total

[corneliusroemer]

I can confirm that the issue still exists. Using augur for the first time today and I was surprised at how unresponsive the CLI is. Very unusual for and potentially off-putting.

Really shouldn't be hard to fix for the common case of displaying help information.

Here's another data point

augur  1.32s user 0.38s system 109% cpu 1.548 total

with the following machine

Model Name: MacBook Pro
Model Identifier: MacBookPro15,1
Processor Name: 6-Core Intel Core i7
Processor Speed: 2.2 GHz
Memory: 16 GB
System Version: macOS 11.3.1 (20E241)

[victorlin]

Noting that this is impacting CI run times. Example: the latest scheduled run took 13m43s to complete. The bottleneck is cram tests which take ~11 minutes to run. Some cram tests do take a while, but I suspect a chunk of it is simply startup time.

[tsibley]

Cram tests are so slow. It's particularly painful to iterate on them in local dev.

[victorlin]

I found this lazy ArgumentParser approach that seemed promising at a quick glance and tried it out: 31d8df3

It needs a lot more work as detailed in the commit message, but seems like a potential solution that avoids moving argument handling out of subcommand files.

[victorlin]

As @jameshadfield alluded to in #1664 (comment), most of the startup time is spent on resolving imports. By running time PYTHONPROFILEIMPORTTIME=1 augur -h 2> import.log and visualizing with tuna, I observed in one run which took 1.3 seconds total, ~1.2 seconds was spent on imports.

The run time of the Augur code was just 0.02 seconds reported by cProfile + snakeviz.

[tsibley]

Right, imports unnecessary to run the current command (or show the command's --help) are the problem. I've previously talked about this with the framing of "don't import bits of Augur we don't need for this invocation" (and that was also what a proposed-but-not-merged PR did), but the reason to avoid importing bits of Augur we don't need is because they in turn import lots of other stuff and cumulatively that's slow.

Relatedly, a standalone install of Nextstrain CLI is noticeably faster to start up than a non-standalone install, because its importing most of its dependencies from memory instead of the filesystem. Nextstrain CLI uses a roughly equivalent approach to subcommands and imports as Augur. I've previously mentioned this casually a few other times in various places, but it seems worth recording here.

[victorlin]

Relatedly, a standalone install of Nextstrain CLI is noticeably faster to start up than a non-standalone install, because its importing most of its dependencies from memory instead of the filesystem.

That's only a good comparison against an initial "cold start" of a non-standalone install. Subsequent invocations should also load dependencies from memory due to caching (at least on my computer), making the speed comparable to a standalone install:

$ for i in {1..5}; do time ~/.micromamba/envs/nextstrain-cli/bin/nextstrain --help >/dev/null; done
0.39s user 0.10s system 24% cpu 2.049 total
0.25s user 0.05s system 98% cpu 0.302 total
0.24s user 0.05s system 98% cpu 0.295 total
0.21s user 0.04s system 99% cpu 0.254 total
0.22s user 0.04s system 99% cpu 0.263 total

$ for i in {1..5}; do time ~/.nextstrain/cli-standalone/nextstrain --help >/dev/null; done
0.21s user 0.05s system 70% cpu 0.365 total
0.22s user 0.02s system 97% cpu 0.244 total
0.19s user 0.01s system 98% cpu 0.207 total
0.20s user 0.02s system 94% cpu 0.230 total
0.19s user 0.01s system 98% cpu 0.209 total

The timing result in my previous comment was after a few consecutive runs, so most dependencies should have been loaded from memory. This is what I get after a fresh reboot:

$ for i in {1..5}; do time ~/.micromamba/envs/nextstrain-augur/bin/augur --help >/dev/null; done
0.66s user 0.29s system 33% cpu 2.806 total
0.55s user 0.11s system 99% cpu 0.668 total
0.55s user 0.12s system 98% cpu 0.679 total
0.55s user 0.11s system 99% cpu 0.663 total
0.55s user 0.11s system 99% cpu 0.672 total

[tsibley]

That's only a good comparison against an initial "cold start" of a non-standalone install. Subsequent invocations should also load dependencies from memory due to caching (at least on my computer), making the speed comparable to a standalone install:

Yeah, true, the disk page cache helps. But those pages are easily evicted if not frequently used, and each eviction "resets" the start up time.

The non-standalone installs also incur more disk accesses (e.g. stat syscalls) due to searching sys.path every time for where the files are located.

BTW, on Linux you can clear the disk caches without rebooting with either:

sudo tee /proc/sys/vm/drop_caches <<<3    # or
sudo sysctl --write vm.drop_caches=3

There is probably a similar method for macOS.

(Also, to be clear, I'm totally not saying we should bundle Augur like we do Nextstrain CLI. I don't think we should!)