tools: sof_perf_analyzer: fix widget ID parsing error #1122

btian1 · 2023-10-31T08:10:21Z

In existing code, we parse component name from the line
that contains 'Create widget', and component ID from the
next line, which normally is the ipc tx message:

Create widget host-copier.0.playback instance 0 - pipe 1 - core 0
ipc tx : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84]

However, due to the concurrent nature of linux kernel, the
assumption that Create widget message and ipc tx message
are always adjacent is wrong. An exception will be raised
if the next line is not the 'ipc tx' message.

The first step to fix the issue is to make a kernel PR to print
all the information we need in a single 'Create widget' line,
thus to avoid the requirement for multiple lines of kernel message,
see thesofproject/linux#4709.

And next，this patch will parse the new 'Create widget' line to
get component name and ID.

tools/sof_perf_analyzer.py

marc-hb · 2023-11-04T00:17:44Z

Long before we search the info in a different place, could we have a "quicker fix" where the entire script does not crash but replaces the missing ID with some "Unknown" category or something?

tools/sof_perf_analyzer.py

aiChaoSONG · 2023-11-08T07:48:17Z

tools/sof_perf_analyzer.py

+    comp_peak_max_cycles = perf_info.groupby('COMP_ID')['CPU_PEAK'].max()
+    perf_stats['MODULE_CPC'] = comp_peak_max_cycles


perf_stats['MODULE_CPC'] = perf_info.groupby('COMP_ID')['CPU_PEAK'].max() single line is good.

Let's make this commit a standalone PR, because

it has nothing to do with widget id issue

it can be merged quickly

commit message:

Previously, module CPC is calculated by multiplying the mean value of cpu_peak with a margin scalar, after internal technical discussion, change module CPC to the maximum value of module's cpu_peak as aligned.

aiChaoSONG · 2023-11-08T07:50:10Z

@btian1 For the widget id issue, I am afraid we have to refine code and comments according Marc's review comments. Let's sync tomorrow.

tools/sof_perf_analyzer.py

plbossart

no idea what this is about

tools/sof_perf_analyzer.py

plbossart · 2023-11-10T22:02:00Z

"When there is no widget ID in kernel logs, try to find the widget ID in bind related logs."

Has anyone tried to change the kernel logs to make the problem go away?

marc-hb

in both create widget and bind message parsing, two lines are involved. we cannot assume it is atomic. because the concurrent nature of the linux kernel.
[...]
there is still probability a component in the topology is missing in our comp_name dict, but the probability is low as we parse more and more information

I just had a quick chat with @plbossart and he told me that there has been zero attempt to simplify the kernel logs... is this real?

tools/sof_perf_analyzer.py

marc-hb

It's rather disappointing that after multiple asks I still get this sort of raw dump of information without clarity on the problem statement. This is starting to be a waste of everyone's time if I am honest. - @plbossart

About two weeks ago, 4 days after this PR was first submitted, I asked this:
#1122 (comment)

Which cases? And what exactly is missing in these cases and why? An entire line and if yes which one? A part of a line and if yes which part? You must be much more specific, otherwise it's impossible to review the code without knowing what it is trying to parse.

That question was marked as "resolved" without an answer.

At the same time I asked basically the same question in #1108. No answer either.

It's pointless to submit a fix to a problem that has not been analyzed, understood and explained. It's called "programming by coincidence".

Why are the kernel logs incomplete, how and when?
Why can't the kernel logs be fixed instead? Or at least made somewhat better.

Don't answer in this PR here, answer in the bug 1108

aiChaoSONG · 2023-11-21T09:34:10Z

tools/sof_perf_analyzer.py

+    Create pipeline pipeline.3 (pipe 3) - instance 3, core 0
+
+    [   59.622645] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3:
+    Create widget host-copier.0.capture (pipe 3) - ID 4, instance 3, core 0



'''Process the dmesg to get component ID to component name mapping, they are acquired from the line that contains 'Create widget': EXAMPLE_OF_CREATE_WIDGWT_LINE By design in the kernel, pipeline ID is the instance ID of pipeline widget, so it is acquired from the line that contains 'Create pipeline': EXAMPLE_OF_CREATE_PIPELINE_LINE '''

aiChaoSONG · 2023-11-21T09:35:38Z

tools/sof_perf_analyzer.py

+                # with sof kernel PR: https://github.com/thesofproject/linux/pull/4709
+                # pipeline and module creation are using separate print in kernle log.
+                # So, for pipeline case, pipeline instance ID will be extracted from pipeline
+                # logs. For module creation, module instance ID and module ID will be
+                # extracted accordingly.
+                # ppln_id, widget_id and widget instance ID will be combined together to
+                # column COMP_ID as the unique ID for each module inside pipelines.


keep my original comments, it explains why instance id of pipeline widget is the widget pipeline id for the widgets of the pineline

aiChaoSONG · 2023-11-21T09:39:12Z

tools/sof_perf_analyzer.py

+                module_instance_id = int(line_split[7][:-1])
+                widget_id = int(line_split[5][:-1])


explain [:-1] with a simple comment.

aiChaoSONG · 2023-11-21T09:39:26Z

tools/sof_perf_analyzer.py

-                widget_id = next_line.split('|')[0].split(':')[-1].strip()
-                # convert to the same ID format in mtrace
-                widget_id = int('0x' + widget_id[-6:], 16)
+                    ppln_id = int(line_split[5][:-1])


explain [:-1], no one know why if you don't explain.
# remove ending comma(,) with [:-1]

aiChaoSONG

Commit title and body:

tools: sof_perf_analyzer: fix widget ID parsing error

In existing code, we parse component name from the line
that contains 'Create widget', and component ID from the
next line, which normally is the ipc tx message:

Create widget host-copier.0.playback instance 0 - pipe 1 - core 0
ipc tx      : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84]

However, due to the concurrent nature of linux kernel, the
assumption that `Create widget` message and `ipc tx` message
are always adjacent is wrong. An exception will be raised
if the next line is not the 'ipc tx' message.

The first step to fix the issue is to make a kernel PR to print
all the information we need in a single 'Create widget' line,
thus to avoid the requirement for multiple lines of kernel message, 
see https://github.com/thesofproject/linux/pull/4709.

And next，this patch will parse the new 'Create widget' line to
get component name and ID.

Fixes: https://github.com/thesofproject/sof-test/issues/1108

Always describe the issue (what), root cause of the issue (why), and how it is fixed(how).

In existing code, we parse component name from the line that contains 'Create widget', and component ID from the next line, which normally is the ipc tx message: Create widget host-copier.0.playback instance 0 - pipe 1 - core 0 ipc tx : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84] However, due to the concurrent nature of linux kernel, the assumption that `Create widget` message and `ipc tx` message are always adjacent is wrong. An exception will be raised if the next line is not the 'ipc tx' message. The first step to fix the issue is to make a kernel PR to print all the information we need in a single 'Create widget' line, thus to avoid the requirement for multiple lines of kernel message, see thesofproject/linux#4709. And next，this patch will parse the new 'Create widget' line to get component name and ID. Fixes: thesofproject#1108 Signed-off-by: Baofeng Tian <[email protected]> Signed-off-by: Chao Song <[email protected]>

aiChaoSONG · 2023-11-23T08:19:15Z

see internal test report 35019， test result is good.

dismiss as resolved

btian1 requested a review from a team as a code owner October 31, 2023 08:10

btian1 force-pushed the fix_widget_id branch from 07b6a37 to 39e4e17 Compare October 31, 2023 08:18

aiChaoSONG suggested changes Oct 31, 2023

View reviewed changes

btian1 force-pushed the fix_widget_id branch 2 times, most recently from 1a41d4c to 64ad709 Compare November 3, 2023 03:12

marc-hb requested changes Nov 3, 2023

View reviewed changes

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

tools/sof_perf_analyzer.py Show resolved Hide resolved

btian1 force-pushed the fix_widget_id branch from 64ad709 to 07661b0 Compare November 6, 2023 01:44

marc-hb requested changes Nov 7, 2023

View reviewed changes

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

tools/sof_perf_analyzer.py Show resolved Hide resolved

btian1 force-pushed the fix_widget_id branch from c0d8de8 to 624dd9c Compare November 7, 2023 02:31

btian1 requested review from marc-hb and aiChaoSONG November 7, 2023 02:31

aiChaoSONG reviewed Nov 8, 2023

View reviewed changes

btian1 force-pushed the fix_widget_id branch from 624dd9c to f3104d3 Compare November 9, 2023 05:15

aiChaoSONG previously approved these changes Nov 9, 2023

View reviewed changes

marc-hb requested changes Nov 10, 2023

View reviewed changes

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

plbossart previously requested changes Nov 10, 2023

View reviewed changes

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

marc-hb requested changes Nov 10, 2023

View reviewed changes

plbossart reviewed Nov 10, 2023

View reviewed changes

tools/sof_perf_analyzer.py Outdated Show resolved Hide resolved

btian1 dismissed aiChaoSONG’s stale review via 19a0efc November 13, 2023 05:20

btian1 force-pushed the fix_widget_id branch from f3104d3 to 19a0efc Compare November 13, 2023 05:20

marc-hb previously requested changes Nov 14, 2023

View reviewed changes

btian1 marked this pull request as draft November 20, 2023 07:25

btian1 force-pushed the fix_widget_id branch from 19a0efc to 5076036 Compare November 21, 2023 08:04

btian1 changed the title ~~audio: perf: fix no widget ID case in kernel logs~~ tools: sof_perf_analyzer: fix no widget ID issue on SDW platform Nov 21, 2023

btian1 requested review from plbossart, bardliao and ranj063 November 21, 2023 08:05

btian1 requested review from marc-hb, ujfalusi and aiChaoSONG November 21, 2023 08:05

btian1 force-pushed the fix_widget_id branch from 5076036 to 63e6317 Compare November 21, 2023 08:09

btian1 marked this pull request as ready for review November 21, 2023 08:10

aiChaoSONG reviewed Nov 21, 2023

View reviewed changes

aiChaoSONG suggested changes Nov 21, 2023

View reviewed changes

btian1 force-pushed the fix_widget_id branch from 63e6317 to d581c89 Compare November 22, 2023 02:44

btian1 changed the title ~~tools: sof_perf_analyzer: fix no widget ID issue on SDW platform~~ tools: sof_perf_analyzer: fix widget ID parsing error Nov 22, 2023

btian1 force-pushed the fix_widget_id branch from d581c89 to 9d2f437 Compare November 22, 2023 02:47

btian1 requested a review from aiChaoSONG November 22, 2023 02:53

btian1 force-pushed the fix_widget_id branch from 9d2f437 to 6720c04 Compare November 22, 2023 03:13

aiChaoSONG approved these changes Nov 23, 2023

View reviewed changes

aiChaoSONG merged commit 6b35e10 into thesofproject:main Nov 23, 2023
3 of 6 checks passed

marc-hb mentioned this pull request Dec 28, 2023

[BUG] check-performance.sh failed with ValueError: invalid literal for int() #1108

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tools: sof_perf_analyzer: fix widget ID parsing error #1122

tools: sof_perf_analyzer: fix widget ID parsing error #1122

btian1 commented Oct 31, 2023 •

edited

Loading

marc-hb commented Nov 4, 2023 •

edited

Loading

aiChaoSONG Nov 8, 2023 •

edited

Loading

aiChaoSONG commented Nov 8, 2023

plbossart left a comment

plbossart commented Nov 10, 2023

marc-hb left a comment •

edited

Loading

marc-hb left a comment •

edited

Loading

aiChaoSONG Nov 21, 2023 •

edited

Loading

aiChaoSONG Nov 21, 2023

aiChaoSONG Nov 21, 2023 •

edited

Loading

aiChaoSONG Nov 21, 2023 •

edited

Loading

aiChaoSONG left a comment

aiChaoSONG commented Nov 23, 2023

		comp_peak_max_cycles = perf_info.groupby('COMP_ID')['CPU_PEAK'].max()
		perf_stats['MODULE_CPC'] = comp_peak_max_cycles

		module_instance_id = int(line_split[7][:-1])
		widget_id = int(line_split[5][:-1])

tools: sof_perf_analyzer: fix widget ID parsing error #1122

tools: sof_perf_analyzer: fix widget ID parsing error #1122

Conversation

btian1 commented Oct 31, 2023 • edited Loading

marc-hb commented Nov 4, 2023 • edited Loading

aiChaoSONG Nov 8, 2023 • edited Loading

Choose a reason for hiding this comment

aiChaoSONG commented Nov 8, 2023

plbossart left a comment

Choose a reason for hiding this comment

plbossart commented Nov 10, 2023

marc-hb left a comment • edited Loading

Choose a reason for hiding this comment

marc-hb left a comment • edited Loading

Choose a reason for hiding this comment

aiChaoSONG Nov 21, 2023 • edited Loading

Choose a reason for hiding this comment

aiChaoSONG Nov 21, 2023

Choose a reason for hiding this comment

aiChaoSONG Nov 21, 2023 • edited Loading

Choose a reason for hiding this comment

aiChaoSONG Nov 21, 2023 • edited Loading

Choose a reason for hiding this comment

aiChaoSONG left a comment

Choose a reason for hiding this comment

aiChaoSONG commented Nov 23, 2023

btian1 commented Oct 31, 2023 •

edited

Loading

marc-hb commented Nov 4, 2023 •

edited

Loading

aiChaoSONG Nov 8, 2023 •

edited

Loading

marc-hb left a comment •

edited

Loading

marc-hb left a comment •

edited

Loading

aiChaoSONG Nov 21, 2023 •

edited

Loading

aiChaoSONG Nov 21, 2023 •

edited

Loading

aiChaoSONG Nov 21, 2023 •

edited

Loading