ASoC: SOF: Intel: IPC: add IPC counters by jajanusz · Pull Request #955 · thesofproject/linux

jajanusz · 2019-05-16T21:01:05Z

Read IPC counters provided by firmware and log them on IPC timeout to help
debug.

Intended to work with thesofproject/sof#1441

Signed-off-by: Janusz Jankowski janusz.jankowski@linux.intel.com

jajanusz · 2019-05-16T21:43:28Z

I've decided to actually make PR of that, because we need to increase debug capabilities. Maybe it's not ultimate solution, but something we may start with.

The problem with this one is that it's too specific - it's literally for just proving that ipc handler on FW side did its job and didn't hand in ipc handler or irq. When we will want to debug other things we won't just add more registers in FW and then dump them in SW. It's not so practical.

Maybe we can add Kconfig option to dump whole window on error? This way when debugging FW we can add whatever we want in unused registers and we will be able to see them without changes in kernel code.
It's useful not only in cases like this one, but also for example on f.e. power-ons when you want to help integration teams, but they don't have enough knowledge to provide debug info - we can give them just modified FW and get logs for things that we cannot log with traces.

We should still consider traces as default logging/debugging - memwnd registers would be used for things that cannot use traces, f.e. before traces mechanism is even set up - for now we have only trace point, but sometimes it's not sufficient.

plbossart

Thanks @jajanusz, see below the comments, an update is needed to avoid polluting the SOF core with Hdaudio-specific stuff, otherwise it's a good fix to add.

plbossart · 2019-05-16T22:15:10Z

+
+		dev_dbg(sdev->dev, "ipc received: %u processed: %u\n",
+			ipc_rec, ipc_proc);
+


this should be dev_err()
Also it's only supported for HDaudio so the right place to add this log is in intel/hda.c (hda_ipc_dump)

Ok, you wrote that you want it on IPC timeout so I wanted to be it closer to ipc timeout message, but yea, it's not worth polluting ipc with hda for that, so i'll move it to hda.

@plbossart Moved it to hda_ipc_dump

Read IPC counters provided by firmware and log them on IPC timeout to help debug. Signed-off-by: Janusz Jankowski <janusz.jankowski@linux.intel.com>

plbossart

that was fast, thanks @jajanusz

RanderWang

Actually, hda_ipc_dump is only for apollolake, and the literal name is a little confusing.
please change cnl_ipc_dump also, this is for cannonlake, whiskylake, and icelake.

And would like me to help to check it on btytrail and broadwell ?

keyonjie · 2019-05-17T01:59:38Z

I've decided to actually make PR of that, because we need to increase debug capabilities. Maybe it's not ultimate solution, but something we may start with.

The problem with this one is that it's too specific - it's literally for just proving that ipc handler on FW side did its job and didn't hand in ipc handler or irq. When we will want to debug other things we won't just add more registers in FW and then dump them in SW. It's not so practical.

Maybe we can add Kconfig option to dump whole window on error? This way when debugging FW we can add whatever we want in unused registers and we will be able to see them without changes in kernel code.

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

It's useful not only in cases like this one, but also for example on f.e. power-ons when you want to help integration teams, but they don't have enough knowledge to provide debug info - we can give them just modified FW and get logs for things that we cannot log with traces.

We should still consider traces as default logging/debugging - memwnd registers would be used for things that cannot use traces, f.e. before traces mechanism is even set up - for now we have only trace point, but sometimes it's not sufficient.

keyonjie

No objection about the code itself since it will be printed at error case only, though I think this could be unnecessary since we already had this in the node /sys/kernel/debug/sof/regs.

jajanusz · 2019-05-17T07:04:02Z

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?

jajanusz · 2019-05-17T07:08:32Z

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?

@keyonjie If I see correctly it's in ipc_get_windows and it's called only on fw_ready. We need something that will be dumped on error also, f.e. on ipc timeout.

jajanusz · 2019-05-17T09:19:52Z

I've decided to actually make PR of that, because we need to increase debug capabilities. Maybe it's not ultimate solution, but something we may start with.
The problem with this one is that it's too specific - it's literally for just proving that ipc handler on FW side did its job and didn't hand in ipc handler or irq. When we will want to debug other things we won't just add more registers in FW and then dump them in SW. It's not so practical.
Maybe we can add Kconfig option to dump whole window on error? This way when debugging FW we can add whatever we want in unused registers and we will be able to see them without changes in kernel code.

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

It's useful not only in cases like this one, but also for example on f.e. power-ons when you want to help integration teams, but they don't have enough knowledge to provide debug info - we can give them just modified FW and get logs for things that we cannot log with traces.
We should still consider traces as default logging/debugging - memwnd registers would be used for things that cannot use traces, f.e. before traces mechanism is even set up - for now we have only trace point, but sometimes it's not sufficient.

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?

@keyonjie If I see correctly it's in ipc_get_windows and it's called only on fw_ready. We need something that will be dumped on error also, f.e. on ipc timeout.

Also it looks empty with default settings. Do I need to enable something in Kconfig?

xiulipan

@jajanusz
Please also do a similar patch to sound/soc/sof/intel/cnl.c for other cAVS platforms.

xiulipan · 2019-05-18T06:05:08Z

+	ipc_proc = snd_sof_dsp_read(sdev, HDA_DSP_BAR,
+				    HDA_DSP_SRAM_REG_FW_IPC_PROCESSED_COUNT);
+
+	dev_err(sdev->dev, "error: ipc received: %u processed: %u\n",


Suggested change

dev_err(sdev->dev, "error: ipc received: %u processed: %u\n",

dev_err(sdev->dev, "error: DSP ipc received: %u processed: %u\n",

xiulipan · 2019-05-18T06:06:03Z

 	dev_err(sdev->dev,
 		"error: host status 0x%8.8x dsp status 0x%8.8x mask 0x%8.8x\n",
 		hipcie, hipct, hipcctl);
+


@jajanusz
Please add some inline comments to explain what is doing here.

jajanusz · 2019-05-18T12:36:50Z

@xiulipan I'd like rather that some driver developer answer my questions that I asked first, because on them depends if it's really needed.

xiulipan · 2019-05-19T04:01:54Z

@jajanusz
What is your questions here?

Maybe we can add Kconfig option to dump whole window on error?

I only see this with question mark.

To answer this, this is called debugfs to us. And you can dump the hda and dsp debugfs file

/sys/kernel/debug/sof# ls
debug  dsp  etrace  exception  fw_version  hda  inbox  ipc_flood_count  ipc_flood_duration_ms  outbox  pp  regs  stream  trace

You can just read from this, they are always readable :)

And if you have some question for driver side feel free to ask and @ me. I will be glad to answer.

jajanusz · 2019-05-19T11:01:33Z

@xiulipan I meant all questions that I asked @keyonjie
I'll ask them again:

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?
If I see correctly it's in ipc_get_windows and it's called only on fw_ready. We need something that will be dumped on error also, f.e. on ipc timeout.
After test run it looks empty with default settings. Do I need to enable something in Kconfig?

keyonjie · 2019-05-20T01:07:25Z

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?

It's 4KB(the size come from FW_READY), the whole memory window. You can read back the latest value of it at any time after FW_READY.

keyonjie · 2019-05-20T01:09:18Z

@xiulipan I meant all questions that I asked @keyonjie
I'll ask them again:

We already had this, you can get the whole dump from the node /sys/kernel/debug/sof/regs.

But is it whole window (4kb?) or just few registers from the beginning? Also are there all memory windows or just first one?
If I see correctly it's in ipc_get_windows and it's called only on fw_ready. We need something that will be dumped on error also, f.e. on ipc timeout.
After test run it looks empty with default settings. Do I need to enable something in Kconfig?

No, you don't need enable anything in Kconfig, you can read back the latest value of it at any time after FW_READY:

test-Bobba:/root/# hexdump /sys/kernel/debug/sof/regs
0000000 0005 0000 d006 0dea 4000 0000 0000 0000
0000010 0000 0000 0000 0000 0000 0000 0000 0000
*
0001000

jajanusz · 2019-05-20T09:46:21Z

@plbossart @keyonjie Right, looks like we can use /sys/kernel/debug/sof/regs to get these values after FW_READY and AFAIK they are not needed before FW_READY, so we can drop this PR.

However we may still need some way to dump these values before FW_READY, for FW boot debugging. I don't know how kernel developers look at things like this, but maybe we can add some Kconfig option to dump registers on every error straight to the dmesg in case when error occurs before FW_READY.

jajanusz requested review from dbaluta, lgirdwood, lyakh and plbossart as code owners May 16, 2019 21:01

jajanusz commented May 16, 2019

View reviewed changes

Comment thread sound/soc/sof/intel/hda.h

jajanusz force-pushed the ipc-debug branch 2 times, most recently from daa60ce to 7ab1736 Compare May 16, 2019 21:29

plbossart requested changes May 16, 2019

View reviewed changes

ASoC: SOF: Intel: hda: add IPC counters

2ed6c89

Read IPC counters provided by firmware and log them on IPC timeout to help debug. Signed-off-by: Janusz Jankowski <janusz.jankowski@linux.intel.com>

jajanusz force-pushed the ipc-debug branch from 7ab1736 to 2ed6c89 Compare May 16, 2019 22:30

plbossart approved these changes May 16, 2019

View reviewed changes

plbossart requested review from RanderWang, bardliao, keyonjie and xiulipan May 17, 2019 01:04

RanderWang suggested changes May 17, 2019

View reviewed changes

keyonjie reviewed May 17, 2019

View reviewed changes

xiulipan suggested changes May 18, 2019

View reviewed changes

jajanusz closed this May 20, 2019

jajanusz mentioned this pull request May 20, 2019

cavs: ipc: added ipc received and processed counters thesofproject/sof#1441

Merged


		dev_dbg(sdev->dev, "ipc received: %u processed: %u\n",
		ipc_rec, ipc_proc);

	dev_err(sdev->dev, "error: ipc received: %u processed: %u\n",
	dev_err(sdev->dev, "error: DSP ipc received: %u processed: %u\n",

Conversation

jajanusz commented May 16, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

jajanusz commented May 16, 2019

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

plbossart May 16, 2019

Choose a reason for hiding this comment

Uh oh!

jajanusz May 16, 2019

Choose a reason for hiding this comment

Uh oh!

jajanusz May 16, 2019

Choose a reason for hiding this comment

Uh oh!

plbossart left a comment

Choose a reason for hiding this comment

Uh oh!

RanderWang left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

keyonjie commented May 17, 2019

Uh oh!

keyonjie left a comment

Choose a reason for hiding this comment

Uh oh!

jajanusz commented May 17, 2019

Uh oh!

jajanusz commented May 17, 2019

Uh oh!

jajanusz commented May 17, 2019

Uh oh!

xiulipan left a comment

Choose a reason for hiding this comment

Uh oh!

xiulipan May 18, 2019

Choose a reason for hiding this comment

Uh oh!

xiulipan May 18, 2019

Choose a reason for hiding this comment

Uh oh!

jajanusz commented May 18, 2019

Uh oh!

xiulipan commented May 19, 2019

Uh oh!

jajanusz commented May 19, 2019

Uh oh!

keyonjie commented May 20, 2019

Uh oh!

keyonjie commented May 20, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jajanusz commented May 20, 2019

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

jajanusz commented May 16, 2019 •

edited

Loading

RanderWang left a comment •

edited

Loading

keyonjie commented May 20, 2019 •

edited

Loading