test/py/tests/test_trace.py

# SPDX-License-Identifier: GPL-2.0
# Copyright 2022 Google LLC
# Written by Simon Glass <sjg@chromium.org>

"""Tests for the function trace facility"""

import os
import re
import pytest

import utils

# 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'.*0\.\.\.\.\.? \s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$')


def collect_trace(ubman):
    """Build U-Boot and run it to collect a trace

    Args:
        ubman (ConsoleBase): U-Boot console

    Returns:
        tuple:
            str: Filename of the output trace file
            int: Microseconds taken for initf_dm according to bootstage
    """
    ubman.run_command('trace pause')
    out = ubman.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'] ==
            ubman.config.buildconfig.get('config_trace_call_depth_limit'))
    assert int(vals['calls not traced due to depth']) > 100000

    out = ubman.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 = 0x02000000
    out = ubman.run_command(f'trace calls {addr:x} {size:x}')
    print(out)
    fname = os.path.join(TMPDIR, 'trace')
    out = ubman.run_command(
        'host save hostfs - %x %s ${profoffset}' % (addr, fname))
    return fname, int(dm_f_time[0])


def wipe_and_collect_trace(ubman):
    """Pause and wipe traces, return the number of calls (should be zero)

    Args:
        ubman (ConsoleBase): U-Boot console

    Returns:
        int: the number of traced function calls reported by 'trace stats'
    """
    ubman.run_command('trace pause')
    ubman.run_command('trace wipe')
    out = ubman.run_command('trace stats')

    # The output is something like this:
    # 117,221 function sites
    #       0 function calls
    #       0 untracked function calls
    #       0 traced 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}

    return int(vals['traced function calls'])


def check_function(ubman, fname, proftool, map_fname, trace_dat):
    """Check that the 'function' output works

    Args:
        ubman (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 = utils.run_and_log(
        ubman, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname,
               'dump-ftrace'])

    # Check that trace-cmd can read it
    out = utils.run_and_log(ubman, ['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 -l {trace_dat} |grep -E '(initf_|initr_)'"
    out = utils.run_and_log(ubman, ['sh', '-c', cmd])

    # Format:
    #      u-boot-1     0.....    60.805596: function:             initf_malloc
    #      u-boot-1     0.....    60.805597: function:             initf_malloc
    #      u-boot-1     0.....    60.805601: function:             initf_bootstage
    #      u-boot-1     0.....    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
    if ubman.config.buildconfig.get('config_trace_early'):
        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(ubman, fname, proftool, map_fname, trace_dat):
    """Check that the 'funcgraph' output works

    Args:
        ubman (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
    utils.run_and_log(ubman, [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 -l {trace_dat} |head -n 70'
    out = utils.run_and_log(ubman, ['sh', '-c', cmd])

    # First look for this:
    #  u-boot-1     0.....   282.101360: funcgraph_entry:   0.004 us   |    initf_malloc();
    # ...
    #  u-boot-1     0.....   282.101369: funcgraph_entry:              |    initf_bootstage() {
    #  u-boot-1     0.....   282.101369: funcgraph_entry:              |      bootstage_init() {
    #  u-boot-1     0.....   282.101369: funcgraph_entry:              |        dlmalloc() {
    # ...
    #  u-boot-1     0.....   282.101375: funcgraph_exit:    0.001 us   |        }
    # Then look for this:
    #  u-boot-1     0.....   282.101375: funcgraph_exit:    0.006 us   |      }
    # Then check for this:
    #  u-boot-1     0.....   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
            if 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 -l {trace_dat} |grep -E '(initf_dm|dm_timer_init)'"
    out = utils.run_and_log(ubman, ['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(ubman, 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:
        ubman (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
    utils.run_and_log(ubman, [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;initcall_run_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
    utils.run_and_log(
        ubman, [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', encoding='utf-8') as fd:
        for line in fd:
            line = line.strip()
            if line.startswith('initf_dm'):
                _, val = line.split()
                count = int(val)
                total += count
    return total

@pytest.mark.slow
@pytest.mark.boardspec('sandbox')
@pytest.mark.buildconfigspec('trace')
def test_trace(ubman):
    """Test we can build sandbox with trace, collect and process a trace"""

    if not os.path.exists(TMPDIR):
        os.mkdir(TMPDIR)
    proftool = os.path.join(ubman.config.build_dir, 'tools', 'proftool')
    map_fname = os.path.join(ubman.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(ubman)

    check_function(ubman, fname, proftool, map_fname, trace_dat)
    trace_time = check_funcgraph(ubman, 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(ubman, fname, proftool, map_fname, trace_fg)

    # Check that bootstage and flamegraph agree to within 30%
    # This allows for CI being slow to run
    diff = abs(fg_time - dm_f_time)
    assert diff / dm_f_time < 0.3

    # Check that the trace buffer can be wiped
    numcalls = wipe_and_collect_trace(ubman)
    assert numcalls == 0