test/py/tests/test_trace.py

   1 # SPDX-License-Identifier: GPL-2.0
   2 # Copyright 2022 Google LLC
   3 # Written by Simon Glass <sjg@chromium.org>
   4
   5 import os
   6 import pytest
   7 import re
   8
   9 import u_boot_utils as util
  10
  11 # This is needed for Azure, since the default '..' directory is not writeable
  12 TMPDIR = '/tmp/test_trace'
  13
  14 # Decode a function-graph line
  15 RE_LINE = re.compile(r'.*0\.\.\.\.\. \s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$')
  16
  17
  18 def collect_trace(cons):
  19     """Build U-Boot and run it to collect a trace
  20
  21     Args:
  22         cons (ConsoleBase): U-Boot console
  23
  24     Returns:
  25         tuple:
  26             str: Filename of the output trace file
  27             int: Microseconds taken for initf_dm according to bootstage
  28     """
  29     cons.run_command('trace pause')
  30     out = cons.run_command('trace stats')
  31
  32     # The output is something like this:
  33     #    251,003 function sites
  34     #  1,160,283 function calls
  35     #          0 untracked function calls
  36     #  1,230,758 traced function calls (341538 dropped due to overflow)
  37     #         33 maximum observed call depth
  38     #         15 call depth limit
  39     #    748,268 calls not traced due to depth
  40     #  1,230,758 max function calls
  41
  42     # Get a dict of values from the output
  43     lines = [line.split(maxsplit=1) for line in out.splitlines() if line]
  44     vals = {key: val.replace(',', '') for val, key in lines}
  45
  46     assert int(vals['function sites']) > 100000
  47     assert int(vals['function calls']) > 200000
  48     assert int(vals['untracked function calls']) == 0
  49     assert int(vals['maximum observed call depth']) > 30
  50     assert (vals['call depth limit'] ==
  51             cons.config.buildconfig.get('config_trace_call_depth_limit'))
  52     assert int(vals['calls not traced due to depth']) > 100000
  53
  54     out = cons.run_command('bootstage report')
  55     # Accumulated time:
  56     #           19,104  dm_r
  57     #           23,078  of_live
  58     #           46,280  dm_f
  59     dm_f_time = [line.split()[0] for line in out.replace(',', '').splitlines()
  60                  if 'dm_f' in line]
  61
  62     # Read out the trace data
  63     addr = 0x02000000
  64     size = 0x02000000
  65     out = cons.run_command(f'trace calls {addr:x} {size:x}')
  66     print(out)
  67     fname = os.path.join(TMPDIR, 'trace')
  68     out = cons.run_command(
  69         'host save hostfs - %x %s ${profoffset}' % (addr, fname))
  70     return fname, int(dm_f_time[0])
  71
  72
  73 def check_function(cons, fname, proftool, map_fname, trace_dat):
  74     """Check that the 'function' output works
  75
  76     Args:
  77         cons (ConsoleBase): U-Boot console
  78         fname (str): Filename of trace file
  79         proftool (str): Filename of proftool
  80         map_fname (str): Filename of System.map
  81         trace_dat (str): Filename of output file
  82     """
  83     out = util.run_and_log(
  84         cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname,
  85                'dump-ftrace'])
  86
  87     # Check that trace-cmd can read it
  88     out = util.run_and_log(cons, ['trace-cmd', 'dump', trace_dat])
  89
  90     # Tracing meta data in file /tmp/test_trace/trace.dat:
  91     #    [Initial format]
  92     #            6        [Version]
  93     #            0        [Little endian]
  94     #            4        [Bytes in a long]
  95     #            4096        [Page size, bytes]
  96     #    [Header page, 205 bytes]
  97     #    [Header event, 205 bytes]
  98     #    [Ftrace format, 3 events]
  99     #    [Events format, 0 systems]
 100     #    [Kallsyms, 342244 bytes]
 101     #    [Trace printk, 0 bytes]
 102     #    [Saved command lines, 9 bytes]
 103     #    1 [CPUs with tracing data]
 104     #    [6 options]
 105     #    [Flyrecord tracing data]
 106     #    [Tracing clock]
 107     #            [local] global counter uptime perf mono mono_raw boot x86-tsc
 108     assert '[Flyrecord tracing data]' in out
 109     assert '4096        [Page size, bytes]' in out
 110     kallsyms = [line.split() for line in out.splitlines() if 'Kallsyms' in line]
 111     # [['[Kallsyms,', '342244', 'bytes]']]
 112     val = int(kallsyms[0][1])
 113     assert val > 50000  # Should be at least 50KB of symbols
 114
 115     # Check that the trace has something useful
 116     cmd = f"trace-cmd report -l {trace_dat} |grep -E '(initf_|initr_)'"
 117     out = util.run_and_log(cons, ['sh', '-c', cmd])
 118
 119     # Format:
 120     #      u-boot-1     0.....    60.805596: function:             initf_malloc
 121     #      u-boot-1     0.....    60.805597: function:             initf_malloc
 122     #      u-boot-1     0.....    60.805601: function:             initf_bootstage
 123     #      u-boot-1     0.....    60.805607: function:             initf_bootstage
 124
 125     lines = [line.replace(':', '').split() for line in out.splitlines()]
 126     vals = {items[4]: float(items[2]) for items in lines if len(items) == 5}
 127     base = None
 128     max_delta = 0
 129     for timestamp in vals.values():
 130         if base:
 131             max_delta = max(max_delta, timestamp - base)
 132         else:
 133             base = timestamp
 134
 135     # Check for some expected functions
 136     assert 'initf_malloc' in vals.keys()
 137     assert 'initr_watchdog' in vals.keys()
 138     assert 'initr_dm' in vals.keys()
 139
 140     # All the functions should be executed within five seconds at most
 141     assert max_delta < 5
 142
 143
 144 def check_funcgraph(cons, fname, proftool, map_fname, trace_dat):
 145     """Check that the 'funcgraph' output works
 146
 147     Args:
 148         cons (ConsoleBase): U-Boot console
 149         fname (str): Filename of trace file
 150         proftool (str): Filename of proftool
 151         map_fname (str): Filename of System.map
 152         trace_dat (str): Filename of output file
 153
 154     Returns:
 155         int: Time taken by the first part of the initf_dm() function, in us
 156     """
 157
 158     # Generate the funcgraph format
 159     out = util.run_and_log(
 160         cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname,
 161                'dump-ftrace', '-f', 'funcgraph'])
 162
 163     # Check that the trace has what we expect
 164     cmd = f'trace-cmd report -l {trace_dat} |head -n 70'
 165     out = util.run_and_log(cons, ['sh', '-c', cmd])
 166
 167     # First look for this:
 168     #  u-boot-1     0.....   282.101360: funcgraph_entry:        0.004 us   |    initf_malloc();
 169     # ...
 170     #  u-boot-1     0.....   282.101369: funcgraph_entry:                   |    initf_bootstage() {
 171     #  u-boot-1     0.....   282.101369: funcgraph_entry:                   |      bootstage_init() {
 172     #  u-boot-1     0.....   282.101369: funcgraph_entry:                   |        dlmalloc() {
 173     # ...
 174     #  u-boot-1     0.....   282.101375: funcgraph_exit:         0.001 us   |        }
 175     # Then look for this:
 176     #  u-boot-1     0.....   282.101375: funcgraph_exit:         0.006 us   |      }
 177     # Then check for this:
 178     #  u-boot-1     0.....   282.101375: funcgraph_entry:        0.000 us   |    initcall_is_event();
 179
 180     expected_indent = None
 181     found_start = False
 182     found_end = False
 183     upto = None
 184
 185     # Look for initf_bootstage() entry and make sure we see the exit
 186     # Collect the time for initf_dm()
 187     for line in out.splitlines():
 188         m = RE_LINE.match(line)
 189         if m:
 190             timestamp, indent, func, brace = m.groups()
 191             if found_end:
 192                 upto = func
 193                 break
 194             elif func == 'initf_bootstage() ':
 195                 found_start = True
 196                 expected_indent = indent + '  '
 197             elif found_start and indent == expected_indent and brace == '}':
 198                 found_end = True
 199
 200     # The next function after initf_bootstage() exits should be
 201     # initcall_is_event()
 202     assert upto == 'initcall_is_event()'
 203
 204     # Now look for initf_dm() and dm_timer_init() so we can check the bootstage
 205     # time
 206     cmd = f"trace-cmd report -l {trace_dat} |grep -E '(initf_dm|dm_timer_init)'"
 207     out = util.run_and_log(cons, ['sh', '-c', cmd])
 208
 209     start_timestamp = None
 210     end_timestamp = None
 211     for line in out.splitlines():
 212         m = RE_LINE.match(line)
 213         if m:
 214             timestamp, indent, func, brace = m.groups()
 215             if func == 'initf_dm() ':
 216                 start_timestamp = timestamp
 217             elif func == 'dm_timer_init() ':
 218                 end_timestamp = timestamp
 219                 break
 220     assert start_timestamp and end_timestamp
 221
 222     # Convert the time to microseconds
 223     return int((float(end_timestamp) - float(start_timestamp)) * 1000000)
 224
 225
 226 def check_flamegraph(cons, fname, proftool, map_fname, trace_fg):
 227     """Check that the 'flamegraph' output works
 228
 229     This spot checks a few call counts and estimates the time taken by the
 230     initf_dm() function
 231
 232     Args:
 233         cons (ConsoleBase): U-Boot console
 234         fname (str): Filename of trace file
 235         proftool (str): Filename of proftool
 236         map_fname (str): Filename of System.map
 237         trace_fg (str): Filename of output file
 238
 239     Returns:
 240         int: Approximate number of microseconds used by the initf_dm() function
 241     """
 242
 243     # Generate the flamegraph format
 244     out = util.run_and_log(
 245         cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname,
 246                'dump-flamegraph'])
 247
 248     # We expect dm_timer_init() to be called twice: once before relocation and
 249     # once after
 250     look1 = 'initf_dm;dm_timer_init 1'
 251     look2 = 'board_init_r;initcall_run_list;initr_dm_devices;dm_timer_init 1'
 252     found = 0
 253     with open(trace_fg, 'r') as fd:
 254         for line in fd:
 255             line = line.strip()
 256             if line == look1 or line == look2:
 257                 found += 1
 258     assert found == 2
 259
 260     # Generate the timing graph
 261     out = util.run_and_log(
 262         cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname,
 263                'dump-flamegraph', '-f', 'timing'])
 264
 265     # Add up all the time spend in initf_dm() and its children
 266     total = 0
 267     with open(trace_fg, 'r') as fd:
 268         for line in fd:
 269             line = line.strip()
 270             if line.startswith('initf_dm'):
 271                 func, val = line.split()
 272                 count = int(val)
 273                 total += count
 274     return total
 275
 276 check_flamegraph
 277 @pytest.mark.slow
 278 @pytest.mark.boardspec('sandbox')
 279 @pytest.mark.buildconfigspec('trace')
 280 def test_trace(u_boot_console):
 281     """Test we can build sandbox with trace, collect and process a trace"""
 282     cons = u_boot_console
 283
 284     if not os.path.exists(TMPDIR):
 285         os.mkdir(TMPDIR)
 286     proftool = os.path.join(cons.config.build_dir, 'tools', 'proftool')
 287     map_fname = os.path.join(cons.config.build_dir, 'System.map')
 288     trace_dat = os.path.join(TMPDIR, 'trace.dat')
 289     trace_fg = os.path.join(TMPDIR, 'trace.fg')
 290
 291     fname, dm_f_time = collect_trace(cons)
 292
 293     check_function(cons, fname, proftool, map_fname, trace_dat)
 294     trace_time = check_funcgraph(cons, fname, proftool, map_fname, trace_dat)
 295
 296     # Check that bootstage and funcgraph agree to within 10 microseconds
 297     diff = abs(trace_time - dm_f_time)
 298     print(f'trace_time {trace_time}, dm_f_time {dm_f_time}')
 299     assert diff / dm_f_time < 0.01
 300
 301     fg_time = check_flamegraph(cons, fname, proftool, map_fname, trace_fg)
 302
 303     # Check that bootstage and flamegraph agree to within 30%
 304     # This allows for CI being slow to run
 305     diff = abs(fg_time - dm_f_time)
 306     assert diff / dm_f_time < 0.3