Skip to content

fix: tools: faulty mtrace lines do not fail script #1343

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
ekurdybx wants to merge 1 commit into
base: main
Choose a base branch
from
+26 −19
Open

fix: tools: faulty mtrace lines do not fail script #1343

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 26 additions & 19 deletions tools/sof_perf_analyzer.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -109,6 +109,21 @@ def skip_to_first_trace(trace_item_gen: TraceItemGenerator):
return item
return next(trace_item_gen)

def get_timestamp_from_line(line, span_end_pos):
try:
timestamp = float(line[span_end_pos - 19: span_end_pos - 7].strip())
# Support for CONFIG_LOG_OUTPUT_FORMAT_TIME_TIMESTAMP - For when default Zephyr timestamp format is used
except ValueError:
h, m, rest = line[span_end_pos - 23: span_end_pos - 7].strip().split(':')
s1, s2 = rest.split(',')
s = s1+s2
timestamp = timedelta(
hours=int(h),
minutes=int(m),
seconds=float(s)
).total_seconds()
return timestamp

def make_trace_item(fileio: TextIO) -> TraceItemGenerator:
'''Filter and parse a line of trace in string form into TraceItem object, for example:
'[ 2.566046] <inf> component: comp_copy: comp:0 0x40000 perf comp_copy samples
Expand All @@ -134,26 +149,18 @@ def make_trace_item(fileio: TextIO) -> TraceItemGenerator:
# second trace from the line. This is done by regarding the end position
# of the matched substring as sentinel, timestamp and trace level are
# both some specific offset from the sentinel.
span_end_pos = match_obj.span()[1]
trace_lvl = line[span_end_pos - 4: span_end_pos - 1]
try:
timestamp = float(line[span_end_pos - 19: span_end_pos - 7].strip())
# Support for CONFIG_LOG_OUTPUT_FORMAT_TIME_TIMESTAMP - For when default Zephyr timestamp format is used
except ValueError:
h, m, rest = line[span_end_pos - 23: span_end_pos - 7].strip().split(':')
s1, s2 = rest.split(',')
s = s1+s2
timestamp = timedelta(
hours=int(h),
minutes=int(m),
seconds=float(s)
).total_seconds()

# The rest after removing timestamp and log level
rest = line[span_end_pos + 1:].split(': ')
ctx, func = rest[0:2]
msg = ': '.join(rest[2:]).strip()
yield TraceItem(timestamp, trace_lvl, ctx, func, msg)
span_end_pos = match_obj.span()[1]
trace_lvl = line[span_end_pos - 4: span_end_pos - 1]
timestamp = get_timestamp_from_line(line, span_end_pos)

# The rest after removing timestamp and log level
rest = line[span_end_pos + 1:].split(': ')
ctx, func = rest[0:2]
msg = ': '.join(rest[2:]).strip()
yield TraceItem(timestamp, trace_lvl, ctx, func, msg)
except Exception as e: # pylint: disable=W0718
Copy link
Collaborator

@marc-hb marc-hb Feb 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ironic how W0718 warns about precisely the type of "green failure" issues that this PR is trying to fix... Why not simply catch the specific parsing exception?

Copy link
Contributor Author

@ekurdybx ekurdybx Feb 5, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This script is a additional tool for getting stats from mtrace file, not a main test. That's why we decided to "ignore" lines that couldn't be parsed for whatever reason - hence the broad exception.

print(f"WARNING: Couldn't parse line: {line}, error: {e}")

def process_trace_file():
'''The top-level caller for processing the trace file'''
Expand Down