Analysis of slow post-build process when building compiled packages on MacOS

[rlizzo]

@msarahan, With the introduction of the check-overlinking features in conda-build 3.3.0, the post-build process on MacOS took a severe performance hit. For the library I maintain, it adds 10+ minutes to the build process. I have profiled conda-build as it builds a small part of the package, and have found that there are two main functions which are resulting in 99% of the slowdown.

I am more than happy to make the appropriate changes to try and speed up code, but before starting work I wanted to reach out and get your input on what the best approach / potential challeges might be?

Function 1

In the function _find_needed_dso_in_system, line 479 in post.py:

sysroot_files.extend(glob(os.path.join(sysroot, '**', dso_fname)))

takes up 99% of the execution time

Function 2

In the function _find_needed_dso_in_prefix, line 436 in post.py

pkgs = list(which_package(in_prefix_dso, m.config.host_prefix))

takes up 96.7% of the execution time

Full Profile

Total time: 160.224 s
File: /Users/rick/projects/conda-build/conda_build/post.py
Function: post_build at line 583

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   583                                           @do_profile(follow=[check_overlinking])
   584                                           def post_build(m, files, build_python):
   585         1           24     24.0      0.0      print('number of files:', len(files))
   586         1       169002 169002.0      0.1      fix_permissions(files, m.config.host_prefix)
   587
   588       597          618      1.0      0.0      for f in files:
   589       596        45738     76.7      0.0          make_hardlink_copy(f, m.config.host_prefix)
   590
   591         1            1      1.0      0.0      if sys.platform == 'win32':
   592                                                   return
   593
   594         1           48     48.0      0.0      binary_relocation = m.binary_relocation()
   595         1            1      1.0      0.0      if not binary_relocation:
   596                                                   print("Skipping binary relocation logic")
   597         1            8      8.0      0.0      osx_is_app = bool(m.get_value('build/osx_is_app', False)) and sys.platform == 'darwin'
   598
   599         1        10468  10468.0      0.0      check_symlinks(files, m.config.host_prefix, m.config.croot)
   600         1       695455 695455.0      0.4      prefix_files = utils.prefix_files(m.config.host_prefix)
   601
   602       597         3582      6.0      0.0      for f in files:
   603       596         1162      1.9      0.0          if f.startswith('bin/'):
   604       174        11134     64.0      0.0              fix_shebang(f, prefix=m.config.host_prefix, build_python=build_python,
   605       174      1300494   7474.1      0.8                          osx_is_app=osx_is_app)
   606       596         1012      1.7      0.0          if binary_relocation is True or (isinstance(binary_relocation, list) and
   607                                                                                    f in binary_relocation):
   608       596      1820404   3054.4      1.1              post_process_shared_lib(m, f, prefix_files)
   609         1    156165036 156165036.0     97.5      check_overlinking(m, files)

Total time: 156.163 s
File: /Users/rick/projects/conda-build/conda_build/post.py
Function: check_overlinking at line 530

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   530                                           def check_overlinking(m, files):
   531         1            1      1.0      0.0      errors = []
   532         1           66     66.0      0.0      pkg_name = m.get_value('package/name')
   533
   534         1           64     64.0      0.0      run_reqs = [req.split(' ')[0] for req in m.meta.get('requirements', {}).get('run', [])]
   535         1           70     70.0      0.0      host_reqs = [req.split(' ')[0] for req in m.meta.get('requirements', {}).get('host', [])]
   536         1      1381061 1381061.0      0.9      sysroots = glob(os.path.join(m.config.build_prefix, '**', 'sysroot'))
   537         1            3      3.0      0.0      if not len(sysroots):
   538         1           12     12.0      0.0          if m.config.variant.get('target_platform') == 'osx-64':
   539         1            5      5.0      0.0              sysroots = ['/usr/lib', '/opt/X11', '/System/Library/Frameworks']
   540
   541       597         1475      2.5      0.0      for f in files:
   542       596        25043     42.0      0.0          path = os.path.join(m.config.host_prefix, f)
   543       596        68029    114.1      0.0          if not is_obj(path):
   544       569          602      1.1      0.0              continue
   545        27    154686242 5729120.1     99.1          _inspect_file_linking(m, path, files, errors, pkg_name, run_reqs, host_reqs, sysroots)
   546        27           72      2.7      0.0          if len(errors):
   547                                                       sys.exit(1)

Total time: 17.8182 s
File: /Users/rick/projects/conda-build/conda_build/post.py
Function: _inspect_file_linking at line 509

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   509                                           @do_profile(follow=[_find_needed_dso_in_prefix, _find_needed_dso_in_system])
   510                                           def _inspect_file_linking(m, path, files, errors, pkg_name, run_reqs, host_reqs, sysroots):
   511         1            6      6.0      0.0      f = os.path.basename(path)
   512         1            3      3.0      0.0      warn_prelude = "WARNING ({},{})".format(pkg_name, f)
   513         1            1      1.0      0.0      err_prelude = "  ERROR ({},{})".format(pkg_name, f)
   514         1            1      1.0      0.0      info_prelude = "   INFO ({},{})".format(pkg_name, f)
   515         1            1      1.0      0.0      msg_prelude = err_prelude if m.config.error_overlinking else warn_prelude
   516
   517         1         5202   5202.0      0.0      needed = inspect_linkages(path, resolve_filenames=True, recurse=False)
   518        89           93      1.0      0.0      for needed_dso in needed:
   519        88         4042     45.9      0.0          if needed_dso.startswith(m.config.host_prefix):
   520        84           55      0.7      0.0              _find_needed_dso_in_prefix(m, needed_dso, f, files, errors, run_reqs, host_reqs,
   521        84       360131   4287.3      2.0                                         msg_prelude, info_prelude)
   522         4           38      9.5      0.0          elif needed_dso.startswith(m.config.build_prefix):
   523                                                       print_msg(errors, "ERROR: {} found in build prefix; should never happen".format(
   524                                                           needed_dso))
   525                                                   else:
   526         4            3      0.8      0.0              _find_needed_dso_in_system(m, needed_dso, errors, sysroots, msg_prelude, info_prelude,
   527         4     17448630 4362157.5     97.9                                         warn_prelude)

Total time: 0.359184 s
File: /Users/rick/projects/conda-build/conda_build/post.py
Function: _find_needed_dso_in_prefix at line 431

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   431                                           def _find_needed_dso_in_prefix(m, needed_dso, f, files, errors, run_reqs, host_reqs,
   432                                                                          msg_prelude, info_prelude):
   433        84         6084     72.4      1.7      in_prefix_dso = os.path.normpath(needed_dso.replace(m.config.host_prefix + '/', ''))
   434        84          170      2.0      0.0      n_dso_p = "Needed DSO {} in {}".format(in_prefix_dso, f)
   435        84         2179     25.9      0.6      and_also = " (and also in this package)" if in_prefix_dso in files else ""
   436        84       347486   4136.7     96.7      pkgs = list(which_package(in_prefix_dso, m.config.host_prefix))
   437        84          145      1.7      0.0      if len(pkgs) == 1:
   438        83          703      8.5      0.2          if pkgs[0].quad[0] not in run_reqs:
   439                                                       print_msg(errors, '{}: {} found in {}{}'.format(msg_prelude,
   440                                                                                                       n_dso_p,
   441                                                                                                       pkgs[0],
   442                                                                                                       and_also))
   443                                                       print_msg(errors, '{}: .. but {} not in reqs/run, i.e. it is overlinked'
   444                                                                           ' (likely) or a missing dependency (less likely)'.
   445                                                                           format(msg_prelude, pkgs[0].quad[0]))
   446        83          102      1.2      0.0          elif m.config.verbose:
   447        83           79      1.0      0.0              print_msg(errors, '{}: {} found in {}{}'.format(info_prelude,
   448        83           39      0.5      0.0                                                              n_dso_p,
   449        83           41      0.5      0.0                                                              pkgs[0],
   450        83         2123     25.6      0.6                                                              and_also))
   451         1            0      0.0      0.0      elif len(pkgs) > 1:
   452                                                   print_msg(errors, '{}: {} found in multiple packages:{}'.format(msg_prelude,
   453                                                                                                                   in_prefix_dso,
   454                                                                                                                   and_also))
   455                                                   for pkg in pkgs:
   456                                                       print_msg(errors, '{}: {}'.format(msg_prelude, pkg))
   457                                                       if pkg.dist_name not in host_reqs:
   458                                                           print_msg(errors, '{}: .. but {} not in reqs/host (is transitive)'.
   459                                                           format(msg_prelude, pkg.dist_name))
   460                                               else:
   461         1           15     15.0      0.0          if in_prefix_dso not in files:
   462                                                       print_msg(errors, '{}: {} not found in any packages'.format(msg_prelude,
   463                                                                                                                   in_prefix_dso))
   464         1            1      1.0      0.0          elif m.config.verbose:
   465         1            1      1.0      0.0              print_msg(errors, '{}: {} found in this package'.format(info_prelude,
   466         1           16     16.0      0.0                                                                      in_prefix_dso))

Total time: 4.72283 s
File: /Users/rick/projects/conda-build/conda_build/post.py
Function: _find_needed_dso_in_system at line 468

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   468                                           @do_profile(follow=[])
   469                                           def _find_needed_dso_in_system(m, needed_dso, errors, sysroots, msg_prelude,
   470                                                                          info_prelude, warn_prelude):
   471                                               # A system dependency then. We should be able to find it in one of the CDT o
   472                                               # compiler packages on linux or at in a sysroot folder on other OSes.
   473                                               #
   474         1            2      2.0      0.0      if m.config.verbose and len(sysroots):
   475                                                   # Check id we have a CDT package.
   476         1            3      3.0      0.0          dso_fname = os.path.basename(needed_dso)
   477         1            0      0.0      0.0          sysroot_files = []
   478         4            6      1.5      0.0          for sysroot in sysroots:
   479         3      4717905 1572635.0     99.9              sysroot_files.extend(glob(os.path.join(sysroot, '**', dso_fname)))
   480         1            1      1.0      0.0          if len(sysroot_files):
   481                                                       # Removing config.build_prefix is only *really* for Linux, though we could
   482                                                       # use CONDA_BUILD_SYSROOT for macOS. We should figure out what to do about
   483                                                       # /opt/X11 too.
   484         1            1      1.0      0.0              in_prefix_dso = os.path.normpath(sysroot_files[0].replace(
   485         1           32     32.0      0.0                  m.config.build_prefix + '/', ''))
   486         1            2      2.0      0.0              n_dso_p = "Needed DSO {}".format(in_prefix_dso)
   487         1         4851   4851.0      0.1              pkgs = list(which_package(in_prefix_dso, m.config.build_prefix))
   488         1            2      2.0      0.0              if len(pkgs):
   489                                                           print_msg(errors, '{}: {} found in CDT/compiler package {}'.
   490                                                                               format(info_prelude, n_dso_p, pkgs[0]))
   491                                                       else:
   492         1            1      1.0      0.0                  print_msg(errors, '{}: {} not found in any CDT/compiler package?!'.
   493         1           23     23.0      0.0                                      format(info_prelude, n_dso_p))
   494                                                   else:
   495                                                       prelude = warn_prelude if needed_dso.startswith('$RPATH') else msg_prelude
   496                                                       print_msg(errors, "{}: {} not found in sysroot, is this binary repackaging?"
   497                                                                           " .. do you need to use install_name_tool/patchelf?".
   498                                                                           format(prelude, needed_dso))
   499                                               else:
   500                                                   # When a needed_dso begins with $RPATH it means we are making a CDT package
   501                                                   # (in any other case this would be a problem), but I should verify it is ok
   502                                                   # for CDT packages too.
   503                                                   if needed_dso.startswith('$RPATH'):
   504                                                       print_msg(errors, "{}: {} returned by pyldd. A CDT package?".
   505                                                                           format(warn_prelude, needed_dso))
   506                                                   else:
   507                                                       print_msg(errors, "{}: did not find - or even know where to look for: {}".
   508                                                                           format(msg_prelude, needed_dso))

[msarahan]

Rick, you are my favorite profiler person ever. Thanks for investigating this. I'm tied up tonight but will get back to you asap tomorrow.

[rlizzo]

Thanks Mike! looking forward to hearing your thoughts!

[msarahan]

That definitely seems like some caching is in order.

The primary thing to be careful about is that you cannot cache based purely on the prefix, because with multiple outputs you can have the build or host prefix be the same path, but have different contents within a single run through conda-build. However, because this is sysroot, and not arbitrary prefixes, caching should be safe - it'll be searching the same files over and over.

As a first try, I'd memoize

def _find_needed_dso_in_system(m, needed_dso, errors, sysroots, msg_prelude,
   470                                                                          info_prelude, warn_prelude):

Unfortunately, because not all arguments there are hashable (especially not m), you won't be able to simply use the decorator. You'll need to refactor it so that the function doing the actual work is memoizable (i.e. all arguments are hashable).

Thanks again for looking into this. No rush - if you can't get to it, please let me know and I'll try to find time soon.

[rlizzo]

Thanks for the insight! I won't have time to dig into this till early next week, but I will definitely provide an update soon!

[mingwandroid]

I'd caution against looking into this. I wrote the code but my version is now significantly diverged (many bug fixes and a whitelist feature) from the master branch and released code (due to time pressure on other tasks).

I will fix it via caching next week if you can wait, otherwise, please submit any PR to my conda-build master branch instead.

[rlizzo]

Thanks for the heads up @mingwandroid!

it's not a work-stoping concern for me right now, so I'll wait until your updates get merged into the main conda-build repo and will reprofile and update here if there are any resulting side effects. Feel free to let me know if there's anything I can do to ease a bit of the time crunch for you!

[rlizzo]

Just wanted to close out this issue since it was fixed in recent versions of conda build. I haven't done a full profile since it doesn't seem necessary, but in a quick test the post-build time has dropped from over 10 minutes to about 20 seconds. thanks for all the hard work @msarahan and @mingwandroid!

[mingwandroid]

Thanks but we didn't do anything to speed it up.. well nothing deliberate anyway. The code changed a bit but not on a way that should make it much faster.

Oh well. Thanks for letting us know.

[epruesse]

@mingwandroid Not sure if it's exactly this issue, but I'm still seeing a lot of time spent in the stage where/when those warnings pop up (not if they don't).

[mingwandroid]

The warnings need to be fixed (I recommend passing -error-overlinking to conda-build).

I'm surprised you see a difference between warning and no-warning. I suspect this is between two different packages so not something that can be easily investigated.

I build many big packages and the speed of the current implementation is "OK" I feel, scaling with the package size and number of C/C++ dependencies. Sure it'd be nice if it were a little faster but I won't be spending time on that soon, unless you can provide useful, clearly bad figures to back up "a lot of time".

I suspect, for example, switching from ld to gold would save a lot more time.

[epruesse]

@mingwandroid It's this one: arb-bio

After creating the various outputs:, the pyldd started taking a lot of time. By "a lot" I mean maybe 10 minutes total, so mostly just annoying.

Thanks for mentioning that it can be turned off! Should have checked that myself. I'm happy with that option as a fix.

(I'm just not really sure how to fix those itchy warnings...)

[mingwandroid]

They really must be fixed.

[github-actions[bot]]

Hi there, thank you for your contribution!

This issue has been automatically locked because it has not had recent activity after being closed.

Please open a new issue if needed.

Thanks!