[PATCH] test: test_trace.py: Handle newer trace-cmd report formats

With newer versions of trace-cmd we have another column in the report that we need to handle. We don't care about it, so just use a regex to remove it from the output that we then parse.
Signed-off-by: Tom Rini trini@konsulko.com --- test/py/tests/test_trace.py | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-)
diff --git a/test/py/tests/test_trace.py b/test/py/tests/test_trace.py index 28a6e72f525f..9cb5aa939c55 100644 --- a/test/py/tests/test_trace.py +++ b/test/py/tests/test_trace.py @@ -117,12 +117,17 @@ def check_function(cons, fname, proftool, map_fname, trace_dat): out = util.run_and_log(cons, ['sh', '-c', cmd])
# Format: - # unknown option 14 # u-boot-1 [000] 60.805596: function: initf_malloc # u-boot-1 [000] 60.805597: function: initf_malloc # u-boot-1 [000] 60.805601: function: initf_bootstage # u-boot-1 [000] 60.805607: function: initf_bootstage - lines = [line.replace(':', '').split() for line in out.splitlines()] + # OR: + # u-boot-1 [000] ..... 60.805596: function: initf_malloc + # u-boot-1 [000] ..... 60.805597: function: initf_malloc + # u-boot-1 [000] ..... 60.805601: function: initf_bootstage + # u-boot-1 [000] ..... 60.805607: function: initf_bootstage + + lines = [re.sub(r'(:|.....)', '', line).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 @@ -176,6 +181,7 @@ def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): # u-boot-1 [000] 282.101375: funcgraph_exit: 0.006 us | } # Then check for this: # u-boot-1 [000] 282.101375: funcgraph_entry: 0.000 us | initcall_is_event(); + # And this all may be '[000] ..... 282.' instead.
expected_indent = None found_start = False @@ -185,7 +191,7 @@ def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): # 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) + m = RE_LINE.match(re.sub(r'.....', '', line)) if m: timestamp, indent, func, brace = m.groups() if found_end: @@ -209,7 +215,7 @@ def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): start_timestamp = None end_timestamp = None for line in out.splitlines(): - m = RE_LINE.match(line) + m = RE_LINE.match(re.sub(r'.....', '', line)) if m: timestamp, indent, func, brace = m.groups() if func == 'initf_dm() ':

With newer versions of trace-cmd the report subcommand will have different output from before if we do or do not pass -l. However, with the -l flag passed our put is consistent here. This updates our regular expressions and comments for this as well now.
Signed-off-by: Tom Rini trini@konsulko.com --- Changes in v2: - Use the -l flag to have consistent output for either version --- test/py/tests/test_trace.py | 32 ++++++++++++++++---------------- 1 file changed, 16 insertions(+), 16 deletions(-)
diff --git a/test/py/tests/test_trace.py b/test/py/tests/test_trace.py index 28a6e72f525f..7c5696ce747f 100644 --- a/test/py/tests/test_trace.py +++ b/test/py/tests/test_trace.py @@ -12,7 +12,7 @@ import u_boot_utils as util TMPDIR = '/tmp/test_trace'
# Decode a function-graph line -RE_LINE = re.compile(r'.*[000]\s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$') +RE_LINE = re.compile(r'.*0..... \s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$')
def collect_trace(cons): @@ -113,15 +113,15 @@ def check_function(cons, fname, proftool, map_fname, trace_dat): assert val > 50000 # Should be at least 50KB of symbols
# Check that the trace has something useful - cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_|initr_)'" + cmd = f"trace-cmd report -l {trace_dat} |grep -E '(initf_|initr_)'" out = util.run_and_log(cons, ['sh', '-c', cmd])
# Format: - # unknown option 14 - # u-boot-1 [000] 60.805596: function: initf_malloc - # u-boot-1 [000] 60.805597: function: initf_malloc - # u-boot-1 [000] 60.805601: function: initf_bootstage - # u-boot-1 [000] 60.805607: function: initf_bootstage + # 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 @@ -161,21 +161,21 @@ def check_funcgraph(cons, fname, proftool, map_fname, trace_dat): 'dump-ftrace', '-f', 'funcgraph'])
# Check that the trace has what we expect - cmd = f'trace-cmd report {trace_dat} |head -n 70' + cmd = f'trace-cmd report -l {trace_dat} |head -n 70' out = util.run_and_log(cons, ['sh', '-c', cmd])
# First look for this: - # u-boot-1 [000] 282.101360: funcgraph_entry: 0.004 us | initf_malloc(); + # u-boot-1 0..... 282.101360: funcgraph_entry: 0.004 us | initf_malloc(); # ... - # u-boot-1 [000] 282.101369: funcgraph_entry: | initf_bootstage() { - # u-boot-1 [000] 282.101369: funcgraph_entry: | bootstage_init() { - # u-boot-1 [000] 282.101369: funcgraph_entry: | dlmalloc() { + # 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 [000] 282.101375: funcgraph_exit: 0.001 us | } + # u-boot-1 0..... 282.101375: funcgraph_exit: 0.001 us | } # Then look for this: - # u-boot-1 [000] 282.101375: funcgraph_exit: 0.006 us | } + # u-boot-1 0..... 282.101375: funcgraph_exit: 0.006 us | } # Then check for this: - # u-boot-1 [000] 282.101375: funcgraph_entry: 0.000 us | initcall_is_event(); + # u-boot-1 0..... 282.101375: funcgraph_entry: 0.000 us | initcall_is_event();
expected_indent = None found_start = False @@ -203,7 +203,7 @@ def check_funcgraph(cons, fname, proftool, map_fname, trace_dat):
# Now look for initf_dm() and dm_timer_init() so we can check the bootstage # time - cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_dm|dm_timer_init)'" + cmd = f"trace-cmd report -l {trace_dat} |grep -E '(initf_dm|dm_timer_init)'" out = util.run_and_log(cons, ['sh', '-c', cmd])
start_timestamp = None

On Wed, 17 Jan 2024 17:12:36 -0500, Tom Rini wrote:
With newer versions of trace-cmd the report subcommand will have different output from before if we do or do not pass -l. However, with the -l flag passed our put is consistent here. This updates our regular expressions and comments for this as well now.
Applied to u-boot/master, thanks!
participants (1)
-
Tom Rini