ASoC/SoundWire: improve dmesg logs #3631

plbossart · 2022-05-03T20:41:24Z

make messages unique, remove useless logs and add more information for useful messages

The same debug message is replicated multiple time, add __func__ to figure out what link is ignored. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

ujfalusi

@plbossart, it is good to have meaningful debug prints, but I'm not sure about the core dtrace and tx print changes

ujfalusi · 2022-05-04T06:44:47Z

sound/soc/sof/ipc3.c

Better to use the flag itself here so we don't need to look back what it is?

I kind of liked this noise as we can see that new data is coming in via dtrace from firmware. If the sof-logger came back with empty log we can see in the dmesg if we have aver received the position update.
I still have the two dtrace PRs open to print the new positions... (#3516)

you still have this capability, it's just not there by default. I think we have to separate out debugging the trace and debugging firmware, if we have all logs all the time it just makes it harder for everyone, and we have already too many logs.

Better to use the flag itself here so we don't need to look back what it is?

I used this to avoid a 100+ line. I can move the definition down but it'll look ugly. I don't have a good solution.

direct use would put it to 92, but surely it looks a bit out of place, but not too much.

switch (glb) { case SOF_IPC_GLB_TRACE_MSG: str = "GLB_TRACE_MSG"; switch (type) { case SOF_IPC_TRACE_DMA_PARAMS: str2 = "DMA_PARAMS"; break; case SOF_IPC_TRACE_DMA_POSITION: if (sof_debug_check_flag(SOF_DBG_SQUELCH_DMA_POSITION_UPDATE_LOGS)) return; str2 = "DMA_POSITION"; break; case SOF_IPC_TRACE_DMA_PARAMS_EXT: str2 = "DMA_PARAMS_EXT"; break; case SOF_IPC_TRACE_FILTER_UPDATE: str2 = "FILTER_UPDATE"; break; case SOF_IPC_TRACE_DMA_FREE: str2 = "DMA_FREE"; break; default: str2 = "unknown type"; break; } break;

Opt-in version of the flag would be 93

ujfalusi · 2022-05-04T06:51:24Z

sound/soc/sof/ipc3.c

I think we had this debate in past: which one is more important, the start of the TX or the end of the TX. Back then I proposed to drop the start and print either the success or the error when it is done to remove the duplication.

But in some cases it is interesting to know how long a tx took and if we had an RX between the start and the completion of the TX.

We can't continue with all logs enabled @ujfalusi, it's not sustainable for production CI.

We would still see if an RX IPC happened between the start of the TX IPC and the RX IPC error.

We could add a flag to make the success printed optionally if that helps.

Sure, but this is also the case when the verbose printing is enabled in kernel config.
Dropping the success message is fine I think. No message == all is good.

The same message was added twice for dai and link_dma, remove the latter one and add dai name and direction to better understand problematic sequences. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

Add the same debug message for IPC4 and IPC3 for consistency. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

plbossart · 2022-05-04T19:03:29Z

@ujfalusi I kept the logs as is but disabled them by default. You can still debug the IPC and trace the same way, just with the added step of changing the sof_debug kernel parameter.

If we want more logs, we have to switch to tracepoints.

greg-intel · 2022-05-04T21:14:15Z

Jenkins failed to run the sofkernel_prs job, I'm fixing it now @plbossart and then I'll run the test again.

greg-intel · 2022-05-04T21:33:29Z

SOFCI TEST

marc-hb · 2022-05-04T22:58:22Z

https://sof-ci.01.org/linuxpr/PR3631/build100/devicetest/?model=WHL_UPEXT_HDA_ZEPHYR&testcase=check-suspend-resume-with-playback-5 is all PASS except for the recent and unfortunately frequent suspend/resume issue on WHL

sound/soc/sof/core.c

ujfalusi · 2022-05-05T06:45:27Z

sound/soc/sof/ipc3.c

direct use would put it to 92, but surely it looks a bit out of place, but not too much.

switch (glb) { case SOF_IPC_GLB_TRACE_MSG: str = "GLB_TRACE_MSG"; switch (type) { case SOF_IPC_TRACE_DMA_PARAMS: str2 = "DMA_PARAMS"; break; case SOF_IPC_TRACE_DMA_POSITION: if (sof_debug_check_flag(SOF_DBG_SQUELCH_DMA_POSITION_UPDATE_LOGS)) return; str2 = "DMA_POSITION"; break; case SOF_IPC_TRACE_DMA_PARAMS_EXT: str2 = "DMA_PARAMS_EXT"; break; case SOF_IPC_TRACE_FILTER_UPDATE: str2 = "FILTER_UPDATE"; break; case SOF_IPC_TRACE_DMA_FREE: str2 = "DMA_FREE"; break; default: str2 = "unknown type"; break; } break;

ujfalusi · 2022-05-05T06:46:34Z

sound/soc/sof/ipc3.c

Opt-in version of the flag would be 93

ujfalusi · 2022-05-05T06:48:29Z

sound/soc/sof/ipc3.c

Sure, but this is also the case when the verbose printing is enabled in kernel config.
Dropping the success message is fine I think. No message == all is good.

We currently log the initiation of an IPC as well at its success. [ 3906.106987] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG [ 3906.107189] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG This is overkill in most cases, we already have a message thrown in case of errors and have tracepoints enabled to check for IPC duration. The only case where this might be useful is to check if there is an interleaved IPC RX. Add a flag and only print those logs if enabled. In addition, the DMA_POSITION_UPDATE for traces brings limited information in most cases and pollutes the logs for no good reason. [ 3906.322256] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3906.322308] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3906.822261] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3906.822319] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3907.822261] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3907.822319] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3908.822251] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION [ 3908.822309] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION This information is only helpful when debugging the trace support, not when using the trace. Add a flag to only print DMA position update logs if enabled. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

ujfalusi

Only one request to hide the ipc rx done along with the tx success.

ujfalusi · 2022-05-06T06:18:37Z

sound/soc/sof/ipc3.c

 		} else {
-			ipc3_log_header(sdev->dev, "ipc tx succeeded", hdr->cmd);
+			if (sof_debug_check_flag(SOF_DBG_PRINT_IPC_SUCCESS_LOGS))
+				ipc3_log_header(sdev->dev, "ipc tx succeeded", hdr->cmd);


@plbossart, can we do the same for rx at the end of sof_ipc3_rx_msg():

if (sof_debug_check_flag(SOF_DBG_PRINT_IPC_SUCCESS_LOGS)) ipc3_log_header(sdev->dev, "ipc rx done", hdr.cmd);

we can, it's just that I don't see a parallel between rx and tx.

for tx, we start the IPC and will get an error.

What happens for RX if someone the IPC handling goes south?

@ujfalusi can you comment on this one? I am not sure what you are asking for.

@plbossart, I would expect it to report an error when handling the received message, but OK, let's leave that one out for now.

soundwire: intel: uniquify debug message

79a45c0

The same debug message is replicated multiple time, add __func__ to figure out what link is ignored. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

plbossart requested review from RanderWang, ajitkupandey, bardliao, dbaluta, jack-cy-yu, juimonen, kuanhsuncheng, kv2019i, lgirdwood, libinyang, lyakh, oder-chiou, ranj063, ryans-lee, shumingfan, ujfalusi and yaochunhung as code owners May 3, 2022 20:41

plbossart force-pushed the fix/improve-dmesg-logs branch from 60c46a9 to d250e1d Compare May 3, 2022 21:52

marc-hb mentioned this pull request May 3, 2022

ASoC: SOF: reduce verbosity of IPC logs #3625

Closed

ujfalusi reviewed May 4, 2022

View reviewed changes

plbossart added 2 commits May 4, 2022 13:49

ASoC: SOF: Intel: hda-dai: enhance debug messages

e1b181e

The same message was added twice for dai and link_dma, remove the latter one and add dai name and direction to better understand problematic sequences. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

fixup! ASoC: SOF: IPC4: set the BE DAI ops

bd7d302

Add the same debug message for IPC4 and IPC3 for consistency. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

plbossart force-pushed the fix/improve-dmesg-logs branch from d250e1d to ea853bb Compare May 4, 2022 19:01

ujfalusi reviewed May 5, 2022

View reviewed changes

plbossart force-pushed the fix/improve-dmesg-logs branch from ea853bb to c162e51 Compare May 5, 2022 20:41

plbossart removed the request for review from yaochunhung May 5, 2022 20:41

ujfalusi requested changes May 6, 2022

View reviewed changes

ranj063 approved these changes May 6, 2022

View reviewed changes

marc-hb mentioned this pull request May 10, 2022

Hung task timeout reported by CI #3387

Closed

ujfalusi self-requested a review May 11, 2022 08:18

ujfalusi approved these changes May 11, 2022

View reviewed changes

plbossart merged commit 9598f4e into thesofproject:topic/sof-dev May 11, 2022

ASoC/SoundWire: improve dmesg logs #3631

ASoC/SoundWire: improve dmesg logs #3631

Uh oh!

Conversation

plbossart commented May 3, 2022

Uh oh!

ujfalusi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

plbossart commented May 4, 2022

Uh oh!

greg-intel commented May 4, 2022

Uh oh!

greg-intel commented May 4, 2022

Uh oh!

marc-hb commented May 4, 2022

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ujfalusi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants