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.