Skip to content

ASoC: SOF: ipc4-mtrace: resync host_read_ptr on debugfs open #5690

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
majunkier wants to merge 2 commits into
base: topic/sof-dev
Choose a base branch
from
Open

ASoC: SOF: ipc4-mtrace: resync host_read_ptr on debugfs open #5690

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
4b9d08c
ASoC: SOF: ipc4-mtrace: resync host_read_ptr on debugfs open
majunkier Mar 4, 2026
8250dee
Add debug for slot pointer drift detection
majunkier Mar 12, 2026
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
28 changes: 28 additions & 0 deletions sound/soc/sof/ipc4-mtrace.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -109,6 +109,20 @@ static int sof_ipc4_mtrace_dfs_open(struct inode *inode, struct file *file)
return -ENOMEM;
}

/*
* Re-sync dsp_write_ptr from SRAM on open to avoid blocking when
* DSP goes idle before next aging timer IPC arrives.
*/
if (core_data->slot_offset != SOF_IPC4_INVALID_SLOT_OFFSET) {
struct snd_sof_dev *sdev = core_data->sdev;
u32 write_ptr;

sof_mailbox_read(sdev, core_data->slot_offset + sizeof(u32),
&write_ptr, sizeof(write_ptr));
write_ptr -= write_ptr % 4;
core_data->dsp_write_ptr = write_ptr;
Copy link
Collaborator

@ujfalusi ujfalusi Mar 10, 2026

Choose a reason for hiding this comment

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

The commit message also needs update.

But something is not quite right in the description. The dsp_write_ptr is updated for the NOTIFY_LOG_BUFFER_STATUS in sof_ipc4_mtrace_update_pos(), it is done regardless if reader is active or not, but if there is one active then it is woken up to read out the data.

Copy link
Author

@majunkier majunkier Mar 10, 2026

Choose a reason for hiding this comment

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

you right i will fix msg

Copy link
Collaborator

@ujfalusi ujfalusi Mar 11, 2026

Choose a reason for hiding this comment

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

out of curiosity, can you debug this a bit further?
read the write and read ptr from the slot and then compare it with the ptr value tracked in core_data and if they differ print them out.
Something is not adding up here.

Copy link
Author

@majunkier majunkier Mar 12, 2026

Choose a reason for hiding this comment

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

ok, i added debug (added as a part of this PR temporary), which reveal other issue:

output catch
core0 ptr mismatch: slot r/w 0xffffffff/0xfffffffc vs cached r/w 0x0/0xfffffffc
slot_read_ptr = 0xffffffff uninitialized SRAM
slot_write_ptr = 0xfffffffc synchronized
cached host_read_ptr = 0x0 kernel memory

In sof_ipc4_mtrace_dfs_open() kernel initializes core_data->host_read_ptr = 0 in local memory but never write value to SRAM, first SRAM write is in sof_ipc4_mtrace_dfs_read() after consuming data.

so problem looks like desync kernel and dsp.
kernel core_data->host_read_ptr = 0
SRAM slot[offset+0] = 0xffffffff
DSP reads from SRAM slot_read_ptr = 0xffffffff
DSP calculates free_space = (0xffffffff - 0xfffffffc - 1) = 2 bytes
DSP thinks buffer is full so posibility of dropped logs

possible solution : Write cached 0x0 value to SRAM in sof_ipc4_mtrace_dfs_open()

@ujfalusi could you take a look if i understand it correctly ?

Copy link
Collaborator

@ujfalusi ujfalusi Mar 12, 2026

Choose a reason for hiding this comment

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

looks like the fw is not initializing the slot at init, so both host_ptr and dsp_ptr is 0xffffffff and it is using these in mtrace_out [1]

As I recall when the mtrace feature was added, the fw did a reset of the ptrs on init.

[1] https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/logging/backends/log_backend_adsp_mtrace.c#L107

Copy link
Collaborator

@ujfalusi ujfalusi Mar 12, 2026

Choose a reason for hiding this comment

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

@majunkier, @kv2019i, this diff in zephyr makes for a huge difference with unpatched kernel mtrace code!

diff --git a/subsys/logging/backends/log_backend_adsp_mtrace.c b/subsys/logging/backends/log_backend_adsp_mtrace.c
index bbceefa4a29d..11c1a8542bd7 100644
--- a/subsys/logging/backends/log_backend_adsp_mtrace.c
+++ b/subsys/logging/backends/log_backend_adsp_mtrace.c
@@ -84,7 +84,13 @@ static void mtrace_init(void)
 	}
 
 	ADSP_DW->descs[ADSP_DW_SLOT_NUM_MTRACE].type = MTRACE_LOGGING_SLOT_TYPE(MTRACE_CORE);
+
+	struct adsp_debug_slot *slot = (struct adsp_debug_slot *)
+		ADSP_DW->slots[ADSP_DW_SLOT_NUM_MTRACE];
 #endif
+
+	slot->host_ptr = 0;
+	slot->dsp_ptr = 0;
 }
 
 static size_t mtrace_out(int8_t *str, size_t len, size_t *space_left)

Copy link
Collaborator

@ujfalusi ujfalusi Mar 12, 2026

Choose a reason for hiding this comment

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

like this on fw boot on TGL with mtrace-reader open:

[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: dma@7d000: initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: dma@7c000: initialized
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP0
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP1
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP2
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP3
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP4
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP5
[    0.000000] <inf> dai_intel_dmic: dai_dmic_probe: dmic_probe()
[    0.000000] <inf> dai_intel_dmic: dai_dmic_probe: dmic_probe()
[    0.000000] <inf> init: print_version_banner: FW ABI 0x301d001 DBG ABI 0x5003000 tags SOF:v2.14-pre-rc-517-gd088eb0747a2 zephyr:v4.3.0-6597-gd885cfebaa34 src hash 0x3e97bd3e (ref hash 0x3e97bd3e)
*** Booting Zephyr OS build v4.3.0-6597-gd885cfebaa34 ***
[    0.000000] <inf> main: sof_app_main: SOF on intel_adsp
[    0.000000] <inf> main: sof_app_main: SOF initialized

and when mtrace-reader started way after the DSP boot:

[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: dma@7d000: initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: dma@7c000: initialized
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP0
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP1
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP2
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP3
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP4
[    0.000000] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: SSP5
[    0.000000] <inf> dai_intel_dmic: dai_dmic_probe: dmic_probe()
[    0.000000] <inf> dai_intel_dmic: dai_dmic_probe: dmic_probe()
[    0.000000] <inf> init: print_version_banner: FW ABI 0x301d001 DBG ABI 0x5003000 tags SOF:v2.14-pre-rc-517-gd088eb0747a2 zephyr:v4.3.0-6597-gd885cfebaa34 src hash 0x3e97bd3e (ref hash 0x3e97bd3e)
*** Booting Zephyr OS build v4.3.0-6597-gd885cfebaa34 ***
[    0.000000] <inf> main: sof_app_main: SOF on intel_adsp
[    0.000000] <inf> main: sof_app_main: SOF initialized

I think the fix is in zephyr...

Copy link
Collaborator

@ujfalusi ujfalusi Mar 12, 2026

Choose a reason for hiding this comment

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

zephyrproject-rtos/zephyr#105357

}

ret = simple_open(inode, file);
if (ret) {
kfree(core_data->log_buffer);
Expand Down Expand Up @@ -148,6 +162,7 @@ static ssize_t sof_ipc4_mtrace_dfs_read(struct file *file, char __user *buffer,
{
struct sof_mtrace_core_data *core_data = file->private_data;
u32 log_buffer_offset, log_buffer_size, read_ptr, write_ptr;
u32 slot_read_ptr, slot_write_ptr;
struct snd_sof_dev *sdev = core_data->sdev;
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
void *log_buffer = core_data->log_buffer;
Expand All @@ -174,6 +189,19 @@ static ssize_t sof_ipc4_mtrace_dfs_read(struct file *file, char __user *buffer,
if (core_data->slot_offset == SOF_IPC4_INVALID_SLOT_OFFSET)
return 0;

/* Compare cached pointers against slot state to catch missed updates. */
sof_mailbox_read(sdev, core_data->slot_offset, &slot_read_ptr,
sizeof(slot_read_ptr));
sof_mailbox_read(sdev, core_data->slot_offset + sizeof(u32), &slot_write_ptr,
sizeof(slot_write_ptr));
slot_write_ptr -= slot_write_ptr % 4;
if (slot_read_ptr != core_data->host_read_ptr ||
slot_write_ptr != core_data->dsp_write_ptr)
dev_dbg(sdev->dev,
"core%d ptr mismatch: slot r/w %#x/%#x vs cached r/w %#x/%#x\n",
core_data->id, slot_read_ptr, slot_write_ptr,
core_data->host_read_ptr, core_data->dsp_write_ptr);

/* The log data buffer starts after the two pointer in the slot */
log_buffer_offset = core_data->slot_offset + (sizeof(u32) * 2);
/* The log data size excludes the pointers */
Expand Down
Loading