1# SPDX-License-Identifier: GPL-2.0
2# Copyright 2022 Google LLC
3# Written by Simon Glass <sjg@chromium.org>
4
5import os
6import pytest
7import re
8
9import u_boot_utils as util
10
11# This is needed for Azure, since the default '..' directory is not writeable
12TMPDIR = '/tmp/test_trace'
13
14# Decode a function-graph line
15RE_LINE = re.compile(r'.*0\.\.\.\.\. \s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$')
16
17
18def 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
73def 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
144def 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
226def 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
276check_flamegraph
277@pytest.mark.slow
278@pytest.mark.boardspec('sandbox')
279@pytest.mark.buildconfigspec('trace')
280def 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
307