Test getting started twice - causing it to report as failed when it passed

[branfosj]

This looks like #1901 but I'm running ReFrame 3.5.3 - so the fix (#1904) is included.

During a ReFrame run I am having tests reporting as failing during the sanity check with a file not found error. However, this is being caused by the test is being run twice. The test passes the first time and fails on the second run - the first run cleans up the stage directory so that it is not there when the second run checks it. I'm also seeing the test counts showing 482/469.

I'm using the async execution policy. I have max_jobs set on the partition.

I see about 1% of my tests fail each time with this issue, but it is different tests from different partitions failing each time.

All the items in the log relating to this test in this partition:

  ('2020b-gompi-osu_reduce_scatter-benchmark', 'bluebear:cascadelake', 'none') -> []
  ('2020b-gompi-osu_reduce_scatter-benchmark', 'bluebear:cascadelake', 'none') -> []
[2021-04-22T02:51:36] info: reframe: [----------] started processing 2020b-gompi-osu_reduce_scatter-benchmark (2020b gompi osu_reduce_scatter Benchmark)
[2021-04-22T02:51:36] info: reframe: [ ^[[32mRUN     ^[[0m ] 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none
[2021-04-22T02:51:36] debug: 2020b-gompi-osu_reduce_scatter-benchmark: Entering stage: setup
[2021-04-22T02:51:36] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Setting up test paths
[2021-04-22T02:51:36] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Created stage directory '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark' [clean_stagedir: True]
[2021-04-22T02:51:36] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Created output directory '/rds/bear-sysadmin/tools/apps-reframe-testing/output/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark'
[2021-04-22T02:51:36] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Setting up job 'rfm_2020b-gompi-osu_reduce_scatter-benchmark_job' (scheduler: 'slurm', launcher: 'local')
[2021-04-22T02:51:37] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: compile
[2021-04-22T02:51:37] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: compile_wait
[2021-04-22T02:51:37] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run
[2021-04-22T02:51:37] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Generating the run script
[2021-04-22T02:51:40] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Spawned run job (id=32949782)
[2021-04-22T02:51:43] info: reframe: [----------] finished processing 2020b-gompi-osu_reduce_scatter-benchmark (2020b gompi osu_reduce_scatter Benchmark)
[2021-04-22T02:55:25] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run_complete
[2021-04-22T02:55:25] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run_wait
[2021-04-22T02:56:22] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: sanity
[2021-04-22T02:56:22] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: performance
[2021-04-22T02:56:22] info: reframe: [ ^[[32m      OK^[[0m ] ( 45/469) 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none [compile: 0.006s run: 285.079s total: 286.143s]
[2021-04-22T02:56:51] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: compile
[2021-04-22T02:56:51] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: compile_wait
[2021-04-22T02:56:51] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run
[2021-04-22T02:56:51] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Generating the run script
[2021-04-22T02:56:54] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Spawned run job (id=32949858)
[2021-04-22T02:57:30] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: cleanup
[2021-04-22T02:57:30] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Copying test files to output directory
[2021-04-22T02:57:30] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Removing stage directory
[2021-04-22T02:58:02] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run_complete
[2021-04-22T02:58:02] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: run_wait
[2021-04-22T02:58:02] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: Entering stage: sanity
[2021-04-22T02:58:02] debug: 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none: caught builtins.FileNotFoundError: [Errno 2] No such file or directory: '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark'
[2021-04-22T02:58:02] info: reframe: [ ^[[31m    FAIL^[[0m ] (379/469) 2020b-gompi-osu_reduce_scatter-benchmark on bluebear:cascadelake using none [compile: 0.006s run: 70.905s total: 385.847s]
[2021-04-22T02:58:02] info: reframe: ==> test failed during 'sanity': test staged in '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark'
[2021-04-22T05:13:36] info: reframe: FAILURE INFO for 2020b-gompi-osu_reduce_scatter-benchmark
[2021-04-22T05:13:36] info: reframe:   * Stage directory: /rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark
[2021-04-22T05:13:36] info: reframe:   * Rerun with '-n 2020b-gompi-osu_reduce_scatter-benchmark -p none --system bluebear:cascadelake -r'
[2021-04-22T05:13:36] info: reframe:   * Reason: file not found error: [Errno 2] No such file or directory: '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark'
FileNotFoundError: [Errno 2] No such file or directory: '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark'
[2021-04-22T05:13:36] info: reframe:                     [2020b-gompi-osu_reduce_scatter-benchmark, none, bluebear:cascadelake]
2020b-gompi-osu_reduce_scatter-benchmark

$ ls -l /rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark
ls: cannot access '/rds/bear-sysadmin/tools/apps-reframe-testing/stage/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark': No such file or directory

$ ls -l /rds/bear-sysadmin/tools/apps-reframe-testing/output/bluebear/cascadelake/none/2020b-gompi-osu_reduce_scatter-benchmark
total 49
-rw-rw-r-- 1 branfosj build 47646 Apr 22 02:57 rfm_2020b-gompi-osu_reduce_scatter-benchmark_job.err
-rw-rw-r-- 1 branfosj build   388 Apr 22 02:57 rfm_2020b-gompi-osu_reduce_scatter-benchmark_job.out
-rwxrwxr-- 1 branfosj build   610 Apr 22 02:57 rfm_2020b-gompi-osu_reduce_scatter-benchmark_job.sh

[vkarak]

Hi @branfosj, do you run with --max-retries as well?

[branfosj]

I do not set --max-retries.

[teojgo]

Hello @branfosj, is actual regression check 2020b-gompi-osu_reduce_scatter-benchmark available somewhere? If not, can you attach here?

[branfosj]

So the 2020b-gompi-osu_reduce_scatter-benchmark regression check is built up using the code below.

metaclasses/osu.py

import reframe as rfm
import reframe.utility.sanity as sn

from common import default_job_options, process_job_options


class OSUMPIBenchmarks(rfm.RunOnlyRegressionTest):
    def __init__(self, series, toolchain, version, tst):
        default_job_options(self)

        self.name = '{}-{}-{}-benchmark'.format(series, toolchain, tst)
        self.descr = '{} {} {} Benchmark'.format(series, toolchain, tst)
        self.maintainers = ['branfosj']
        self.modules = ['bear-apps/{}'.format(series),
                        'OSU-Micro-Benchmarks/{}-{}-{}'.format(version, toolchain, series)]
        self.executable = 'mpirun'
        self.executable_opts = [tst, '-m', '8', '-x', '1000', '-i', '20000']
        self.tags = {'nightly', 'benchmark', series, 'mpi'}

        self.num_tasks_per_node = 1
        self.num_tasks = 2

        self._sanity_patterns = [sn.assert_found(r'^8', self.stdout)]
        self.perf_patterns = {
            'latency': sn.extractsingle(r'^8\s+(?P<latency>\S+)', self.stdout, 'latency', float),
        }

        process_job_options(self)

apps_2020b/osu2020b.py

import reframe as rfm

from metaclasses.osu import OSUMPIBenchmarks


@rfm.parameterized_test(*(['2020b', tc, '5.6.3', tst]
                          for tc in ['gompi', 'iompi']
                          for tst in ['osu_alltoall', 'osu_allreduce', 'osu_bcast', 'osu_reduce_scatter']))
class OSUMPI2020bBenchmarks(OSUMPIBenchmarks):
    pass

common.py

import os

import reframe.utility.sanity as sn


# POWER9 SMT Setting
POWER9_SMT = 4


def default_job_options(job_options):
    """
    Default job options
    """
    job_options._valid_partitions = ['cascadelake', 'skylake', 'haswell', 'power9', 'login']
    job_options.valid_prog_environs = ['none']
    job_options.extra_resources = {'qos': {'qos': 'bbshort'}}
    job_options.max_pending_time = '15m'


def process_job_options(job_options):
    """
    Process the job options so that the relevant tests are run in the right places
    """
    if 'power9' not in job_options.tags and 'power9' in job_options._valid_partitions:
        job_options._valid_partitions.remove('power9')

    if 'gpu' in job_options.tags and 'cascadelake' in job_options._valid_partitions:
        job_options._valid_partitions.remove('cascadelake')

    if 'login' in job_options.tags:
        job_options._valid_partitions = ['login']
    elif 'login' not in job_options.tags and 'login' in job_options._valid_partitions:
        job_options._valid_partitions.remove('login')

    el8fails = [
    ]
    if job_options.name in el8fails:
        job_options._valid_partitions = []

    # We use an environment variable to control which partitions are used
    use_partitions = os.environ.get('REFRAME_USE_PARTITIONS').split()
    job_options.valid_systems = ['bluebear:%s' % p for p in job_options._valid_partitions if p in use_partitions]

    # allow for non-bbshort jobs
    # p9 does not have an resources block for qos, so this is fine.
    if hasattr(job_options, '_time_limit'):
        job_options.extra_resources = {'qos': {'qos': 'bbdefault'}}
        job_options.time_limit = job_options._time_limit

    # prepend standard prerun commands
    job_options.prerun_cmds = [
        'set -ex',
        'echo ${SLURM_JOB_NODELIST}',
        'date',
        "module list | true",
    ] + job_options.prerun_cmds

    # Put the common sanity checks first, so we catch the standard problems first
    job_options.sanity_patterns = sn.all([
        # See if the job timed out
        sn.assert_not_found('DUE TO TIME LIMIT', job_options.stderr),
        # Check to see that the module was found
        sn.assert_not_found('Unable to locate a modulefile for', job_options.stderr),
        sn.assert_not_found('Lmod has detected the following error', job_options.stderr),
        # Pick up MPI (and other) seg faults
        sn.assert_not_found('Segmentation fault', job_options.stderr),
        # Memory issues
        sn.assert_not_found('killed by the cgroup out-of-memory', job_options.stderr),
    ] + job_options._sanity_patterns)

[rsarm]

Hi @branfosj Could you please share your configuration file?

[branfosj]

site_configuration = {
    'general': [
        {
            'check_search_path': ['apps_2018b', 'apps_2019a', 'apps_2019b', 'apps_2019h', 'apps_2020a', 'apps_2020b',
                                  'apps_misc', 'apps_special'],
            'check_search_recursive': True,
        }
    ],
    'systems': [
        {
            'name': 'bluebear',
            'descr': 'BlueBEAR',
            'hostnames': ['.*'],
            'modules_system': 'lmod',
            'partitions': [
                {
                    'name': 'login',
                    'descr': 'Login nodes',
                    'scheduler': 'local',
                    'launcher': 'ssh',
                    'environs': ['none'],
                    'access': ['bb-pg-login02'],
                    'max_jobs': 1,
                },
                {
                    'name': 'cascadelake',
                    'descr': 'Cascade Lake',
                    'scheduler': 'slurm',
                    'launcher': 'local',
                    'prepare_cmds': ['module purge'],
                    'modules': ['bluebear'],
                    'environs': ['none'],
                    'max_jobs': 20,
                    'time_limit': '10m',
                    'access': [
                        '--constraint=cascadelake',
                        '--account=edmondac-rescomp-software',
                    ],
                    'resources': [
                        {
                            'name': 'qos',
                            'options': [
                                '--qos={qos}'
                            ]
                        },
                        {
                            'name': 'mem',
                            'options': [
                                '--mem={mem}'
                            ]
                        }
                    ],
                },
                {
                    'name': 'skylake',
                    'descr': 'Sky Lake',
                    'scheduler': 'slurm',
                    'launcher': 'local',
                    'prepare_cmds': ['module purge'],
                    'modules': ['bluebear'],
                    'environs': ['none'],
                    'max_jobs': 5,
                    'time_limit': '10m',
                    'access': [
                        '--constraint=skylake',
                        '--account=edmondac-rescomp-software',
                    ]
                },
                {
                    'name': 'haswell',
                    'descr': 'Haswell',
                    'scheduler': 'slurm',
                    'launcher': 'local',
                    'prepare_cmds': ['module purge'],
                    'modules': ['bluebear'],
                    'environs': ['none'],
                    'max_jobs': 20,
                    'time_limit': '10m',
                    'access': [
                        '--constraint=haswell',
                        '--account=edmondac-rescomp-software',
                    ],
                    'resources': [
                        {
                            'name': '_rfm_gpu',
                            'options': [
                                '--gres=gpu:{num_gpus_per_node}'
                            ]
                        },
                        {
                            'name': 'qos',
                            'options': [
                                '--qos={qos}'
                            ]
                        },
                        {
                            'name': 'mem',
                            'options': [
                                '--mem={mem}'
                            ]
                        }
                    ],
                },
                {
                    'name': 'power9',
                    'descr': 'Power9',
                    'scheduler': 'slurm',
                    'launcher': 'local',
                    'prepare_cmds': ['module purge'],
                    'modules': ['bluebear'],
                    'environs': ['none'],
                    'max_jobs': 10,
                    'time_limit': '10m',
                    'access': [
                        '--qos=bbpowergpu',
                        '--account=edmondac-rescomp-software',
                    ],
                    'resources': [
                        {
                            'name': '_rfm_gpu',
                            'options': [
                                '--gres=gpu:{num_gpus_per_node}'
                            ]
                        }
                    ],
                }
            ]
        },
    ],
    'environments': [
        {
            'name': 'none',
        },
    ],
    'logging': [
        {
            'level': 'debug',
            'handlers': [
                {
                    'type': 'stream',
                    'name': 'stdout',
                    'level': 'info',
                    'format': '%(message)s'
                },
                {
                    'type': 'file',
                    'name': 'reframe.log',
                    'level': 'debug',
                    'format': '[%(asctime)s] %(levelname)s: %(check_info)s: %(message)s',   # noqa: E501
                    'append': False
                }
            ],
            'handlers_perflog': [
                {
                {
                    'type': 'filelog',
                    'prefix': '%(check_system)s/%(check_partition)s',
                    'level': 'info',
                    'format': (
                        '%(check_job_completion_time)s|reframe %(version)s|'
                        '%(check_info)s|jobid=%(check_jobid)s|'
                        '%(check_perf_var)s=%(check_perf_value)s|'
                        'ref=%(check_perf_ref)s '
                        '(l=%(check_perf_lower_thres)s, '
                        'u=%(check_perf_upper_thres)s)|'
                        '%(check_perf_unit)s'
                    ),
                    'append': True
                }
            ]
        }
    ],
}

[branfosj]

When we see this problem a lot of the jobs were being queued and then cancelled when they hit the max_pending_time. At the time I reported this, one of the partitions was unavailable - so about 1/4 of the tests were like this. Since then I have removed running tests against that partition and I've not seen the issue.