mirror of
https://github.com/u-boot/u-boot.git
synced 2024-12-11 21:53:29 +08:00
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>
This commit is contained in:
parent
71d3e7949c
commit
9cea4797ae
@ -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}/
|
||||
|
@ -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"
|
||||
|
304
test/py/tests/test_trace.py
Normal file
304
test/py/tests/test_trace.py
Normal file
@ -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
|
Loading…
Reference in New Issue
Block a user