trace: Add a test

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

@@ -240,6 +240,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"
@@ -362,6 +367,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}/

.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/
@@ -268,6 +271,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"

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