long MODULEPATH drastically reduces performance

[pescobar]

I did this test with latest EasyBuld 3.2.1 and Lmod-7.4.5 in a Centos7.3 machine:

With a long $MODULEPATH the execution time is quite long:

$> echo $MODULEPATH
/scicore/soft/modules/base:/scicore/soft/modules/bio:/scicore/soft/modules/cae:/scicore/soft/modules/chem:/scicore/soft/modules/compiler:/scicore/soft/modules/data:/scicore/soft/modules/debugger:/scicore/soft/modules/devel:/scicore/soft/modules/geo:/scicore/soft/modules/ide:/scicore/soft/modules/lang:/scicore/soft/modules/lib:/scicore/soft/modules/math:/scicore/soft/modules/mpi:/scicore/soft/modules/numlib:/scicore/soft/modules/perf:/scicore/soft/modules/phys:/scicore/soft/modules/system:/scicore/soft/modules/toolchain:/scicore/soft/modules/tools:/scicore/soft/modules/vis

$> time eb foss-2016a.eb -r -D
real	0m57.002s
user	0m36.900s
sys	0m8.828s

If I just reduce the $MODULEPATH length the execution time is much better:

$> export MODULEPATH=/scicore/soft/modules/all

$> time eb foss-2016a.eb -r -D
real	0m8.054s
user	0m4.925s
sys	0m1.361s

I don't know if this is the root cause but It seem that when MODULEPATH is so long EasyBuild is executing Lmod many more times:

$ echo $MODULEPATH 
/scicore/soft/modules/base:/scicore/soft/modules/bio:/scicore/soft/modules/cae:/scicore/soft/modules/chem:/scicore/soft/modules/compiler:/scicore/soft/modules/data:/scicore/soft/modules/debugger:/scicore/soft/modules/devel:/scicore/soft/modules/geo:/scicore/soft/modules/ide:/scicore/soft/modules/lang:/scicore/soft/modules/lib:/scicore/soft/modules/math:/scicore/soft/modules/mpi:/scicore/soft/modules/numlib:/scicore/soft/modules/perf:/scicore/soft/modules/phys:/scicore/soft/modules/system:/scicore/soft/modules/toolchain:/scicore/soft/modules/tools:/scicore/soft/modules/vis

$> time strace -f -o /tmp/eb-strace.log eb foss-2016a.eb -r -D

$> which lmod
/export/soft/lua_lmod/centos7/lmod/lmod/libexec/lmod

$> grep /export/soft/lua_lmod/centos7/lmod/lmod/libexec/lmod /tmp/eb-strace.log | wc -l
948

$> export MODULEPATH=/scicore/soft/modules/all

$> time strace -f -o /tmp/eb-strace2.log eb foss-2016a.eb -r -D

$> which lmod
/export/soft/lua_lmod/centos7/lmod/lmod/libexec/lmod

$ grep /export/soft/lua_lmod/centos7/lmod/lmod/libexec/lmod /tmp/eb-strace2.log | wc -l
272

[pescobar]

To make this issue more weird, if I try the same using EB-3.2.1 in Centos6 machine with Lmod-6.0.9 the long $MODULEPATH doesn't seem to be a problem:

echo $MODULEPATH 
/scicore/soft/modules/base:/scicore/soft/modules/bio:/scicore/soft/modules/chem:/scicore/soft/modules/compiler:/scicore/soft/modules/data:/scicore/soft/modules/devel:/scicore/soft/modules/lang:/scicore/soft/modules/lib:/scicore/soft/modules/math:/scicore/soft/modules/mpi:/scicore/soft/modules/numlib:/scicore/soft/modules/perf:/scicore/soft/modules/phys:/scicore/soft/modules/system:/scicore/soft/modules/toolchain:/scicore/soft/modules/tools:/scicore/soft/modules/vis

$ time eb foss-2016a.eb -r -D
real	0m4.169s
user	0m2.980s
sys	0m0.728s

[boegel]

@pescobar That could be because of internal changes to Lmod...

A long $MODULEPATH is currently going to make EB run a lot of module use commands, which may be handled very differently by Lmod 6 & Lmod 7. Thoughts @rtmclay?

[rtmclay]

I have a few ideas but I can't really say without more data. Try timing a module avail and a module load (without the spider cache) for both a long MODULEPATH and a short one. For the test to be fair, it would be nice if the total number of modules was the same.

Also please do the same thing for Lmod 6.

[pescobar]

I think I located the issue. I did this other test in the Centos6-Lmod6.9 environment and I got totally puzzled because I was getting the same bad runtime and the difference in $MODULEPATH was 17 folders vs 21 folders:

$ echo $MODULEPATH
/scicore/soft/modules/base:/scicore/soft/modules/bio:/scicore/soft/modules/chem:/scicore/soft/modules/compiler:/scicore/soft/modules/data:/scicore/soft/modules/devel:/scicore/soft/modules/lang:/scicore/soft/modules/lib:/scicore/soft/modules/math:/scicore/soft/modules/mpi:/scicore/soft/modules/numlib:/scicore/soft/modules/perf:/scicore/soft/modules/phys:/scicore/soft/modules/system:/scicore/soft/modules/toolchain:/scicore/soft/modules/tools:/scicore/soft/modules/vis

[easybuild@login10 ~]$ time eb foss-2016a.eb -r -D
real	0m4.293s
user	0m2.958s
sys	0m0.809s

export MODULEPATH=/scicore/soft/modules/base:/scicore/soft/modules/bio:/scicore/soft/modules/cae:/scicore/soft/modules/chem:/scicore/soft/modules/compiler:/scicore/soft/modules/data:/scicore/soft/modules/debugger:/scicore/soft/modules/devel:/scicore/soft/modules/geo:/scicore/soft/modules/ide:/scicore/soft/modules/lang:/scicore/soft/modules/lib:/scicore/soft/modules/math:/scicore/soft/modules/mpi:/scicore/soft/modules/numlib:/scicore/soft/modules/perf:/scicore/soft/modules/phys:/scicore/soft/modules/system:/scicore/soft/modules/toolchain:/scicore/soft/modules/tools:/scicore/soft/modules/vis

$> time eb foss-2016a.eb -r -D
real	1m4.156s
user	0m40.182s
sys	0m10.166s

Then I realized that my $MODULEPATH in Centos7 contains non existing folders like /scicore/soft/modules/cae .When I configured Lmod in centos7 I added all the EasyBuild's moduleclasses to the $MODULEPATH so in case I add extra modules to those folders in the future the $MODULEPATH wouldn't need any update but it seems that this is affecting EasyBuild's or Lmod's performance.

After removing non existing folders from MODULEPATH the performance seems to be much better but I couldn't figure out how the non-existing folders are affecting to the performance

Thanks @boegel and @rtmclay for your help and suggestions!

[wpoely86]

I'm have 10 directories in $MODULEPATH and I count 154 calls to ml use. This makes it all very slow.

[boegel]

module use supports multiple arguments, that would be an easy way to fix this...