Skip to content

ipc4: logging: make the mtrace hook safe in any context #11332

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

Merged
kv2019i merged 1 commit into from
Oct 23, 2026
Merged

ipc4: logging: make the mtrace hook safe in any context #11332

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
17 changes: 12 additions & 5 deletions src/ipc/ipc4/logging.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,8 @@ static uint32_t mtrace_aging_timer = IPC4_MTRACE_NOTIFY_AGING_TIMER_MS;

#define MTRACE_IPC_CORE PLATFORM_PRIMARY_CORE_ID

static K_MUTEX_DEFINE(log_mutex);
/* the hook runs under the mtrace backend spinlock */
static struct k_spinlock log_lock;
static struct k_work_delayable log_work;

static void mtrace_log_hook_unlocked(size_t written, size_t space_left)
Expand Down Expand Up @@ -93,22 +94,28 @@ static void mtrace_log_hook_unlocked(size_t written, size_t space_left)

static void mtrace_log_hook(size_t written, size_t space_left)
{
k_mutex_lock(&log_mutex, K_FOREVER);
k_spinlock_key_t key;

/* fatal exception log flush: IPC and work queue won't run anyway, their locks may be held */
if (k_is_in_isr())
return;

@kv2019i kv2019i Oct 22, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

Oh, can you @serhiy-katsyuba-intel see how this is handled in other backends (in Zephyr), and whether this is safe for immediate mode logging? IOW, are we really, really sure this is called in ISR only in panic?

@serhiy-katsyuba-intel serhiy-katsyuba-intel Oct 22, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Sorry, used AI to answer. Hope that's OK :) The answer is lengthy, but it seems a pity to cut it.

In SOF's deferred logging mode, the hook only runs in ISR context during a panic. In immediate mode it also runs from ordinary ISRs. That case is still safe: the log data is written either way, and only the BUFFER_STATUS notification for those bytes is postponed. That postponement already happens today for logs written on cores 1–3. Before this PR, immediate mode with ISR logging hit the "mutexes cannot be used inside ISRs" assertion, so the PR makes that case strictly better. Zephyr backends normally handle this differently, through the .panic() callback; details below.

When is the hook called in ISR context?

The hook is invoked from the mtrace backend's char_out(), i.e. wherever log_process() / msg_process() runs:

Mode Who processes messages Hook in ISR?
Deferred, normal operation (SOF default, app/prj.conf) log thread (pinned to core 0) no
Deferred, after LOG_PANIC() inline in the caller (z_log_msg_post_finalize()) yes, only after panic
Immediate (CONFIG_LOG_MODE_IMMEDIATE) inline in the caller (z_log_msg_commit() → msg_process()) yes, any ISR on any core

In SOF builds, LOG_PANIC() is reached only on the fatal path: z_fatal_error() runs coredump() first, and the coredump logging backend calls LOG_PANIC(), then k_sys_fatal_error_handler() calls it again. (ztest also calls it at the end of a run, from thread context.) So in deferred mode, yes, the hook runs in ISR context only in panic.

No in-tree SOF config combines immediate mode with mtrace (ACP boards don't use mtrace; the PTL/WCL sim configs set LOG_BACKEND_ADSP_MTRACE=n), but it is a common local debug setting, so it is worth covering.

Is it safe in immediate mode?

Yes. With the k_is_in_isr() early return, a log from a regular ISR still goes to the slot: mtrace_out() copies the data and advances dsp_ptr before the hook is called. Only the BUFFER_STATUS accounting and notification are skipped. The host reads dsp_ptr from the slot, so those bytes become visible with the next notification: the next core-0 thread log, the aging work, or EXCEPTION_CAUGHT. This is exactly what already happens for logs from secondary cores (the existing TODO in mtrace_log_hook_unlocked()). The only cost is notification latency for long ISR-only log bursts.

Before this PR, the same case (immediate mode + log from ISR) hit the "mutexes cannot be used inside ISRs" assertion, so this is strictly an improvement.

Notifying from a non-panic ISR would also mostly work: spinlocks and k_work_schedule_for_queue() are ISR-safe. The problem is that the hook has no way to tell a panic from a regular ISR. In panic, the backend forces space_left = 0, but that value also means a full buffer.

How other Zephyr backends handle this

None of them use k_is_in_isr(); they all rely on the .panic() callback:

Backend Panic handling
uart sets in_panic, switches from async uart_tx() to uart_poll_out()
rtt panic_mode; sync mode (immediate or panic) busy-waits instead of k_msleep()
adsp (winstream), SOF probe log_backend_std_panic(), lock-free synchronous output
net, ws, ble panic_mode → process() returns early (the stack can't run anymore)
fs deactivates the backend

The mtrace backend's .panic() does the opposite: it sets mtrace_panic_mode and keeps calling the hook with space_left forced to 0 to get an immediate notification. It assumes the hook is panic-safe but doesn't tell the hook it is in panic. On Xtensa every fatal path enters through the exception vector, which increments nested, so k_is_in_isr() is a reliable signal for that.

Possible follow-up

A cleaner long-term fix would be in Zephyr's log_backend_adsp_mtrace.c: either pass a panic flag to the hook, or skip the hook in panic mode. SOF doesn't need the backend's panic-time notification, because the host takes the final write pointer on EXCEPTION_CAUGHT (ipc4_mtrace_fw_crashed()). The hook could then check panic explicitly instead of using k_is_in_isr() as a proxy.

@kv2019i kv2019i Oct 23, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

Thanks @serhiy-katsyuba-intel ! I think agent replies are perfectly ok, especially if you have done a human sanity check on the output (it's often just spot on, but sometimes completely off, so a sanity check before posting is appreciated so we don't waste precious non-agent cycles many times).


key = k_spin_lock(&log_lock);

mtrace_log_hook_unlocked(written, space_left);

k_mutex_unlock(&log_mutex);
k_spin_unlock(&log_lock, key);
Comment on lines +103 to +107
}
Comment on lines 95 to 108

static void log_work_handler(struct k_work *work)
{
k_mutex_lock(&log_mutex, K_FOREVER);
k_spinlock_key_t key = k_spin_lock(&log_lock);

if (k_uptime_get() - mtrace_notify_last_sent >= mtrace_aging_timer &&
mtrace_bytes_pending)
mtrace_log_hook_unlocked(0, 0);

k_mutex_unlock(&log_mutex);
k_spin_unlock(&log_lock, key);
}

static struct k_work_sync ipc4_log_work_sync;
Expand Down
Loading