rough performance analysis of the current internals

[RonnyPfannschmidt]

this is the second followup to #401

its about time we take a good looks what eats time when executing pytest,
the last deep look was quite a while ago

[rajibmitra]

can I work on it ?

[RonnyPfannschmidt]

Feel free to, please send a mail to the ml and join the IRC channels if IRC works out for you

[boxed]

We have a test suite at TriOptima where if you run pytest 3.4.0 with "-k this_will_never_match_anything", it takes 3 seconds. But if I upgrade to 3.9.2 that's suddenly 13(!) seconds. Some profiling reveals:

In [7]: Stats('pytest3.4').sort_stats('tottime').print_stats(40)                                                                  
Wed Oct 24 13:40:31 2018    pytest3.4

         7104316 function calls (6876020 primitive calls) in 7.618 seconds

   Ordered by: internal time
   List reduced from 15512 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    74504    0.593    0.000    0.593    0.000 {built-in method posix.stat}
     2305    0.327    0.000    0.327    0.000 {built-in method marshal.loads}
8109/7564    0.170    0.000    1.824    0.000 {built-in method builtins.__build_class__}
329269/329064    0.169    0.000    0.172    0.000 {built-in method builtins.getattr}
 24228/51    0.126    0.000    7.495    0.147 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/pluggy/callers.py:151(_multicall)
444973/444109    0.124    0.000    0.177    0.000 {built-in method builtins.isinstance}
    37865    0.123    0.000    0.466    0.000 /Users/andersh/triresolve/env3/lib/python3.6/copy.py:66(copy)
    43680    0.113    0.000    0.118    0.000 {built-in method __new__ of type object at 0x10a7dd840}
193459/193417    0.106    0.000    0.122    0.000 {built-in method builtins.hasattr}
     1913    0.090    0.000    0.090    0.000 {built-in method posix.listdir}
     2308    0.089    0.000    0.120    0.000 <frozen importlib._bootstrap_external>:830(get_data)
      251    0.089    0.000    0.089    0.000 {built-in method marshal.load}
    40333    0.088    0.000    0.147    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:75(join)
    79/63    0.083    0.001    0.144    0.002 {built-in method _imp.create_dynamic}
      745    0.080    0.000    0.086    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/django/forms/fields.py:63(__init__)
  23975/2    0.079    0.000    7.493    3.747 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/pluggy/__init__.py:603(__call__)
   236513    0.075    0.000    0.088    0.000 {built-in method posix.fspath}
    13799    0.072    0.000    0.113    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:331(normpath)
24349/20443    0.067    0.000    0.786    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/config.py:325(_getconftestmodules)
   128641    0.066    0.000    0.066    0.000 {method 'split' of 'str' objects}
    39388    0.062    0.000    0.543    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:371(check)
      486    0.062    0.000    0.439    0.001 /Users/andersh/triresolve/env3/lib/python3.6/imp.py:255(find_module)
    36513    0.060    0.000    0.221    0.000 /Users/andersh/triresolve/env3/lib/python3.6/copy.py:268(_reconstruct)
35999/4576    0.059    0.000    0.689    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/tri/declarative/__init__.py:70(__init__)
    31606    0.056    0.000    0.075    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/tri/token/__init__.py:28(__init__)
    44967    0.056    0.000    0.370    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/genericpath.py:27(isfile)
   201158    0.055    0.000    0.055    0.000 {method 'startswith' of 'str' objects}
     4013    0.052    0.000    0.116    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/tri/token/__init__.py:46(__init__)
   2865/1    0.049    0.000    7.622    7.622 {built-in method builtins.exec}
      705    0.049    0.000    0.060    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/django/db/models/fields/related.py:67(lazy_related_operation)
    25397    0.048    0.000    0.078    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:282(_getbyspec)
     4087    0.045    0.000    0.245    0.000 <frozen importlib._bootstrap_external>:1233(find_spec)
   222375    0.042    0.000    0.048    0.000 {method 'get' of 'dict' objects}
   335322    0.040    0.000    0.040    0.000 {method 'append' of 'list' objects}
    16747    0.039    0.000    0.072    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:154(dirname)
     1113    0.037    0.000    0.038    0.000 {built-in method io.open}
     2942    0.037    0.000    0.060    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/django/db/models/fields/__init__.py:145(__init__)
    28539    0.037    0.000    0.037    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
     2920    0.037    0.000    1.175    0.000 <frozen importlib._bootstrap>:870(_find_spec)
     6081    0.036    0.000    0.063    0.000 {built-in method builtins.dir}


Out[7]: <pstats.Stats at 0x103da2898>

In [8]: Stats('pytest3.9').sort_stats('tottime').print_stats(40)                                                                  
Wed Oct 24 13:41:08 2018    pytest3.9

         44300096 function calls (44049151 primitive calls) in 24.070 seconds

   Ordered by: internal time
   List reduced from 15698 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  1801661    2.927    0.000    5.233    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:154(dirname)
  9066854    2.767    0.000    3.623    0.000 {built-in method posix.fspath}
   208445    1.860    0.000   11.618    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/common.py:315(parts)
  1789894    1.548    0.000    7.161    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:312(dirpath)
  3543756    1.458    0.000    4.706    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:163(__eq__)
   110852    0.948    0.000    0.948    0.000 {built-in method posix.stat}
  7115283    0.856    0.000    0.856    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/common.py:394(__fspath__)
  1859892    0.571    0.000    0.923    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:41(_get_sep)
   150272    0.568    0.000   10.339    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/main.py:535(<genexpr>)
  1810946    0.529    0.000    0.529    0.000 {method 'rfind' of 'str' objects}
  1836546    0.479    0.000    0.484    0.000 {built-in method __new__ of type object at 0x103507840}
2297823/2296959    0.467    0.000    0.523    0.000 {built-in method builtins.isinstance}
  1431322    0.388    0.000    0.388    0.000 {method 'rstrip' of 'str' objects}
  2036776    0.261    0.000    0.261    0.000 {method 'append' of 'list' objects}
     2323    0.235    0.000    0.235    0.000 {built-in method marshal.loads}
2132768/2131097    0.234    0.000    0.235    0.000 {built-in method builtins.len}
    62679    0.231    0.000    4.120    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/main.py:530(<genexpr>)
8155/7610    0.173    0.000    1.733    0.000 {built-in method builtins.__build_class__}
347520/347310    0.171    0.000    0.173    0.000 {built-in method builtins.getattr}
 26125/51    0.157    0.000   23.911    0.469 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/pluggy/callers.py:157(_multicall)
    89562    0.152    0.000    0.257    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:282(_getbyspec)
   315483    0.148    0.000    0.148    0.000 {method 'split' of 'str' objects}
202362/202320    0.118    0.000    0.133    0.000 {built-in method builtins.hasattr}
    52153    0.115    0.000    0.192    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:75(join)
  25869/2    0.110    0.000   23.909   11.954 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/pluggy/hooks.py:270(__call__)
    64362    0.108    0.000    0.906    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/py/_path/local.py:371(check)
     4162    0.104    0.000    0.111    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/nodes.py:77(__init__)
     2040    0.100    0.000    0.100    0.000 {built-in method posix.listdir}
    74565    0.098    0.000    0.714    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/genericpath.py:27(isfile)
    37867    0.096    0.000    0.423    0.000 /Users/andersh/triresolve/env3/lib/python3.6/copy.py:66(copy)
      251    0.087    0.000    0.087    0.000 {built-in method marshal.load}
    22396    0.087    0.000    1.131    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/config/__init__.py:379(_getconftestmodules)
     2326    0.086    0.000    0.117    0.000 <frozen importlib._bootstrap_external>:830(get_data)
   312214    0.085    0.000    0.085    0.000 {method 'startswith' of 'str' objects}
      519    0.084    0.000    0.630    0.001 /Users/andersh/triresolve/env3/lib/python3.6/imp.py:255(find_module)
      745    0.082    0.000    0.088    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/django/forms/fields.py:63(__init__)
    15976    0.080    0.000    0.126    0.000 /Users/andersh/triresolve/env3/bin/../lib/python3.6/posixpath.py:331(normpath)
     3629    0.078    0.000    0.085    0.000 /usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/inspect.py:485(unwrap)
    79/63    0.077    0.001    0.124    0.002 {built-in method _imp.create_dynamic}
    55882    0.071    0.000    0.303    0.000 /Users/andersh/triresolve/env3/lib/python3.6/site-packages/_pytest/fixtures.py:1367(getfixturedefs)

To summarize: 3 seconds just in dirname(), ~3 in fspath(), stuff in py/_path maybe 7ish?.

[blueyed]

@boxed
Can you try #4224, please?
I think this might be partly caused by 52ff1ea.

[boxed]

14.14 -> 13.27. So some improvement, but not really significant compared to the big problem outlined in the profiler output above. It would be a big improvement if the problem with path handling was fixed though :P

[blueyed]

Ok.
Then it appears to be something else that is using py.path a lot more than before.
It would be useful if you could look at the actual callers for this.
Also of couse bisecting would help, but that might be tedious (from 3.4 to 3.9).

It would be a big improvement if the problem with path handling was fixed though :P

What do you mean?

[boxed]

What do you mean?

I mean that you've made a significant performance improvement, it's just overshadowed by one much larger. So please merge your change even if it doesn't fix my problem!

[blueyed]

I see. It was easy since I've thought about it before already, and have introduced it myself after all.. ;)
As for the other issue it would be good to create a new issue with more details, i.e. with information about the actual callers.

[boxed]

I'll look into creating an example project with the performance issues tomorrow at work. It's probably just to create lots of files and directories that are irrelevant I think.

What's the deal with the "marked as off topic" stuff btw? This issue was about performance issues generally and I gave a pretty clear example of a huge performance issue. I don't see how I could be more on topic than that ^_-

[blueyed]

Cool, looking forward to this.

Re offtopic: this issue appears to be investigating performance altogether / in general, so your issue is not really offtopic, but should be a separate issue - my intention was to keep this issue here easier to read / skim in the future.