From 355931960e85aeaac83378f4dc7936d8b46665dd Mon Sep 17 00:00:00 2001 From: Michael Tryby Date: Wed, 18 Oct 2023 16:38:45 -0400 Subject: [PATCH 1/2] Add formatted logging during execute and compare --- nrtest/compare.py | 26 +++++++++++++++++++++----- nrtest/execute.py | 25 ++++++++++++++++++------- 2 files changed, 39 insertions(+), 12 deletions(-) diff --git a/nrtest/compare.py b/nrtest/compare.py index b5b84ff..8b782b5 100644 --- a/nrtest/compare.py +++ b/nrtest/compare.py @@ -4,6 +4,7 @@ import os import json import logging +from datetime import datetime # third-party imports import six @@ -13,6 +14,11 @@ from .plugin import find_unique_function +cwidth = 4 +nwidth = 35 +fill = '.' + + class CompareException(Exception): pass @@ -47,11 +53,11 @@ def compare_testsuite(ts_sut, ts_ref, rtol, atol, outfile): # compare all tests and return False if any are incompatible compatible = True - for name in sorted(common_test_names): + for count, name in enumerate(sorted(common_test_names), start=1): test_sut = tests_sut[name] test_ref = tests_ref[name] - comparison = compare_test(test_sut, test_ref, rtol, atol) + comparison = compare_test(count, test_sut, test_ref, rtol, atol) receipt['Tests'].append(comparison) if not comparison['passed']: @@ -65,7 +71,7 @@ def compare_testsuite(ts_sut, ts_ref, rtol, atol, outfile): return compatible -def compare_test(test_sut, test_ref, rtol, atol): +def compare_test(count, test_sut, test_ref, rtol, atol): """Compare the results of a single test against a benchmark. Args: @@ -75,6 +81,10 @@ def compare_test(test_sut, test_ref, rtol, atol): Returns: boolean compatibility """ + + ccount = f"#{count}" + name = f"{test_sut.name} " + logger = logging.getLogger(test_sut.name) comparison = { @@ -96,6 +106,7 @@ def compare_test(test_sut, test_ref, rtol, atol): # compare result files # return False immediately if any are incompatible + start_time = datetime.now() for fname, ftype in six.iteritems(test_sut.output_files): ftype = ftype.lower() @@ -110,21 +121,26 @@ def compare_test(test_sut, test_ref, rtol, atol): compare_file = find_unique_function('compare', ftype) try: compatible = compare_file(path_sut, path_ref, rtol, atol) + except Exception as e: raise CompareException('Exception raised during diff: %s' % e) if not compatible: raise CompareException('%s: diff failed' % fname) + duration = (datetime.now() - start_time).total_seconds() + except CompareException as e: comparison['passed'] = False comparison['error_msg'] = str(e) - logger.info(color('fail', 'r')) + status = color('fail', 'r') + logging.info(f"Test {ccount:>{cwidth}}: {name:{fill}<{nwidth}} {status}") logger.info(str(e)) else: comparison['passed'] = compatible - logger.info(color('pass', 'g')) + status = color('pass', 'g') + logging.info(f"Test {ccount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.3f} sec") return comparison diff --git a/nrtest/execute.py b/nrtest/execute.py index 7058482..a93fc1e 100644 --- a/nrtest/execute.py +++ b/nrtest/execute.py @@ -15,20 +15,28 @@ from .utility import color, copy_file_and_path, rmtree, which +cwidth = 4 +nwidth = 35 +fill = '.' + + class TestFailure(Exception): pass def execute_testsuite(ts): success = True - for test in ts.tests: - if not execute_test(test, ts.app): + for count, test in enumerate(ts.tests, start=1): + if not execute_test(count, test, ts.app): success = False return success -def execute_test(test, app): +def execute_test(count, test, app): + tcount = f"#{count}" + name = f"{test.name} " + logger = logging.getLogger(test.name) if not os.path.exists(test.output_dir): @@ -37,17 +45,20 @@ def execute_test(test, app): try: duration = _execute(test, app) _postcheck(test) + except TestFailure as e: test.passed = False test.error_msg = str(e) - logger.info(color('fail', 'r')) + status = color('fail', 'r') + logging.info(f"Test {tcount:>{cwidth}}: {name:{fill}<{nwidth}} {status}") logger.info(test.error_msg) else: test.passed = True test.error_msg = None - logger.info(color('pass', 'g')) - dur_str = str(datetime.timedelta(seconds=duration)).split('.')[0] - logger.debug('Duration {0}'.format(dur_str)) + status = color('pass', 'g') + logging.info(f"Test {tcount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.3f} sec") +# dur_str = str(datetime.timedelta(seconds=duration)).split('.')[0] +# logger.debug('Duration {0}'.format(dur_str)) return test.passed From 861a778c0beee15d12a2051c827b5856e42d515d Mon Sep 17 00:00:00 2001 From: Michael Tryby Date: Thu, 19 Oct 2023 10:43:07 -0400 Subject: [PATCH 2/2] Add test summary to log --- nrtest/compare.py | 20 +++++++++++++++++--- nrtest/execute.py | 22 ++++++++++++++++++---- 2 files changed, 35 insertions(+), 7 deletions(-) diff --git a/nrtest/compare.py b/nrtest/compare.py index 8b782b5..cb75f5a 100644 --- a/nrtest/compare.py +++ b/nrtest/compare.py @@ -53,15 +53,29 @@ def compare_testsuite(ts_sut, ts_ref, rtol, atol, outfile): # compare all tests and return False if any are incompatible compatible = True - for count, name in enumerate(sorted(common_test_names), start=1): + pass_count = 0 + + start_time = datetime.now() + + for test_count, name in enumerate(sorted(common_test_names), start=1): test_sut = tests_sut[name] test_ref = tests_ref[name] - comparison = compare_test(count, test_sut, test_ref, rtol, atol) + comparison = compare_test(test_count, test_sut, test_ref, rtol, atol) receipt['Tests'].append(comparison) if not comparison['passed']: compatible = False + else: + pass_count += 1 + + duration = (datetime.now() - start_time).total_seconds() + + prct = int(100*pass_count/test_count) + fail_count = test_count - pass_count + logging.info("") + logging.info(f"{prct}% tests passed, {fail_count} tests failed of {test_count}") + logging.info(f"Total test time (real) = {duration:3.2f} sec") if outfile: with open(outfile, 'w') as f: @@ -140,7 +154,7 @@ def compare_test(count, test_sut, test_ref, rtol, atol): else: comparison['passed'] = compatible status = color('pass', 'g') - logging.info(f"Test {ccount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.3f} sec") + logging.info(f"Test {ccount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.2f} sec") return comparison diff --git a/nrtest/execute.py b/nrtest/execute.py index a93fc1e..1faa4e7 100644 --- a/nrtest/execute.py +++ b/nrtest/execute.py @@ -5,7 +5,7 @@ import logging import tempfile import json -import datetime +from datetime import datetime # third-party imports from packaging import version @@ -26,9 +26,23 @@ class TestFailure(Exception): def execute_testsuite(ts): success = True - for count, test in enumerate(ts.tests, start=1): - if not execute_test(count, test, ts.app): + pass_count = 0 + + start_time = datetime.now() + + for test_count, test in enumerate(ts.tests, start=1): + if not execute_test(test_count, test, ts.app): success = False + else: + pass_count += 1 + + duration = (datetime.now() - start_time).total_seconds() + + prct = int(100*pass_count/test_count) + fail_count = test_count - pass_count + logging.info("") + logging.info(f"{prct}% tests passed, {fail_count} tests failed of {test_count}") + logging.info(f"Total test time (real) = {duration:3.2f} sec") return success @@ -56,7 +70,7 @@ def execute_test(count, test, app): test.passed = True test.error_msg = None status = color('pass', 'g') - logging.info(f"Test {tcount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.3f} sec") + logging.info(f"Test {tcount:>{cwidth}}: {name:{fill}<{nwidth}} {status} {duration:3.2f} sec") # dur_str = str(datetime.timedelta(seconds=duration)).split('.')[0] # logger.debug('Duration {0}'.format(dur_str))