Test suite run over all tests takes long due to loading of ReFrame environments

[casparvl]

It takes a few minutes now to even list the tests for all tests in the test suite. Looking at the logs, I noticed the following:

[2026-07-10T14:03:42] debug: reframe: Validating '/home/casparvl/rfm.GkAMf7TaDb/test-suite/eessi/testsuite/tests/apps/walberla/__init__.py': not a test file
[2026-07-10T14:03:42] debug: reframe: Validating '/home/casparvl/rfm.GkAMf7TaDb/test-suite/eessi/testsuite/tests/apps/walberla/walberla.py': OK
[2026-07-10T14:03:42] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:42] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:42] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:42] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:42] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:43] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:43] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:43] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:43] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:44] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:44] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:44] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:44] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:44] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:44] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:44] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:45] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:45] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:45] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:45] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:46] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:46] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:46] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:46] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:46] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:47] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:47] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:47] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:47] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:47] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:47] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:47] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:48] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:48] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:48] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:48] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:49] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:49] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:49] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:49] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:49] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:50] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:50] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:50] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:50] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06'
[2026-07-10T14:03:50] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2022b with regex waLBerla
[2026-07-10T14:03:50] debug: reframe: [find_modules]: Matched module waLBerla/6.1-foss-2023a with regex waLBerla
[2026-07-10T14:03:50] debug: reframe: [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2025.06'
[2026-07-10T14:03:51] verbose: reframe: Scales supported by EESSI_WALBERLA_BACKWARD_FACING_STEP: ('8_cores', '1_8_node', '1_4_node', '1_2_node', '1_node', '2_nodes')
[2026-07-10T14:03:51] debug: reframe: [filter_supported_scales]: valid_systems set to ['+8_cores']
[2026-07-10T14:03:51] debug: reframe: [set_module_names]: module_names set to ['waLBerla/6.1-foss-2022b']
[2026-07-10T14:03:51] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+8_cores +cpu'] for device type cpu
[2026-07-10T14:03:51] debug: reframe: [set_tag_scale]: tags set to {'8_cores'}
[2026-07-10T14:03:51] debug: reframe: [filter_supported_scales]: valid_systems set to ['+8_cores']
[2026-07-10T14:03:51] debug: reframe: [set_module_names]: module_names set to ['waLBerla/6.1-foss-2023a']
[2026-07-10T14:03:51] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+8_cores +cpu'] for device type cpu
[2026-07-10T14:03:51] debug: reframe: [set_tag_scale]: tags set to {'8_cores'}
...
[2026-07-10T14:03:52] debug: reframe: [set_module_names]: module_names set to ['waLBerla/6.1-foss-2023a']
[2026-07-10T14:03:52] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+2_nodes +cpu'] for device type cpu
[2026-07-10T14:03:52] debug: reframe: [set_tag_scale]: tags set to {'2_nodes'}
[2026-07-10T14:03:52] debug: reframe:   > Loaded 144 test(s)

In other words, just for waLBerla, it takes 10 seconds. Out of those 10 seconds, 8 seconds seem to be spent in find_modules, specifically (I think) in running [CMD] '/cvmfs/software.eessi.io/versions/2025.06/compat/linux/aarch64/usr/share/Lmod/libexec/lmod python load EESSI/2023.06' and similar. This command is executed 12 times, probably once per partition listed for this system.

I'm wondering if we can still optimize on this and make sure this doesn't happen.

Another thing to note is that even after that, it takes 2 more seconds to instantiate the 144 test instances (and some tests have way more instances, e.g. 1008 for MetalWalls, taking a whopping 10 seconds). OSU has over 5000 instances and takes a whopping minute to instantiate. I'm not sure if there is anything we can optimize here, maybe we can make sure that instantiation is skipped earlier in the pipeline for some very simple cases...

One potential point for improvement is that if someone asks -t 1_node that not all the scales are generated first... Another idea - although I know we've had issues with these in the past combined with EESSI_Mixin - is that we could make a hierarchy using fixtures. If the base class only does the scaling, and then already eliminates all but the 1_node scale before any of the more complex/heavy instantiation happens, that might save substantial time.

[casparvl]

At

test-suite/eessi/testsuite/utils.py

Line 177 in b29d3cf

rt.loadenv(part.local_env, env)

we have this code section

    for part in current_system.partitions:
        if part.fullname not in _modules_cache:
            _modules_cache[part.fullname] = {}
        for env in part.environs:
            rt.loadenv(part.local_env, env)
            if env.name not in _modules_cache[part.fullname]:
                log(f'Getting available modules for ({part.fullname}, {env.name})')
                available_modules = sorted(ms.available_modules())
                _modules_cache[part.fullname][env.name] = [mod for mod in available_modules if not mod.endswith('/')]
            snap0.restore()
            seen = set()
            dupes = []
            for mod in _modules_cache[part.fullname][env.name]:

Why is the rt.loadenv(part.local_env, env) outside of the if-block there? Don't we only need to load the environment if env.name is NOT in he cache yet? It also saves us the snap0.restore() I suppose.

[casparvl]

A bit more fine-grained log, and with https://github.com/EESSI/test-suite/pull/345/changes shows

[2026-07-10T14:49:23.521373] debug: reframe: Looking for tests in '/home/casparvl/EESSI/test-suite/eessi/testsuite/tests/apps/MetalWalls.py'
[2026-07-10T14:49:23.523909] debug: reframe: Validating '/home/casparvl/EESSI/test-suite/eessi/testsuite/tests/apps/MetalWalls.py': OK
[2026-07-10T14:49:23.538514] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.541303] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.543969] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.553262] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.555945] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.558666] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.561254] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.563845] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.566449] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.569032] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.571594] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.574166] debug: reframe: [find_modules]: Matched module MetalWalls/21.06.1-foss-2023a with regex MetalWalls
[2026-07-10T14:49:23.590061] debug: reframe: [filter_supported_scales]: valid_systems set to ['+1_core']
[2026-07-10T14:49:23.591369] debug: reframe: [set_module_names]: module_names set to ['MetalWalls/21.06.1-foss-2023a']
[2026-07-10T14:49:23.592558] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+1_core +cpu'] for device type cpu
[2026-07-10T14:49:23.593881] debug: reframe: [set_tag_scale]: tags set to {'sciapp', 'chemistry', '1_core'}
[2026-07-10T14:49:23.594925] debug: reframe: [EESSI_mixin_set_tag_ci]: tags set to {'sciapp', 'chemistry', '1_core', 'CI'}
[2026-07-10T14:49:23.599995] debug: reframe: [filter_supported_scales]: valid_systems set to ['+1_core']
[2026-07-10T14:49:23.601113] debug: reframe: [set_module_names]: module_names set to ['MetalWalls/21.06.1-foss-2023a']
[2026-07-10T14:49:23.602079] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+1_core +cpu'] for device type cpu
[2026-07-10T14:49:23.603261] debug: reframe: [set_tag_scale]: tags set to {'sciapp', 'chemistry', '1_core'}
[2026-07-10T14:49:23.604376] debug: reframe: [EESSI_mixin_set_tag_ci]: tags set to {'sciapp', 'chemistry', '1_core', 'CI'}

Great, no longer loading the programming environments every time when they are already cached. We also see better how long it takes to generate a single test instance: about 10ms. About 5ms happens after EESSI_mixin_set_tag_ci.

[casparvl]

Hm, there are many instances for which EESSI_mixin_set_tag_ci doesn't get executed. Maybe those are the ones that are filtered?

[2026-07-10T14:49:25.251485] debug: reframe: [filter_supported_scales]: valid_systems set to ['+1_core']
[2026-07-10T14:49:25.252656] debug: reframe: [set_module_names]: module_names set to ['MetalWalls/21.06.1-foss-2023a']
[2026-07-10T14:49:25.253675] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+1_core +cpu'] for device type cpu
[2026-07-10T14:49:25.254869] debug: reframe: [set_tag_scale]: tags set to {'sciapp', 'chemistry', '1_core'}
[2026-07-10T14:49:25.260198] debug: reframe: [filter_supported_scales]: valid_systems set to ['+1_core']
[2026-07-10T14:49:25.261409] debug: reframe: [set_module_names]: module_names set to ['MetalWalls/21.06.1-foss-2023a']
[2026-07-10T14:49:25.262551] debug: reframe: [filter_valid_systems_by_device_type]: valid_systems set to ['+1_core +cpu'] for device type cpu
[2026-07-10T14:49:25.263828] debug: reframe: [set_tag_scale]: tags set to {'sciapp', 'chemistry', '1_core'}

[casparvl]

Ah, no, those are the tests not marekd with the CI tag, of course :) The time it takes per instance is still the same, about 10ms.

[casparvl]

Ah, I might misinterpret things: that 5ms may not so muhc happen after EESSI_mixin_set_tag_ci, but more before filter_supported_scales.

[casparvl]

We should really profile the init phase (and post-init phase) I guess. Since this happens before the tests are filtered, it takes a lot of time.

Note that I also see:

[2026-07-10T15:17:38.618857] debug: reframe: Resolving systems/environments for "EESSI_MetalWalls_MW %benchmark_info=hackathonGPU/benchmark6 %scale=16_nodes %module_info=('Magic_Castle:aarch64-neoverse-V1-16c-32gb', 'EESSI-2023.06', 'MetalWalls/21.06.1-foss-2023a') %device_type=cpu" wi
th:
[2026-07-10T15:17:38.619797] debug: reframe:   > valid_systems: ['Magic_Castle:aarch64-neoverse-V1-16c-32gb']
[2026-07-10T15:17:38.620718] debug: reframe:   > valid_prog_environs: ['EESSI-2023.06']
[2026-07-10T15:17:38.621821] debug: reframe:   Generated test case: EESSI_MetalWalls_MW %benchmark_info=hackathonGPU/benchmark6 %scale=16_nodes %module_info=('Magic_Castle:aarch64-neoverse-V1-16c-32gb', 'EESSI-2023.06', 'MetalWalls/21.06.1-foss-2023a') %device_type=cpu @Magic_Castle:aarch64-neoverse-V1-16c-32gb+EESSI-2023.06
[2026-07-10T15:17:38.622851] debug: reframe: Resolving systems/environments for "EESSI_MetalWalls_MW %benchmark_info=hackathonGPU/benchmark6 %scale=16_nodes %module_info=('Magic_Castle:aarch64-neoverse-N1-16c-32gb', 'EESSI-2023.06', 'MetalWalls/21.06.1-foss-2023a') %device_type=cpu" wi
th:
[2026-07-10T15:17:38.623780] debug: reframe:   > valid_systems: ['Magic_Castle:aarch64-neoverse-N1-16c-32gb']
[2026-07-10T15:17:38.624706] debug: reframe:   > valid_prog_environs: ['EESSI-2023.06']
[2026-07-10T15:17:38.625802] debug: reframe:   Generated test case: EESSI_MetalWalls_MW %benchmark_info=hackathonGPU/benchmark6 %scale=16_nodes %module_info=('Magic_Castle:aarch64-neoverse-N1-16c-32gb', 'EESSI-2023.06', 'MetalWalls/21.06.1-foss-2023a') %device_type=cpu @Magic_Castle:aarch64-neoverse-N1-16c-32gb+EESSI-2023.06
[2026-07-10T15:17:38.626712] verbose: reframe: Generated 1152 test case(s)
[2026-07-10T15:17:38.634506] verbose: reframe: Filtering test cases(s) by name: 1152 remaining
[2026-07-10T15:17:38.640993] verbose: reframe: Filtering test cases(s) by tags: 12 remaining
[2026-07-10T15:17:38.642183] verbose: reframe: Filtering test cases(s) by other attributes: 12 remaining
[2026-07-10T15:17:38.643174] debug: reframe: Building and validating the full test DAG
[2026-07-10T15:17:38.699708] debug: reframe: Full test DAG:

I think this is really the ReFrame runtime. This is taking another 10ms per test case - even the ones that eventually get filtered out.

That means that with 1152 test case (like I have here) both the init hooks from us plus the runtime take 20ms per test case, thus already accounting for 23 seconds of the total 35s runtime.