Add a test which runs sandbox, collects a trace and makes sure it can be processed by trace-cmd. This should ensure that this feature continues to work as U-Boot and trace-cmd evolve.
Signed-off-by: Simon Glass sjg@chromium.org ---
.azure-pipelines.yml | 8 + .gitlab-ci.yml | 12 ++ test/py/tests/test_trace.py | 304 ++++++++++++++++++++++++++++++++++++ 3 files changed, 324 insertions(+) create mode 100644 test/py/tests/test_trace.py
diff --git a/.azure-pipelines.yml b/.azure-pipelines.yml index 49fc34fbf23..8f5c8e05dc5 100644 --- a/.azure-pipelines.yml +++ b/.azure-pipelines.yml @@ -239,6 +239,11 @@ stages: TEST_PY_TEST_SPEC: "test_ofplatdata or test_handoff or test_spl" sandbox_flattree: TEST_PY_BD: "sandbox_flattree" + sandbox_trace: + TEST_PY_BD: "sandbox" + BUILD_ENV: "FTRACE=1 NO_LTO=1" + TEST_PY_TEST_SPEC: "trace" + OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000" coreboot: TEST_PY_BD: "coreboot" TEST_PY_ID: "--id qemu" @@ -361,6 +366,9 @@ stages: # the below corresponds to .gitlab-ci.yml "script" cd ${WORK_DIR} export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD}; + if [ -n "${BUILD_ENV}" ]; then + export ${BUILD_ENV}; + fi tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e --board ${TEST_PY_BD} ${OVERRIDE} cp ~/grub_x86.efi ${UBOOT_TRAVIS_BUILD_DIR}/ cp ~/grub_x64.efi ${UBOOT_TRAVIS_BUILD_DIR}/ diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 398fa2b45e2..87288a666df 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -35,6 +35,9 @@ stages: # If we've been asked to use clang only do one configuration. - export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD} - echo BUILD_ENV ${BUILD_ENV} + - if [ -n "${BUILD_ENV}" ]; then + export ${BUILD_ENV}; + fi - tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e --board ${TEST_PY_BD} ${OVERRIDE} - cp ~/grub_x86.efi $UBOOT_TRAVIS_BUILD_DIR/ @@ -267,6 +270,15 @@ sandbox_vpl test.py: TEST_PY_TEST_SPEC: "test_vpl_help or test_spl" <<: *buildman_and_testpy_dfn
+# Enable tracing and disable LTO, to ensure functions are not elided +sandbox trace_test.py: + variables: + TEST_PY_BD: "sandbox" + BUILD_ENV: "FTRACE=1 NO_LTO=1" + TEST_PY_TEST_SPEC: "trace" + OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000" + <<: *buildman_and_testpy_dfn + evb-ast2500 test.py: variables: TEST_PY_BD: "evb-ast2500" diff --git a/test/py/tests/test_trace.py b/test/py/tests/test_trace.py new file mode 100644 index 00000000000..14584d11a23 --- /dev/null +++ b/test/py/tests/test_trace.py @@ -0,0 +1,304 @@ +# SPDX-License-Identifier: GPL-2.0 +# Copyright 2022 Google LLC +# Written by Simon Glass sjg@chromium.org + +import os +import pytest +import re + +import u_boot_utils as util + +# This is needed for Azure, since the default '..' directory is not writeable +TMPDIR = '/tmp/test_trace' + +# Decode a function-graph line +RE_LINE = re.compile(r'.*[000]\s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$') + + +def collect_trace(cons): + """Build U-Boot and run it to collect a trace + + Args: + cons (ConsoleBase): U-Boot console + + Returns: + tuple: + str: Filename of the output trace file + int: Microseconds taken for initf_dm according to bootstage + """ + cons.run_command('trace pause') + out = cons.run_command('trace stats') + + # The output is something like this: + # 251,003 function sites + # 1,160,283 function calls + # 0 untracked function calls + # 1,230,758 traced function calls (341538 dropped due to overflow) + # 33 maximum observed call depth + # 15 call depth limit + # 748,268 calls not traced due to depth + # 1,230,758 max function calls + + # Get a dict of values from the output + lines = [line.split(maxsplit=1) for line in out.splitlines() if line] + vals = {key: val.replace(',', '') for val, key in lines} + + assert int(vals['function sites']) > 100000 + assert int(vals['function calls']) > 200000 + assert int(vals['untracked function calls']) == 0 + assert int(vals['maximum observed call depth']) > 30 + assert (vals['call depth limit'] == + cons.config.buildconfig.get('config_trace_call_depth_limit')) + assert int(vals['calls not traced due to depth']) > 100000 + + out = cons.run_command('bootstage report') + # Accumulated time: + # 19,104 dm_r + # 23,078 of_live + # 46,280 dm_f + dm_f_time = [line.split()[0] for line in out.replace(',', '').splitlines() + if 'dm_f' in line] + + # Read out the trace data + addr = 0x02000000 + size = 0x01000000 + out = cons.run_command(f'trace calls {addr:x} {size:x}') + print(out) + fname = os.path.join(TMPDIR, 'trace') + out = cons.run_command( + 'host save hostfs - %x %s ${profoffset}' % (addr, fname)) + return fname, int(dm_f_time[0]) + + +def check_function(cons, fname, proftool, map_fname, trace_dat): + """Check that the 'function' output works + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_dat (str): Filename of output file + """ + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname, + 'dump-ftrace']) + + # Check that trace-cmd can read it + out = util.run_and_log(cons, ['trace-cmd', 'dump', trace_dat]) + + # Tracing meta data in file /tmp/test_trace/trace.dat: + # [Initial format] + # 6 [Version] + # 0 [Little endian] + # 4 [Bytes in a long] + # 4096 [Page size, bytes] + # [Header page, 205 bytes] + # [Header event, 205 bytes] + # [Ftrace format, 3 events] + # [Events format, 0 systems] + # [Kallsyms, 342244 bytes] + # [Trace printk, 0 bytes] + # [Saved command lines, 9 bytes] + # 1 [CPUs with tracing data] + # [6 options] + # [Flyrecord tracing data] + # [Tracing clock] + # [local] global counter uptime perf mono mono_raw boot x86-tsc + assert '[Flyrecord tracing data]' in out + assert '4096 [Page size, bytes]' in out + kallsyms = [line.split() for line in out.splitlines() if 'Kallsyms' in line] + # [['[Kallsyms,', '342244', 'bytes]']] + val = int(kallsyms[0][1]) + assert val > 50000 # Should be at least 50KB of symbols + + # Check that the trace has something useful + cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_|initr_)'" + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + # Format: + # unknown option 14 + # u-boot-1 [000] 60.805596: function: initf_malloc + # u-boot-1 [000] 60.805597: function: initf_malloc + # u-boot-1 [000] 60.805601: function: initf_bootstage + # u-boot-1 [000] 60.805607: function: initf_bootstage + lines = [line.replace(':', '').split() for line in out.splitlines()] + vals = {items[4]: float(items[2]) for items in lines if len(items) == 5} + base = None + max_delta = 0 + for timestamp in vals.values(): + if base: + max_delta = max(max_delta, timestamp - base) + else: + base = timestamp + + # Check for some expected functions + assert 'initf_malloc' in vals.keys() + assert 'initr_watchdog' in vals.keys() + assert 'initr_dm' in vals.keys() + + # All the functions should be executed within five seconds at most + assert max_delta < 5 + + +def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): + """Check that the 'funcgraph' output works + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_dat (str): Filename of output file + + Returns: + int: Time taken by the first part of the initf_dm() function, in us + """ + + # Generate the funcgraph format + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname, + 'dump-ftrace', '-f', 'funcgraph']) + + # Check that the trace has what we expect + cmd = f'trace-cmd report {trace_dat} |head -n 70' + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + # First look for this: + # u-boot-1 [000] 282.101360: funcgraph_entry: 0.004 us | initf_malloc(); + # ... + # u-boot-1 [000] 282.101369: funcgraph_entry: | initf_bootstage() { + # u-boot-1 [000] 282.101369: funcgraph_entry: | bootstage_init() { + # u-boot-1 [000] 282.101369: funcgraph_entry: | dlmalloc() { + # ... + # u-boot-1 [000] 282.101375: funcgraph_exit: 0.001 us | } + # Then look for this: + # u-boot-1 [000] 282.101375: funcgraph_exit: 0.006 us | } + # Then check for this: + # u-boot-1 [000] 282.101375: funcgraph_entry: 0.000 us | event_init(); + + expected_indent = None + found_start = False + found_end = False + upto = None + + # Look for initf_bootstage() entry and make sure we see the exit + # Collect the time for initf_dm() + for line in out.splitlines(): + m = RE_LINE.match(line) + if m: + timestamp, indent, func, brace = m.groups() + if found_end: + upto = func + break + elif func == 'initf_bootstage() ': + found_start = True + expected_indent = indent + ' ' + elif found_start and indent == expected_indent and brace == '}': + found_end = True + + # The next function after initf_bootstage() exits should be event_init() + assert upto == 'event_init()' + + # Now look for initf_dm() and dm_timer_init() so we can check the bootstage + # time + cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_dm|dm_timer_init)'" + out = util.run_and_log(cons, ['sh', '-c', cmd]) + + start_timestamp = None + end_timestamp = None + for line in out.splitlines(): + m = RE_LINE.match(line) + if m: + timestamp, indent, func, brace = m.groups() + if func == 'initf_dm() ': + start_timestamp = timestamp + elif func == 'dm_timer_init() ': + end_timestamp = timestamp + break + assert start_timestamp and end_timestamp + + # Convert the time to microseconds + return int((float(end_timestamp) - float(start_timestamp)) * 1000000) + + +def check_flamegraph(cons, fname, proftool, map_fname, trace_fg): + """Check that the 'flamegraph' output works + + This spot checks a few call counts and estimates the time taken by the + initf_dm() function + + Args: + cons (ConsoleBase): U-Boot console + fname (str): Filename of trace file + proftool (str): Filename of proftool + map_fname (str): Filename of System.map + trace_fg (str): Filename of output file + + Returns: + int: Approximate number of microseconds used by the initf_dm() function + """ + + # Generate the flamegraph format + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname, + 'dump-flamegraph']) + + # We expect dm_timer_init() to be called twice: once before relocation and + # once after + look1 = 'initf_dm;dm_timer_init 1' + look2 = 'board_init_r;initr_dm_devices;dm_timer_init 1' + found = 0 + with open(trace_fg, 'r') as fd: + for line in fd: + line = line.strip() + if line == look1 or line == look2: + found += 1 + assert found == 2 + + # Generate the timing graph + out = util.run_and_log( + cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname, + 'dump-flamegraph', '-f', 'timing']) + + # Add up all the time spend in initf_dm() and its children + total = 0 + with open(trace_fg, 'r') as fd: + for line in fd: + line = line.strip() + if line.startswith('initf_dm'): + func, val = line.split() + count = int(val) + total += count + return total + + +@pytest.mark.slow +@pytest.mark.boardspec('sandbox') +@pytest.mark.buildconfigspec('trace') +def test_trace(u_boot_console): + """Test we can build sandbox with trace, collect and process a trace""" + cons = u_boot_console + + if not os.path.exists(TMPDIR): + os.mkdir(TMPDIR) + proftool = os.path.join(cons.config.build_dir, 'tools', 'proftool') + map_fname = os.path.join(cons.config.build_dir, 'System.map') + trace_dat = os.path.join(TMPDIR, 'trace.dat') + trace_fg = os.path.join(TMPDIR, 'trace.fg') + + fname, dm_f_time = collect_trace(cons) + + check_function(cons, fname, proftool, map_fname, trace_dat) + trace_time = check_funcgraph(cons, fname, proftool, map_fname, trace_dat) + + # Check that bootstage and funcgraph agree to within 10 microseconds + diff = abs(trace_time - dm_f_time) + print(f'trace_time {trace_time}, dm_f_time {dm_f_time}') + assert diff / dm_f_time < 0.01 + + fg_time = check_flamegraph(cons, fname, proftool, map_fname, trace_fg) + + # Check that bootstage and flamegraph agree to within 10% + diff = abs(fg_time - dm_f_time) + assert diff / dm_f_time < 0.1