# SPDX-License-Identifier: GPL-2.0
# Copyright 2022 Google LLC
# Written by Simon Glass <sjg@chromium.org>
import os
import pytest
import re
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
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
out = 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
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 -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
out = 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') 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
check_flamegraph
@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