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