Skip to content

fix #8991 and enhance collection performance #9125

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 5 commits into from

Conversation

elbehery95
Copy link
Contributor

The commit introduces few performance improvements for _pytest.main.Session.gethookproxy.

As per #8991 it seems that caching gethookproxy can buy some collection time since almost same fspath will yield the same proxy however due to the fact that plugin manger updates _conftest_plugins as it collect; using lru_cache will regress some of the tests.

The fix tries to implement a simple cache dict that is cleared every time the number of seen collected conftest plugin is changed.

Below are results when tested against pandas test suite about 16% less collection time.

hyperfine --warmup=1 --min-runs 4 'venv_vanilla/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count' 'venv_pytest/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count'
Benchmark #1: venv_vanilla/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count
  Time (mean ± σ):     146.703 s ±  1.040 s    [User: 144.008 s, System: 2.980 s]
  Range (min … max):   145.604 s … 148.006 s    4 runs

Benchmark #2: venv_modifyied/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count
  Time (mean ± σ):     126.830 s ±  3.221 s    [User: 124.087 s, System: 3.101 s]
  Range (min … max):   123.021 s … 130.446 s    4 runs

Summary
  'venv_modifyied/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count' ran
    1.16 ± 0.03 times faster than 'venv_vanilla/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count'

And below are line profiler comparison

Before caching

Total time: 64.3543 s
File: pytest/src/_pytest/main.py
Function: gethookproxy at line 543

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   543                                               @profile
   544                                               def gethookproxy(self, fspath: "os.PathLike[str]"):
   545                                                   # Check if we have the common case of running
   546                                                   # hooks with all conftest.py files.
   547    205108     796878.0      3.9      1.2          pm = self.config.pluginmanager
   548    410216   13867279.0     33.8     21.5          my_conftestmodules = pm._getconftestmodules(
   549    205108   38889376.0    189.6     60.4              Path(fspath),
   550    205108    2686139.0     13.1      4.2              self.config.getoption("importmode"),
   551    205108    1025885.0      5.0      1.6              rootpath=self.config.rootpath,
   552                                                   )
   553    205108    1351659.0      6.6      2.1          remove_mods = pm._conftest_plugins.difference(my_conftestmodules)
   554    205108     659567.0      3.2      1.0          if remove_mods:
   555                                                       # One or more conftests are not in use at this fspath.
   556    205096    2566431.0     12.5      4.0              from .config.compat import PathAwareHookProxy
   557
   558    205096    1874691.0      9.1      2.9              proxy = PathAwareHookProxy(FSHookProxy(pm, remove_mods))
   559                                                   else:
   560                                                       # All plugins are active for this fspath.
   561        12         43.0      3.6      0.0              proxy = self.config.hook
   562    205108     636347.0      3.1      1.0          return proxy

After caching

Total time: 11.4839 s
File: /pytest/src/_pytest/main.py
Function: gethookproxy at line 547

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   547                                               @profile
   548                                               def gethookproxy(self, fspath: "os.PathLike[str]") -> PathAwareHookProxy:
   549                                                   # Check if we have the common case of running
   550                                                   # hooks with all conftest.py files.
   551
   552    205813     828010.0      4.0      7.2          len_conftest_plugins = len(self._pm._conftest_plugins)
   553
   554    205813     717134.0      3.5      6.2          if len_conftest_plugins != self._num_conftest_plugins_collected:
   555        23       1052.0     45.7      0.0              self._fspath_hookproxy_cache.clear()
   556        23         84.0      3.7      0.0              self._num_conftest_plugins_collected = len_conftest_plugins
   557
   558    205813    1338631.0      6.5     11.7          proxy: Optional[PathAwareHookProxy] = self._fspath_hookproxy_cache.get(fspath)
   559
   560    205813     674276.0      3.3      5.9          if proxy:
   561    203797     628775.0      3.1      5.5              return proxy
   562
   563      4032    6764603.0   1677.7     58.9          my_conftestmodules = self._pm._getconftestmodules(
   564      2016     421239.0    208.9      3.7              Path(fspath),
   565      2016      29414.0     14.6      0.3              self.config.getoption("importmode"),
   566      2016      11151.0      5.5      0.1              rootpath=self.config.rootpath,
   567                                                   )
   568      2016      20378.0     10.1      0.2          remove_mods = self._pm._conftest_plugins.difference(my_conftestmodules)
   569      2016       6940.0      3.4      0.1          if remove_mods:
   570                                                       # One or more conftests are not in use at this fspath.
   571      2010      22098.0     11.0      0.2              proxy = PathAwareHookProxy(FSHookProxy(self._pm, remove_mods))
   572                                                   else:
   573                                                       # All plugins are active for this fspath.
   574         6         20.0      3.3      0.0              proxy = self.config.hook
   575      2016      13761.0      6.8      0.1          self._fspath_hookproxy_cache[fspath] = proxy
   576      2016       6365.0      3.2      0.1          return proxy

Appreciate your thoughts and feedback

Copy link
Member

@nicoddemus nicoddemus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great @elbehery95, thanks a lot for the contribution and detailed summary.

Besides the minor comments I left, we should also add a changelog/9125.improvement.rst file, with something like:

Improve collection performance by caching the internal hook proxy objects.

Copy link
Member

@nicoddemus nicoddemus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @elbehery95!

One thing I forgot to mention: feel free to add yourself to AUTHORS. 👍

@bluetech
Copy link
Member

I'd like to review this as well, when I get a bit of free time (but if I don't review it in a few days, feel free to merge, I don't intend to block things indefinitely...)

Copy link
Member

@RonnyPfannschmidt RonnyPfannschmidt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is a lovely enhancement

@elbehery95
Copy link
Contributor Author

I am getting different results when trying to import HookCaller It seems that HookCaller is defined inside pluggy.hooks._HookCaller in v0.13.1 and as pluggy._hooks._HookCaller in v1.0.0

setup.cfg defines pluggy dependency pluggy>=0.12,<2.0 in such case this dependency is no longer valid right ? or maybe i am importing the wrong _HookCaller

@RonnyPfannschmidt
Copy link
Member

@elbehery95 indeed, its a "private class" its ok to select based on where its available for now, we should make a issue report to pluggy for making it (or a protocol for it) avaliable as type)

@elbehery95
Copy link
Contributor Author

Added the missing _HookCaller type annotation. Is there is any reason for limiting _getconftestmodules cache size to 128 results. I noticed some extra collection speed-up when maxsize=None

@bluetech
Copy link
Member

(Not a review yet, just a comment)

I'm trying to understand the pre-caching line profile you've shown in the PR description. Do I understand correctly that 64.3543 s is spent in gethookproxy, and 60.4% of that time is just in the line Path(fspath)?

@elbehery95
Copy link
Contributor Author

(Not a review yet, just a comment)

I'm trying to understand the pre-caching line profile you've shown in the PR description. Do I understand correctly that 64.3543 s is spent in gethookproxy, and 60.4% of that time is just in the line Path(fspath)?

Probably yes; this is the base implementation with different format

Total time: 65.7615 s
File: pytest/src/_pytest/main.py
Function: gethookproxy at line 543

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   543                                               @profile
   544                                               def gethookproxy(self, fspath: "os.PathLike[str]"):
   545                                                   # Check if we have the common case of running
   546                                                   # hooks with all conftest.py files.
   547    205108     853594.0      4.2      1.3          pm = self.config.pluginmanager
   548    205108   39292528.0    191.6     59.8          p = Path(fspath)
   549    205108    2775737.0     13.5      4.2          import_mode = self.config.getoption("importmode")
   550    205108    1111320.0      5.4      1.7          root_path = self.config.rootpath
   551    205108   14185275.0     69.2     21.6          my_conftestmodules = pm._getconftestmodules(p, import_mode, rootpath=root_path)
   552    205108    1414525.0      6.9      2.2          remove_mods = pm._conftest_plugins.difference(my_conftestmodules)
   553    205108     703070.0      3.4      1.1          if remove_mods:
   554                                                       # One or more conftests are not in use at this fspath.
   555    205096    2740815.0     13.4      4.2              from .config.compat import PathAwareHookProxy
   556
   557    205096    2007707.0      9.8      3.1              proxy = PathAwareHookProxy(FSHookProxy(pm, remove_mods))
   558                                                   else:
   559                                                       # All plugins are active for this fspath.
   560        12         47.0      3.9      0.0              proxy = self.config.hook
   561    205108     676901.0      3.3      1.0          return proxy

Other usage for pathlib that consume time can be found in _getconftestmodules

Timer unit: 1e-06 s

Total time: 11.6957 s
File: pytest/src/_pytest/config/__init__.py
Function: _getconftestmodules at line 525

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   525                                               @lru_cache(maxsize=128)
   526                                               @profile
   527                                               def _getconftestmodules(
   528                                                   self, path: Path, importmode: Union[str, ImportMode], rootpath: Path   529                                               ) -> List[types.ModuleType]:
   530      2242       9181.0      4.1      0.1          if self._noconftest:
   531                                                       return []
   532
   533      2242      90943.0     40.6      0.8          if path.is_file():
   534      1957      47316.0     24.2      0.4              directory = path.parent
   535                                                   else:
   536       285        911.0      3.2      0.0              directory = path
   537
   538                                                   # XXX these days we may rather want to use config.rootpath
   539                                                   # and allow users to opt into looking into the rootdir parent
   540                                                   # directories instead of requiring to specify confcutdir.
   541      2242       6647.0      3.0      0.1          clist = []
   542     23086     575779.0     24.9      4.9          for parent in reversed((directory, *directory.parents)):
   543     20844    3180991.0    152.6     27.2              if self._confcutdir and parent in self._confcutdir.parents:
   544      8968      27306.0      3.0      0.2                  continue
   545     11876     880322.0     74.1      7.5              conftestpath = parent / "conftest.py"
   546     11876     562783.0     47.4      4.8              if conftestpath.is_file():
   547      4169    6242670.0   1497.4     53.4                  mod = self._importconftest(conftestpath, importmode, rootpath)
   548      4169      16294.0      3.9      0.1                  clist.append(mod)
   549      2242      48137.0     21.5      0.4          self._dirpath2confmods[directory] = clist
   550      2242       6397.0      2.9      0.1          return clist

where looking up if parent in parents takes about 30% from the total time ; I keep thinking that using is_relative_to or equivalent can be faster but not sure if this is valid or not

>>> from pathlib import Path
>>> a = Path() ; b = Path()/'src/config/__init__.py'
>>> timeit.timeit(lambda: a in b.parents, number=30000)
0.8800809980020858
>>> timeit.timeit(lambda: str(b).startswith(str(a)), number=30000)
0.06638047900923993

@RonnyPfannschmidt
Copy link
Member

@elbehery95 great find, i believe it may be sensible to check the parts attributes for quick checking

@bluetech
Copy link
Member

bluetech commented Oct 1, 2021

@elbehery95 I've made some changes in main branch that would affect the numbers here. Could you rebase and see how the PR behaves after?

Sorry for the hassle. The reason I'm hesitant to add caches is that they have memory overhead and invalidation issues and generally make the code harder to understand and refactor. Especially in this case which deals with imports and side effects. So I always try to optimize the underlying operation first.

@elbehery95
Copy link
Contributor Author

Branch is rebased.

Below is the comparison between current main (with path workaround and re-based gethookproxy with cache) about 20% gain

hyperfine --warmup=1 --min-runs 4 'venv_vanila/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count' 'venv_modified/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count'
Benchmark #1: venv_vanila/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count
  Time (mean ± σ):     118.802 s ±  0.257 s    [User: 116.185 s, System: 2.993 s]
  Range (min … max):   118.515 s … 119.140 s    4 runs
 
Benchmark #2: venv_modified/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count
  Time (mean ± σ):     97.289 s ±  2.239 s    [User: 95.390 s, System: 2.190 s]
  Range (min … max):   95.295 s … 100.213 s    4 runs
 
Summary
  'venv_modified/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count' ran
    1.22 ± 0.03 times faster than 'venv_vanila/bin/pytest --collect-only -q pandas/pandas/tests -k test_nans_count'

@elbehery95
Copy link
Contributor Author

I am seeing "Changes requested" but not able to spot what are those changes as i marked all of them as resolved. Let me know if anything is required from my side

Copy link
Member

@RonnyPfannschmidt RonnyPfannschmidt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

my changes requested was not resolved, so i just approved now :)

return proxy

def pytest_plugin_registered(self, plugin):
self._fspath_hookproxy_cache.clear()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

im wondering if we could limit the invalidations to conftest registrations (and possibly do partial invalidations later

this is a followup idea

Copy link
Member

@bluetech bluetech left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm still a bit suspicious of this cache, but I guess we can try it.

I left a few comments.

# Check if we have the common case of running
# hooks with all conftest.py files.

pm = self.config.pluginmanager
proxy: Optional[PathAwareHookProxy] = self._fspath_hookproxy_cache.get(fspath)
Copy link
Member

@bluetech bluetech Oct 10, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The cache should be keyed off path, not fspath, this way it's normalized to a single unsurprising type.

# Cache of hookproxy objects, which speeds up collection.
# The cache is cleared whenever a new plugin got registered.
# See #9125 for a detailed summary of the gains.
self._fspath_hookproxy_cache: Dict[
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the fspath_ part is redundant, just _hookproxy_cache is enough and matches gethookproxy.

# Check if we have the common case of running
# hooks with all conftest.py files.

pm = self.config.pluginmanager
proxy: Optional[PathAwareHookProxy] = self._fspath_hookproxy_cache.get(fspath)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why the annotation? It looks like it (incorrectly) gets rid of the _HookCaller part of the union.

return proxy

def pytest_plugin_registered(self, plugin):
self._fspath_hookproxy_cache.clear()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the argument that this is sufficient for the cache invalidation here? (would be good as a code comment)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i believe this could need a note on conftests,

i suspect it may be acceptable to do the invalidation only on the registration of conftests

@holmanb
Copy link
Contributor

holmanb commented Jan 17, 2022

I'm excited to see potential improvements in collection performance. A project I work on spends much longer on collection than I would expect (6s collection time, 30s total test time for a project of ~150 files in ~3000 tests).

It looks like this work has stalled. @elbehery95 do you plan to continue working on this PR?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants