Repository navigation
ipc4: logging: make the mtrace hook safe in any context - #11332
serhiy-katsyuba-intel wants to merge 1 commit into
Conversation
The mtrace log backend calls the hook with its own spinlock held, so the hook must not sleep, but a k_mutex may sleep under contention. Replace the mutex with a spinlock. Nothing done under the lock sleeps: the IPC notification and the delayed log work are only queued. On a fatal error the hook is also called from the exception handler: coredump() calls LOG_PANIC() to flush the pending logs, and it does so before k_sys_fatal_error_handler() runs, so a flag set there would be too late. Two problems showed up in this context: - k_mutex_lock() asserts in ISR context, so every DSP fatal error was hidden behind a secondary assertion. - Queueing the IPC notification or the log work takes the work queue lock, which the faulting code may hold, e.g. on an assertion in k_work_reschedule_for_queue(). The DSP then deadlocked after the first log line. Return early from the hook when k_is_in_isr() is true. The log data is already in the buffer, and the host reads the final write pointer when it receives the EXCEPTION_CAUGHT notification. Signed-off-by: Serhiy Katsyuba <serhiy.katsyuba@intel.com>
There was a problem hiding this comment.
Warning
Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.
Copilot review overview
2 open issues
What changed in this PR
Makes the IPC4 mtrace log hook safe when invoked under the mtrace backend spinlock and during fatal exception log flushing, avoiding sleeping locks and deadlocks.
Changes:
- Replace the hook’s
k_mutexwith ak_spinlockto avoid sleeping under contention. - Bail out early from the hook when running in ISR context to avoid deadlocking on work/IPC queue locks during fault handling.
- Use the same spinlock in the delayed work handler for consistent serialization.
| File | Description |
|---|---|
| src/ipc/ipc4/logging.c | Switches log hook serialization from mutex to spinlock and adds ISR early-return to prevent fault-path deadlocks. |
Review effort: Lite
| key = k_spin_lock(&log_lock); | ||
|
|
||
| mtrace_log_hook_unlocked(written, space_left); | ||
|
|
||
| k_mutex_unlock(&log_mutex); | ||
| k_spin_unlock(&log_lock, key); |
| 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; | ||
|
|
||
| key = k_spin_lock(&log_lock); | ||
|
|
||
| mtrace_log_hook_unlocked(written, space_left); | ||
|
|
||
| k_mutex_unlock(&log_mutex); | ||
| k_spin_unlock(&log_lock, key); | ||
| } |
PR 11332: test resultsRun date: 2026-10-22 12:33 UTC Tested commit: c2511a9b2fe73dad008d85746faba293937c1920
|
|
|
||
| /* fatal exception log flush: IPC and work queue won't run anyway, their locks may be held */ | ||
| if (k_is_in_isr()) | ||
| return; |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
The mtrace log backend calls the hook with its own spinlock held, so the hook must not sleep, but a k_mutex may sleep under contention. Replace the mutex with a spinlock. Nothing done under the lock sleeps: the IPC notification and the delayed log work are only queued.
On a fatal error the hook is also called from the exception handler: coredump() calls LOG_PANIC() to flush the pending logs, and it does so before k_sys_fatal_error_handler() runs, so a flag set there would be too late. Two problems showed up in this context:
Return early from the hook when k_is_in_isr() is true. The log data is already in the buffer, and the host reads the final write pointer when it receives the EXCEPTION_CAUGHT notification.