Patch 1 bottleneck

[mottosso]

In preparation for patching bottlenecks, one at a time, here is some preliminary (production) data, from 200 packages, 2,000 versions, 30 GB, over an NFS share on Windows 10.

10+ seconds spent in total for rez env.

Collecting samples from 'c:\Python27\python.exe -m rez.cli._main env ATC maya -- exit' (python v2.7.10)
Total Samples 2500
GIL: 0.00%, Active: 100.00%, Threads: 1

  %Own   %Total  OwnTime  TotalTime  Function (filename:line)
  0.00%   0.00%    4.13s     4.13s   isfile (c:\Python27\lib\genericpath.py:37)
  0.00%   0.00%    3.52s     3.52s   _load_file (rez\serialise.py:159)
  0.00%   0.00%    2.34s     2.34s   updatecache (c:\Python27\lib\linecache.py:84)
100.00% 100.00%    2.03s     2.03s   wait (c:\Python27\lib\subprocess.py:1007)
  0.00%   0.00%    2.00s     2.00s   exists (c:\Python27\lib\genericpath.py:26)
  0.00%   0.00%    1.92s     1.92s   updatecache (c:\Python27\lib\linecache.py:131)
  0.00%   0.00%    1.54s     2.01s   _get_version_dirs (C:\Users\marcus\Desktop\Rez\Rez\Lib\site-packages\rez-2.29.1-py2.7.egg\rezplugins\package_repository\filesystem.py:741)
  0.00%   0.00%    1.22s     1.22s   updatecache (c:\Python27\lib\linecache.py:132)
  0.00%   0.00%    1.01s     1.02s   _load_py (rez\serialise.py:231)
  0.00%   0.00%   0.580s    0.580s   _get_version_dirs (C:\Users\marcus\Desktop\Rez\Rez\Lib\site-packages\rez-2.29.1-py2.7.egg\rezplugins\package_repository\filesystem.py:731)
  0.00%   0.00%   0.510s     9.58s   _load_file (rez\serialise.py:160)
  0.00%   0.00%   0.180s    0.180s   _readerthread (c:\Python27\lib\subprocess.py:1013)
  0.00%   0.00%   0.170s    0.170s   _get_family (C:\Users\marcus\Desktop\Rez\Rez\Lib\site-packages\rez-2.29.1-py2.7.egg\rezplugins\package_repository\filesystem.py:780)
  0.00%   0.00%   0.130s    0.130s   generate_tokens (c:\Python27\lib\tokenize.py:367)
  0.00%   0.00%   0.050s    0.050s   _win32_getvalue (c:\Python27\lib\platform.py:543)
  0.00%   0.00%   0.040s    0.040s   generate_tokens (c:\Python27\lib\tokenize.py:373)
  0.00%   0.00%   0.040s    0.040s   dedent (c:\Python27\lib\textwrap.py:391)
  0.00%   0.00%   0.040s    0.040s   find_module (c:\Python27\lib\pkgutil.py:186)
  0.00%   0.00%   0.040s    0.040s   win32_ver (c:\Python27\lib\platform.py:582)
  0.00%   0.00%   0.030s    0.070s   <module> (rez\solver.py:15)
  0.00%   0.00%   0.030s    0.060s   <module> (c:\Python27\lib\logging\handlers.py:26)
  0.00%   0.00%   0.030s    0.200s   <module> (rez\__init__.py:2)
  0.00%   0.00%   0.030s    0.030s   _execute_child (c:\Python27\lib\subprocess.py:958)
  0.00%   0.00%   0.030s    0.070s   import_module (rez\backport\importlib.py:36)
  0.00%   0.00%   0.030s    0.030s   sub (c:\Python27\lib\re.py:155)
  0.00%   0.00%   0.030s    0.030s   __init__ (rez\vendor\version\version.py:137)
  0.00%   0.00%   0.030s    0.210s   <module> (rez\utils\_version.py:7)
  0.00%   0.00%   0.030s    0.030s   __exit__ (c:\Python27\lib\contextlib.py:24)
  0.00%   0.00%   0.020s    0.040s   <module> (rez\vendor\pyparsing\pyparsing.py:71)
  0.00%   0.00%   0.020s    0.020s   <module> (c:\Python27\lib\hashlib.py:134)
  0.00%   0.00%   0.020s    0.020s   <module> (c:\Python27\lib\shutil.py:21)
  0.00%   0.00%   0.020s    0.030s   _load_config_py (rez\config.py:795)
  0.00%   0.00%   0.020s    0.020s   <module> (c:\Python27\lib\dis.py:6)
  0.00%   0.00%   0.020s    0.030s   <module> (rez\utils\graph_utils.py:15)
  0.00%   0.00%   0.020s    0.200s   func (rez\utils\data_utils.py:462)
  0.00%   0.00%   0.020s    0.020s   _load_file (rez\serialise.py:150)

[mottosso]

cProfile and RunSnakeRun

Not particularly useful, as Rez launches an opaque subprocess taking the vast majority of time.

PySpy

220 seconds to resolve 2 requests, in a repository of 200 packages with a total of 2,000 versions, on a local SSD drive on Windows 10

$ rez env a b

Not much to see here. The subprocess is the one doing all the work.

Something interesting appears.

• 200 seconds is spread evenly across 52 modules
• With 1 notable example, pyparsing, taking up a whopping 10 seconds
• 5 modules fit in the 7-second range
  • filesystem
  • locale
  • ntpath
  • shutil
  • logging
  • With os at 6.98 seconds
• 9 modules go in the 5-second range, of interest being config and handlers both coming from the logging package.
  • formatting
  • socket
  • warnings
  • handlers
  • inspect
  • tempfile
  • config
  • collections
  • platform_
• With 35 modules sitting comfortably at roughly 2 seconds

[mottosso]

Could we leverage Python's -O flag for this?

import time

t0 = time.time()
if __debug__:
    print("Zzzzzzzzzz...")
    time.sleep(1)

print("Finished in %.2f s" % (time.time() - t0))

This script takes ~1 second to run, unless you pass -O.

$ python temp.py
Finished in 1.00 seconds
$ python -O temp.py
Finished in 0.00 seconds

Apparently, anything under if __debug__ is removed from the resulting source code prior to being run. Along with also removing assert statements. Or at the very least __debug__ is guaranteed to be available regardless of -O and set to False with -O which is the next best thing.

• https://stackoverflow.com/a/4777156/478949

My guess is that if we host calls to print and log statements during resolve under a if __debug__ we should see a significant performance improvement.

If that works, then an install could automatically yield .pyo files as opposed to .py or .pyc, and a user on an install without those could create them himself by simply passing -O to Python.