Slow import of affiliate packages
Closed this issue · 11 comments
The following line in __init__.py takes about 500ms on my laptop and dominates the time required to import my affiliated package:
from ._astropy_init import *
Could this be streamlined to defer some its work until it is actually needed?
Try profiling it to see exactly where in astropy_init it is the slowest.
Thanks for the suggestion. Here is what I ran:
import cProfile, pstats
cProfile.run('from speclite._astropy_init import *', 'import_profile')
pstats.Stats('import_profile').sort_stats('cumulative').print_stats(15)
The output is:
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.614 0.614 speclite/__init__.py:5(<module>)
1 0.001 0.001 0.614 0.614 speclite/_astropy_init.py:3(<module>)
1 0.001 0.001 0.496 0.496 .../astropy/__init__.py:7(<module>)
1 0.001 0.001 0.362 0.362 .../astropy/logger.py:2(<module>)
1 0.001 0.001 0.360 0.360 .../astropy/utils/console.py:5(<module>)
1 0.003 0.003 0.308 0.308 .../astropy/units/__init__.py:11(<module>)
2673/2645 0.007 0.000 0.144 0.000 .../astropy/units/core.py:1967(__init__)
2 0.000 0.000 0.132 0.066 .../astropy/units/core.py:279(set_enabled_units)
2 0.000 0.000 0.132 0.066 .../astropy/units/core.py:144(set_enabled_units)
5 0.008 0.002 0.132 0.026 .../astropy/units/core.py:163(add_enabled_units)
2673/2645 0.036 0.000 0.127 0.000 .../astropy/units/core.py:2029(_expand_and_gather)
1 0.000 0.000 0.117 0.117 .../astropy/units/astrophys.py:7(<module>)
1 0.000 0.000 0.117 0.117 speclite/version.py:2(<module>)
2 0.000 0.000 0.116 0.058 speclite/version.py:54(get_git_devstr)
2 0.000 0.000 0.115 0.058 speclite/version.py:98(run_git)
Looking at the call graph, I see that the following nested import chain dominates the timing:
_astropy_init => astropy => astropy.logger => astropy.utils.console => astropy.units
As expected, a profile of import astropy looks essentially the same.
It does seem unusual that it is importing astropy.units on init. Just guessing here, I wonder if it is because your version string (https://github.com/dkirkby/speclite/blob/master/setup.py#L50) is not PEP 386 compatible (https://www.python.org/dev/peps/pep-0386/#the-new-versioning-algorithm). Any improvement if you change your version to '0.6.dev0'?
Changing the version string does not make a difference, but I was following the affiliated pkg instructions, so perhaps there's a separate issue there.
Note that the version stuff only accounts for about 20% of the profile report, and is dominated by the time spent firing up a subprocess to call git and get the current commit hash.
@pllim - actually I think that this isn't due to his version string but really just to the fact that importing astropy alone results in astropy.units being imported (due to the console import relying on units). This does seem silly though, I think we should consider making the console stuff not depend on units since the unit conversion is simple.
@astrofrog , ah, okay. But I thought you and @mhvk sped up units. I wonder if the import time would improve if @dkirkby uses the dev version of Astropy (not sure what version is being used when code was profiled).
I used astropy 1.1.1 for the profile above.
Just out of curiousity, if possible, what does the timing look like if you use dev version of Astropy?
It should be better with Astropy 1.2, the import is now done only if the logger is used:
astropy/astropy#4649
I just repeated the profile above with astropy 1.2.1 and it is much faster (great!) so I am happy to close this now.