Very bad performance due to sourcing of all modules on module add about modules HOT 12 CLOSED

I will follow-up now onwards on this

from modules.

Hi @wenzler

It seems the Tcl extended library is not enabled on your setup:

tcl_ext_lib_loaded        0

Could you please redo your test with a Modules version where Tcl extended library is enabled.

This lib supersedes the open and read functions of Tcl specifically to avoid the many lstat, fnctl and ioctl calls.

It would be interested to have in your case the number of io calls (given by strace -c) with and without the Tcl extended library.

from modules.

We kept it off for portability.
Will update you on that.

Lack of tclenvmodules doesn't really explain why it has to open all neighboring files on a properly match-able single module load, though.

from modules.

Lack of tclenvmodules doesn't really explain why it has to open all neighboring files on a properly match-able single module load, though.

I would like to see if enablement of tclenvmodules helps to solve the observed slowness.

Neighboring files are analyzed to determine the properties of the loading module. Especially to determine if the @latest symbol applies to it.

Having many version files in the directory should not impact performances as there should not be too much files (>30). Things that could be done to improve the situation are:

• removing files that are not modulefiles
• using virtual modules rather than files
• using cache file

from modules.

No real change in performance - module loads take extensively long in both configs

normal build:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
67.05    0.319764        3852        83        37 wait4
11.26    0.053696          10      4889         2 lstat
  3.05    0.014548          10      1324           readlink
  2.99    0.014261           9      1470           read
  2.48    0.011810          15       779       115 openat
  1.99    0.009513          12       765       102 stat
  1.71    0.008141           8       922        14 close


lib build:

82.24    0.378750        4563        83        37 wait4
  2.70    0.012430           8      1471           read
  2.21    0.010171          13       778       115 openat
  1.81    0.008335          11       756       102 stat
  1.74    0.008034           8       921        14 close

modules531-local_build-state-add-python.strace.txt
modules531-local_build-libtclenvmodules-state-add-python.strace.txt

from modules.

Ok, so from the provided strace results, it does not seem that too much time is eaten by lstat, ioctl, fnctl, open or read.

A significant amount of time is used by wait4, which I find odd.

Could you provide the output of the module add command in verbose2 mode (-DD). It could also be interesting to run this verbose2 command with --timer option.

There are ~700 files read. It will be interesting to see what files are read within the enabled modulepaths and what are the duration of these file reads.

from modules.

Give me some more time to come back on this

from modules.

@wenzler any news?

from modules.

I still have to find the time to anonymize the debug output.

But the opening of all module files in a folder takes 1ms each - which ofc accumulates for large folders.

Thus the basic complaint remains:
why does modules have to open every appver file present in the folder
for a distinct 'module add appname/appver' call

from modules.

Thus the basic complaint remains:
why does modules have to open every appver file present in the folder
for a distinct 'module add appname/appver' call

See my earlier comment in #507 (comment): neighboring files are analyzed to determine the properties of the loading module. Especially to determine if the @latest symbol applies to it.

from modules.

Could you provide the output of the module add command in verbose2 mode (-DD). It could also be interesting to run this verbose2 command with --timer option.

There are ~700 files read. It will be interesting to see what files are read within the enabled modulepaths and what are the duration of these file reads.

@wenzler any news? debug output would be interesting to see what files are read.

Above strace's stats mention ~700 files for a module load. Cannot be sure without debugging output, but I think there are non-modulefiles stuff in modulepath directories. Moving the non-modulefiles stuff away from modulepath directory will help (or build module cache if Modules >= 5.3).

from modules.

I am closing this issue. With the element provided, module command seem to perform as expected. More modulefiles are read by newer version of Modules but it should not impact performances.

A large number of files is read here. I am lacking information but I would suggest to look at the files inside the modulepaths and remove non modulefiles.

If the filesystem where the modulefiles are located does not cope well with the load implied by module command I/O operations, suggestion is to enable the module cache.

from modules.