prepend_module_path is very slow

[Micket]

One a system with HMNS and quite a few modules installed. Most commands take 2-5 minutes to get going due to it. Pretty rough.

python -O -m cProfile -s cumtime /path/to/main.py foss-2019b -Dr output below

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.007    0.007  105.525  105.525 main.py:37(<module>)
        1    0.000    0.000  104.931  104.931 main.py:182(main)
      158    0.078    0.000   97.561    0.617 modules.py:705(run_module)
      164    0.002    0.000   96.834    0.590 subprocess.py:448(communicate)
      162    0.003    0.000   96.831    0.598 subprocess.py:1093(_communicate)
      162    0.013    0.000   96.822    0.598 subprocess.py:1126(_communicate_with_poll)
     2336   96.795    0.041   96.795    0.041 {built-in method poll}
       71    0.001    0.000   89.467    1.260 modules.py:1481(modules_tool)
       71    0.002    0.000   89.462    1.260 modules.py:1209(__init__)
       71    0.003    0.000   89.421    1.259 modules.py:153(__init__)
       71    0.002    0.000   89.329    1.258 modules.py:402(check_module_path)
      213    0.003    0.000   89.302    0.419 modules.py:1323(prepend_module_path)
      143    0.007    0.000   89.261    0.624 modules.py:1308(use)
 1279/894    0.012    0.000   88.251    0.099 easyconfig.py:1741(process_easyconfig)
    70/27    0.012    0.000   88.116    3.264 easyconfig.py:386(__init__)
        1    0.000    0.000   54.947   54.947 tools.py:369(parse_easyconfigs)
1326/1035    0.009    0.000   54.366    0.053 easyconfig.py:2259(_det_module_name_with)
    70/27    0.018    0.000   53.921    1.997 easyconfig.py:582(parse)
1399/1062    0.016    0.000   53.853    0.051 easyconfig.py:2228(check_ec_type)
    70/27    0.004    0.000   53.783    1.992 easyconfig.py:1352(_finalize_dependencies)
   196/73    0.003    0.000   53.699    0.736 easyconfig.py:2330(det_short_module_name)
        1    0.000    0.000   42.094   42.094 robot.py:230(dry_run)
        1    0.006    0.006   34.607   34.607 robot.py:326(resolve_dependencies)
    68/35    0.001    0.000   31.689    0.905 easyconfig.py:1933(robot_find_subtoolchain_for_dep)
1130/1043    0.017    0.000   24.467    0.023 easyconfig.py:2301(det_full_module_name)
    68/63    0.001    0.000    9.114    0.145 easyconfig.py:196(cache_aware_func)
        3    0.000    0.000    9.114    3.038 easyconfig.py:253(get_toolchain_hierarchy)

[Micket]

Caching the many repeated module use commands should speed this up a lot.

[boegel]

I'd like to get some input from @rtmclay on this one..

Which environment variables should be part of the cache key?

Obviously $MODULEPATH, but we probably also need to only cache when there are no modules loaded ($LOADEDMODULES), since running module use makes Lmod re-scan $MODULEPATH and check whether any of the loaded modules shoulc be reloaded.

We don't want to include the list of existing module flies in the cache key (too expensive), so we should only use the cache if no modules are loaded (since then there's no Lmod magic going on w.r.t. reloading already loaded modules)

[akesandgren]

@Micket asked me for the data, 2042 .lua files under modules/all/*
EB 4.0.1, Lmod 7.8.20, HMNS
Running:

python -O -m cProfile -s cumtime /hpc2n/eb/software/Core/EasyBuild/4.0.1/lib/python2.7/site-packages/easybuild/main.py /hpc2n/eb/software/Core/EasyBuild/4.0.1/easybuild/easyconfigs/f/foss/foss-2019b.eb -Dr

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.010    0.010   19.937   19.937 main.py:37(<module>)
        1    0.001    0.001   19.402   19.402 main.py:182(main)
        1    0.000    0.000   10.614   10.614 robot.py:230(dry_run)
        1    0.010    0.010   10.590   10.590 robot.py:326(resolve_dependencies)
1625/1277    0.024    0.000   10.450    0.008 easyconfig.py:2266(_det_module_nam
e_with)
1571/1100    0.022    0.000    9.559    0.009 easyconfig.py:1748(process_easycon
fig)
    36683    0.178    0.000    9.308    0.000 __init__.py:1267(_log)
    34492    0.177    0.000    8.949    0.000 __init__.py:1145(debug)
1395/1282    0.042    0.000    8.607    0.007 easyconfig.py:2308(det_full_module
_name)
    78/31    0.012    0.000    8.437    0.272 easyconfig.py:386(__init__)
1706/1308    0.051    0.000    7.155    0.005 easyconfig.py:2235(check_ec_type)
    36683    0.097    0.000    7.127    0.000 __init__.py:1288(handle)
    78/31    0.025    0.000    7.062    0.228 easyconfig.py:589(parse)
    36683    0.223    0.000    6.998    0.000 __init__.py:1320(callHandlers)
    73290    0.267    0.000    6.776    0.000 __init__.py:746(handle)
    78/31    0.006    0.000    6.109    0.197 easyconfig.py:1359(_finalize_depen
dencies)
    73290    0.229    0.000    5.849    0.000 handlers.py:68(emit)
    73290    0.149    0.000    5.560    0.000 __init__.py:948(emit)
   230/88    0.006    0.000    5.536    0.063 easyconfig.py:2337(det_short_modul
e_name)
        1    0.000    0.000    5.480    5.480 tools.py:391(parse_easyconfigs)
    73290    0.371    0.000    5.411    0.000 __init__.py:849(emit)
       30    0.016    0.001    5.298    0.177 tools.py:104(find_resolved_modules)
        4    0.014    0.004    4.932    1.233 modules.py:705(run_module)
        5    0.000    0.000    4.892    0.978 subprocess.py:769(communicate)
        4    0.000    0.000    4.873    1.218 subprocess.py:1408(_communicate)
        4    0.000    0.000    4.873    1.218 subprocess.py:1441(_communicate_with_poll)

[boegel]

@akesandgren Which command did you run here? Is this with a module hierarchy?

Interestingly, prepend_module_path isn't even listed there, at least not at the top of the list you provided...

[akesandgren]

Added command and HMNS info above

[boegel]

@migueldiascosta I'm moving this back to the 4.1.0 milestone, I hope to fix this in time for the release...

[boegel]

@Micket For some reason, the ModulesTool instance is being created over and over again in your configuration:

       71    0.002    0.000   89.462    1.260 modules.py:1209(__init__)

Each of those triggers a check_module_path, which in turns triggers a bunch of prepend_module_path calls doing module use (to get the order in $MODULEPATH) as it should be:

       71    0.002    0.000   89.329    1.258 modules.py:402(check_module_path)
      213    0.003    0.000   89.302    0.419 modules.py:1323(prepend_module_path)
      143    0.007    0.000   89.261    0.624 modules.py:1308(use)

So, the actual question is why the ModulesTool instance is created over and over again, there's no point in doing that... It should be created exactly once, and recycled.

@Micket Can you share the output of eb --show-config?

@akesandgren Can you rerun the profile in your setup, and check how many times check_module_path is called, and also share the output of eb --show-config?

[akesandgren]

check_module_path 79 times

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.015    0.015   14.696   14.696 main.py:37(<module>)
        1    0.001    0.001   14.099   14.099 main.py:182(main)
1625/1277    0.016    0.000    8.335    0.007 easyconfig.py:2266(_det_module_name_with)
1571/1100    0.015    0.000    7.825    0.007 easyconfig.py:1748(process_easyconfig)
    78/31    0.010    0.000    6.874    0.222 easyconfig.py:386(__init__)
    36683    0.131    0.000    6.678    0.000 __init__.py:1267(_log)
1706/1308    0.032    0.000    6.574    0.005 easyconfig.py:2235(check_ec_type)
    34492    0.129    0.000    6.367    0.000 __init__.py:1145(debug)
1395/1282    0.025    0.000    6.346    0.005 easyconfig.py:2308(det_full_module_name)
        1    0.000    0.000    6.254    6.254 robot.py:230(dry_run)
        1    0.005    0.005    6.230    6.230 robot.py:326(resolve_dependencies)
    78/31    0.019    0.000    6.146    0.198 easyconfig.py:589(parse)
    78/31    0.005    0.000    5.656    0.182 easyconfig.py:1359(_finalize_dependencies)
        1    0.000    0.000    5.351    5.351 tools.py:391(parse_easyconfigs)
   230/88    0.005    0.000    5.334    0.061 easyconfig.py:2337(det_short_module_name)
    36683    0.068    0.000    5.089    0.000 __init__.py:1288(handle)
    36683    0.161    0.000    4.998    0.000 __init__.py:1320(callHandlers)
    73290    0.192    0.000    4.837    0.000 __init__.py:746(handle)
    73290    0.161    0.000    4.184    0.000 handlers.py:68(emit)
    73290    0.103    0.000    3.982    0.000 __init__.py:948(emit)
    73290    0.264    0.000    3.879    0.000 __init__.py:849(emit)
    94/48    0.003    0.000    3.487    0.073 easyconfig.py:1940(robot_find_subtoolchain_for_dep)
        4    0.007    0.002    3.310    0.828 modules.py:705(run_module)
        5    0.000    0.000    3.285    0.657 subprocess.py:769(communicate)
        4    0.000    0.000    3.276    0.819 subprocess.py:1408(_communicate)
        4    0.000    0.000    3.275    0.819 subprocess.py:1441(_communicate_with_poll)
       39    3.275    0.084    3.275    0.084 {built-in method poll}
       30    0.009    0.000    3.192    0.106 tools.py:104(find_resolved_modules)
    73290    0.083    0.000    2.596    0.000 __init__.py:723(format)
    73290    0.400    0.000    2.513    0.000 __init__.py:452(format)
       79    0.001    0.000    2.175    0.028 modules.py:1481(modules_tool)
       79    0.002    0.000    2.169    0.027 modules.py:1209(__init__)
       79    0.002    0.000    2.097    0.027 modules.py:153(__init__)
     1461    0.009    0.000    1.883    0.001 hierarchical_mns.py:127(det_module_subdir)
       79    0.002    0.000    1.843    0.023 modules.py:402(check_module_path)
     1383    0.010    0.000    1.815    0.001 hierarchical_mns.py:82(det_full_module_name)
       79    0.000    0.000    1.734    0.022 modules.py:1323(prepend_module_path)
        1    0.000    0.000    1.712    1.712 modules.py:1308(use)
     1461    0.025    0.000    1.529    0.001 toolchain.py:89(det_toolchain_compilers)
    73290    0.305    0.000    1.392    0.000 __init__.py:405(formatTime)
        2    0.002    0.001    1.391    0.696 modules.py:1257(available)
        2    0.001    0.000    1.389    0.694 modules.py:436(available)
     1571    0.027    0.000    1.353    0.001 one.py:369(retrieve_blocks_in_spec)
       78    0.001    0.000    1.222    0.016 parser.py:83(__init__)
    36683    0.140    0.000    1.213    0.000 fancylogger.py:280(makeRecord)
       78    0.001    0.000    1.201    0.015 parser.py:189(_set_formatter)
       78    0.000    0.000    1.173    0.015 one.py:124(parse)
       78    0.001    0.000    1.173    0.015 pyheaderconfigobj.py:110(parse)
       78    0.001    0.000    1.144    0.015 pyheaderconfigobj.py:140(parse_pre_section)
       78    0.029    0.000    1.122    0.014 pyheaderconfigobj.py:175(parse_pyheader)
     1674    0.384    0.000    1.075    0.001 filetools.py:183(read_file)
    36683    0.565    0.000    1.062    0.000 __init__.py:237(__init__)
7986/7900    0.007    0.000    0.997    0.000 easyconfig.py:1046(toolchain)
    73290    0.201    0.000    0.899    0.000 __init__.py:838(flush)
    78/75    0.001    0.000    0.894    0.012 easyconfig.py:706(check_deprecated)
       78    0.000    0.000    0.882    0.011 parser.py:218(get_config_dict)
       78    0.004    0.000    0.880    0.011 parser.py:120(check_values_types)
    73290    0.879    0.000    0.879    0.000 {time.localtime}
     1069    0.006    0.000    0.863    0.001 types.py:191(check_type_of_param_value)
     2446    0.084    0.000    0.764    0.000 toolchain.py:477(definition)
    94/87    0.001    0.000    0.756    0.009 easyconfig.py:196(cache_aware_func)
        3    0.001    0.000    0.738    0.246 easyconfig.py:253(get_toolchain_hierarchy)
     1691    0.655    0.000    0.655    0.000 {open}

#
# Current EasyBuild configuration
# (C: command line argument, D: default value, E: environment variable, F: configuration file)
#
buildpath                      (E) = /scratch/eb-buildpath
check-ebroot-env-vars          (F) = error
containerpath                  (F) = /hpc2n/eb/containers
debug                          (F) = True
filter-deps                    (E) = 
fixed-installdir-naming-scheme (F) = False
hooks                          (F) = /hpc2n/eb/custom/easyhooks/hpc2n_hooks.py
include-easyblocks             (F) = /hpc2n/eb/custom/easyblocks/*.py, /hpc2n/eb/custom/easyblocks/generic/*.py
installpath                    (F) = /hpc2n/eb
job-backend                    (F) = Slurm
minimal-toolchains             (F) = True
module-naming-scheme           (F) = HierarchicalMNS
packagepath                    (F) = /hpc2n/eb/packages
prefix                         (F) = /hpc2n/eb
recursive-module-unload        (F) = True
repositorypath                 (F) = /hpc2n/eb/ebfiles_repo
robot-paths                    (F) = /hpc2n/eb/custom/easyconfigs, /hpc2n/eb/software/Core/EasyBuild/4.0.1/easybuild/easyconfigs
sourcepath                     (F) = /pfs/software/open_sources:/pfs/software/hidden_sources
subdir-user-modules            (F) = Public/easybuild/modules
tmpdir                         (E) = /scratch/eb-tmpdir
verify-easyconfig-filenames    (F) = True

[boegel]

@akesandgren Is your current hpc2n_hooks.py available somewhere?