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