Execution time varies widely with the existing tests. Provides a way to produce a summary of the time taken for each test, along with a histogram.
This is enabled with the --timing flag.
Enable it for sandbox in CI.
Example:
Duration : Number of tests ======== : ======================================== <1ms : 1 <8ms : 1 <20ms : # 20 <30ms : ######## 127 <50ms : ######################################## 582 <75ms : ####### 102 <100ms : ## 39 <200ms : ##### 86 <300ms : # 29 <500ms : ## 42 <750ms : # 16 <1.0s : # 15 <2.0s : # 23 <3.0s : 13 <5.0s : 9 <7.5s : 1 <10.0s : 6 <20.0s : 12
Signed-off-by: Simon Glass sjg@chromium.org ---
Changes in v2: - Only show the report if the --timing flag is provided - Use --timing flag to show the report in CI for just the sandbox tests
.azure-pipelines.yml | 3 +- .gitlab-ci.yml | 3 +- doc/develop/py_testing.rst | 33 +++++++++++++++ test/py/conftest.py | 87 ++++++++++++++++++++++++++++++++++++++ 4 files changed, 124 insertions(+), 2 deletions(-)
diff --git a/.azure-pipelines.yml b/.azure-pipelines.yml index df3f82074af..1a5d15a8cdc 100644 --- a/.azure-pipelines.yml +++ b/.azure-pipelines.yml @@ -295,7 +295,7 @@ stages: export PATH=/opt/qemu/bin:/tmp/uboot-test-hooks/bin:${PATH} export PYTHONPATH=/tmp/uboot-test-hooks/py/travis-ci # "${var:+"-k $var"}" expands to "" if $var is empty, "-k $var" if not - ./test/py/test.py -ra -o cache_dir="$UBOOT_TRAVIS_BUILD_DIR"/.pytest_cache --bd ${TEST_PY_BD} ${TEST_PY_ID} ${TEST_PY_TEST_SPEC:+"-k ${TEST_PY_TEST_SPEC}"} --build-dir "$UBOOT_TRAVIS_BUILD_DIR" --report-dir "$UBOOT_TRAVIS_BUILD_DIR" --junitxml=$(System.DefaultWorkingDirectory)/results.xml + ./test/py/test.py -ra -o cache_dir="$UBOOT_TRAVIS_BUILD_DIR"/.pytest_cache --bd ${TEST_PY_BD} ${TEST_PY_ID} ${TEST_TIMING} ${TEST_PY_TEST_SPEC:+"-k ${TEST_PY_TEST_SPEC}"} --build-dir "$UBOOT_TRAVIS_BUILD_DIR" --report-dir "$UBOOT_TRAVIS_BUILD_DIR" --junitxml=$(System.DefaultWorkingDirectory)/results.xml # the below corresponds to .gitlab-ci.yml "after_script" rm -rf /tmp/uboot-test-hooks /tmp/venv EOF @@ -318,6 +318,7 @@ stages: matrix: sandbox: TEST_PY_BD: "sandbox" + TEST_TIMING: "--timing" sandbox_asan: TEST_PY_BD: "sandbox" OVERRIDE: "-a ASAN" diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 88a078c83dc..a25c037b7d3 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -89,7 +89,7 @@ stages: # "${var:+"-k $var"}" expands to "" if $var is empty, "-k $var" if not - export PATH=/opt/qemu/bin:/tmp/uboot-test-hooks/bin:${PATH}; export PYTHONPATH=/tmp/uboot-test-hooks/py/travis-ci; - ./test/py/test.py -ra --bd ${TEST_PY_BD} ${TEST_PY_ID} + ./test/py/test.py -ra --bd ${TEST_PY_BD} ${TEST_PY_ID} ${TEST_TIMING} ${TEST_PY_TEST_SPEC:+"-k ${TEST_PY_TEST_SPEC}"} --build-dir "$UBOOT_TRAVIS_BUILD_DIR" --junitxml=/tmp/${TEST_PY_BD}/results.xml @@ -273,6 +273,7 @@ Check packing of Python tools: sandbox test.py: variables: TEST_PY_BD: "sandbox" + TEST_TIMING: "--timing" <<: *buildman_and_testpy_dfn
sandbox with clang test.py: diff --git a/doc/develop/py_testing.rst b/doc/develop/py_testing.rst index 6ff78103409..b50473039be 100644 --- a/doc/develop/py_testing.rst +++ b/doc/develop/py_testing.rst @@ -246,6 +246,39 @@ Command-line options sets the directory used to store persistent test data. This is test data that may be re-used across test runs, such as file-system images.
+--timing + shows a histogram of test duration, at the end of the run. The columns are: + + Duration + the duration-bucket that this test was in + + Total + total time of all tests in this bucket + + Number of tests + graph showing the number of tests in this bucket, with the actual number + shown at the end + + Example:: + + Duration : Total | Number of tests + ======== : ======= |======================================== + <20ms : 418ms |## 23 + <30ms : 9.1s |######################################## 347 + <40ms : 10.0s |################################# 294 + <50ms : 3.1s |####### 69 + <75ms : 2.6s |#### 43 + <100ms : 1.7s |## 19 + <200ms : 3.0s |## 22 + <300ms : 1.7s | 7 + <400ms : 675ms | 2 + <500ms : 2.2s | 5 + <750ms : 8.3s |# 13 + <1.0s : 1.6s | 2 + <2.0s : 9.4s | 7 + <3.0s : 2.4s | 1 + <7.5s : 6.1s | 1 + `pytest` also implements a number of its own command-line options. Commonly used options are mentioned below. Please see `pytest` documentation for complete details. Execute `py.test --version` for a brief summary. Note that U-Boot's diff --git a/test/py/conftest.py b/test/py/conftest.py index 3bd333bfd24..31043a697e2 100644 --- a/test/py/conftest.py +++ b/test/py/conftest.py @@ -25,6 +25,7 @@ import re from _pytest.runner import runtestprotocol import subprocess import sys +import time from u_boot_spawn import BootFail, Timeout, Unexpected, handle_exception
# Globals: The HTML log file, and the connection to the U-Boot console. @@ -91,6 +92,9 @@ def pytest_addoption(parser): parser.addoption('--role', help='U-Boot board role (for Labgrid-sjg)') parser.addoption('--use-running-system', default=False, action='store_true', help="Assume that U-Boot is ready and don't wait for a prompt") + parser.addoption('--timing', default=False, action='store_true', + help='Show info on test timing') +
def run_build(config, source_dir, build_dir, board_type, log): """run_build: Build U-Boot @@ -322,6 +326,7 @@ def pytest_configure(config): ubconfig.use_running_system = config.getoption('use_running_system') ubconfig.dtb = build_dir + '/arch/sandbox/dts/test.dtb' ubconfig.connection_ok = True + ubconfig.timing = config.getoption('timing')
env_vars = ( 'board_type', @@ -516,6 +521,12 @@ tests_skipped = [] tests_warning = [] tests_passed = []
+# Duration of each test: +# key (string): test name +# value (float): duration in ms +test_durations = {} + + def pytest_itemcollected(item): """pytest hook: Called once for each test found during collection.
@@ -531,6 +542,73 @@ def pytest_itemcollected(item):
tests_not_run.append(item.name)
+ +def show_timings(): + """Write timings for each test, along with a histogram""" + + def get_time_delta(msecs): + """Convert milliseconds into a user-friendly string""" + if msecs >= 1000: + return f'{msecs / 1000:.1f}s' + else: + return f'{msecs:.0f}ms' + + def show_bar(key, msecs, value): + """Show a single bar (line) of the histogram + + Args: + key (str): Key to write on the left + value (int): Value to display, i.e. the relative length of the bar + """ + if value: + bar_length = int((value / max_count) * max_bar_length) + print(f"{key:>8} : {get_time_delta(msecs):>7} |{'#' * bar_length} {value}", file=buf) + + # Create the buckets we will use, each has a count and a total time + bucket = {} + for power in range(5): + for i in [1, 2, 3, 4, 5, 7.5]: + bucket[i * 10 ** power] = {'count': 0, 'msecs': 0.0} + max_dur = max(bucket.keys()) + + # Collect counts for each bucket; if outside the range, add to too_long + # Also show a sorted list of test timings from longest to shortest + too_long = 0 + too_long_msecs = 0.0 + max_count = 0 + with log.section('Timing Report', 'timing_report'): + for name, dur in sorted(test_durations.items(), key=lambda kv: kv[1], + reverse=True): + log.info(f'{get_time_delta(dur):>8} {name}') + greater = [k for k in bucket.keys() if dur <= k] + if greater: + buck = bucket[min(greater)] + buck['count'] += 1 + max_count = max(max_count, buck['count']) + buck['msecs'] += dur + else: + too_long += 1 + too_long_msecs += dur + + # Set the maximum length of a histogram bar, in characters + max_bar_length = 40 + + # Show a a summary with histogram + buf = io.StringIO() + with log.section('Timing Summary', 'timing_summary'): + print('Duration : Total | Number of tests', file=buf) + print(f'{"=" * 8} : {"=" * 7} |{"=" * max_bar_length}', file=buf) + for dur, buck in bucket.items(): + if buck['count']: + label = get_time_delta(dur) + show_bar(f'<{label}', buck['msecs'], buck['count']) + if too_long: + show_bar(f'>{get_time_delta(max_dur)}', too_long_msecs, too_long) + log.info(buf.getvalue()) + if ubconfig.timing: + print(buf.getvalue(), end='') + + def cleanup(): """Clean up all global state.
@@ -580,6 +658,7 @@ def cleanup(): for test in tests_not_run: anchor = anchors.get(test, None) log.status_fail('... ' + test, anchor) + show_timings() log.close() atexit.register(cleanup)
@@ -713,7 +792,9 @@ def pytest_runtest_protocol(item, nextitem): log.get_and_reset_warning() ihook = item.ihook ihook.pytest_runtest_logstart(nodeid=item.nodeid, location=item.location) + start = time.monotonic() reports = runtestprotocol(item, nextitem=nextitem) + duration = round((time.monotonic() - start) * 1000, 1) ihook.pytest_runtest_logfinish(nodeid=item.nodeid, location=item.location) was_warning = log.get_and_reset_warning()
@@ -726,6 +807,7 @@ def pytest_runtest_protocol(item, nextitem): start_test_section(item)
failure_cleanup = False + record_duration = True if not was_warning: test_list = tests_passed msg = 'OK' @@ -756,6 +838,11 @@ def pytest_runtest_protocol(item, nextitem): test_list = tests_skipped msg = 'SKIPPED:\n' + str(report.longrepr) msg_log = log.status_skipped + record_duration = False + + msg += f' {duration} ms' + if record_duration: + test_durations[item.name] = duration
if failure_cleanup: console.drain_console()