Skip to content

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

New issue
New issue
Open
Open
Test suite run over all tests takes long due to loading of ReFrame environments#344

Description

@casparvl
casparvl
opened on Jul 10, 2026

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.

Activity

  1. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

    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.

  2. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

    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.

  3. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

    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'}

  4. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

    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.

  5. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

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

  6. casparvl commented on Jul 10, 2026

    @casparvl
    casparvl
    on Jul 10, 2026
    CollaboratorAuthor

    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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions