Skip to content

Commit 2482f44

Browse files
committed
shell: add log_status and mtrace_dump commands
Add two new SOF shell commands for in-firmware log introspection without rebuilding or attaching host-side tooling. sof log_status - list every Zephyr log backend with its index, internal id, active/inactive state and name, plus the total number of registered log sources in the local domain. Read-only, uses Zephyr's public log_backend_*/log_src_cnt_get() API. sof mtrace_dump - snapshot the unread portion of the ADSP mtrace SRAM ring buffer and print it to the shell without advancing host_ptr, so the host-side mtrace-reader.py keeps receiving the same bytes. The mtrace slot is re-acquired through adsp_dw_request_slot() when CONFIG_INTEL_ADSP_DEBUG_SLOT_MANAGER=y (the slot manager returns the already allocated slot), otherwise via ADSP_DW->slots[] directly. The slot layout mirrors the one in zephyr/subsys/logging/backends/ log_backend_adsp_mtrace.c. Two new Kconfigs (default y): CONFIG_SOF_SHELL_LOG_INFO (depends on LOG) CONFIG_SOF_SHELL_MTRACE_DUMP (depends on LOG_BACKEND_ADSP_MTRACE) Per-source runtime log_level was intentionally not added: it would require CONFIG_LOG_RUNTIME_FILTERING=y (extra per-call overhead) and Zephyr already ships an equivalent 'log' shell command (CONFIG_LOG_CMDS=y). Update zephyr/shell.md. Signed-off-by: Liam Girdwood <liam.r.girdwood@linux.intel.com>
1 parent 053c962 commit 2482f44

3 files changed

Lines changed: 182 additions & 2 deletions

File tree

zephyr/Kconfig

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -488,6 +488,35 @@ config SOF_SHELL_SCHED_INFO
488488
own lock during the walk; schedulers without an implementation are
489489
silently skipped.
490490

491+
config SOF_SHELL_LOG_INFO
492+
bool "Log subsystem status command"
493+
default y
494+
depends on SHELL && LOG
495+
help
496+
Enables the 'sof log_status' shell command, which lists every
497+
registered Zephyr log backend with its index, internal id,
498+
active/inactive state and name, plus the total number of
499+
registered log sources in the local domain.
500+
501+
Read-only and cheap; useful for confirming which backends
502+
(uart_console, adsp_mtrace, adsp_hda, ...) are alive without
503+
having to enable CONFIG_LOG_RUNTIME_FILTERING and the much
504+
larger Zephyr 'log' shell module.
505+
506+
config SOF_SHELL_MTRACE_DUMP
507+
bool "mtrace SRAM buffer snapshot command"
508+
default y
509+
depends on SHELL && LOG_BACKEND_ADSP_MTRACE
510+
help
511+
Enables the 'sof mtrace_dump' shell command which prints the
512+
unread portion of the ADSP mtrace SRAM ring buffer (the same
513+
buffer normally consumed by host-side mtrace-reader.py).
514+
515+
The snapshot does NOT advance the host_ptr, so it is safe to
516+
use while a host consumer is running: the host will still
517+
receive every byte. Useful when no host driver is attached
518+
(e.g. early bring-up over UART shell only).
519+
491520
endmenu # SOF shell commands
492521

493522
config SOF_VREGIONS

zephyr/shell.md

Lines changed: 46 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -87,7 +87,7 @@ debug or testing. Items get ticked off as commands land on `topic/shell`.
8787
| IPC inject | `ipc_inject <hex>`, `ipc_queue` | TODO |
8888
| Audio buffers | `buffer_list`, `buffer_info <id>` | **DONE (task 2)** |
8989
| **Scheduler** | `sched_tasks`, `sched_load`, `task_info <task>` | **DONE (task 3)** |
90-
| Logging / trace | `log_level <component> <lvl>`, `log_filter`, `mtrace_dump`, `trace_stats` | TODO |
90+
| Logging / trace | `log_status`, `mtrace_dump` (snapshot) | **DONE (task 4)** &mdash; runtime per-source `log_level` deferred (needs `CONFIG_LOG_RUNTIME_FILTERING`, see notes) |
9191
| Telemetry / perf | `perf_status`, `perf_reset`, `cpu_load` | TODO |
9292
| Notifications | `notify_subscribers`, `notify_stats` | TODO |
9393
| Debug window / mailbox | `dbgwin_dump <slot>`, `mailbox_hex` | TODO |
@@ -112,7 +112,7 @@ debug or testing. Items get ticked off as commands land on `topic/shell`.
112112
1. **`ipc_stats` / `ipc_last`** &mdash; DONE.
113113
2. **`buffer_list` / `buffer_info`** &mdash; DONE.
114114
3. **`sched_tasks` / `sched_load`** &mdash; DONE.
115-
4. `log_level` / `mtrace_dump` &mdash; runtime log tuning without rebuild.
115+
4. **`log_status` / `mtrace_dump`** &mdash; DONE.
116116
5. `crash_log` / `bt` &mdash; pair with the `crash-*` artifacts in the tree.
117117
6. `perf_status` &mdash; wraps SOF telemetry counters.
118118
7. `dai_list` / `dma_chan_status` &mdash; link/DMA blind spot.
@@ -221,3 +221,47 @@ debug or testing. Items get ticked off as commands land on `topic/shell`.
221221
targets).
222222
- `task_info <uid>` lookup, deadline-miss counts and per-core
223223
aggregation could be added on top of the same op.
224+
225+
## Task 4 &mdash; `log_status` / `mtrace_dump`
226+
227+
### Commands
228+
229+
| Command | Description |
230+
|---|---|
231+
| `sof log_status` | List every Zephyr log backend (idx, internal id, active state, name) plus the total number of registered log sources in the local domain. Read-only. |
232+
| `sof mtrace_dump` | Print the unread portion of the ADSP mtrace SRAM ring buffer as a snapshot, *without* advancing `host_ptr`. Safe to use while host-side `mtrace-reader.py` is running. |
233+
234+
### Implementation
235+
236+
- `log_status` uses Zephyr's public log backend API
237+
(`log_backend_count_get()`, `log_backend_get()`,
238+
`log_backend_is_active()`, `log_backend_id_get()`,
239+
`log_src_cnt_get()`); no new state is added.
240+
- `mtrace_dump` re-acquires the existing mtrace slot:
241+
- With `CONFIG_INTEL_ADSP_DEBUG_SLOT_MANAGER=y` (default on PTL/MTL/LNL):
242+
via `adsp_dw_request_slot()` with the same descriptor type
243+
(`ADSP_DW_SLOT_DEBUG_LOG | core 0`); the slot manager returns the
244+
already-allocated slot.
245+
- Otherwise: directly indexes
246+
`ADSP_DW->slots[ADSP_DW_SLOT_NUM_MTRACE]`.
247+
- The slot layout (`{host_ptr, dsp_ptr, data[]}`) mirrors the one in
248+
[zephyr/subsys/logging/backends/log_backend_adsp_mtrace.c](../../zephyr/subsys/logging/backends/log_backend_adsp_mtrace.c).
249+
- We read from `host_ptr` to `dsp_ptr` byte-by-byte and write to the
250+
shell, but never store back to `host_ptr`, so the host-side
251+
consumer keeps seeing the same bytes.
252+
- Two new Kconfigs (default `y`):
253+
- `CONFIG_SOF_SHELL_LOG_INFO` (depends on `LOG`)
254+
- `CONFIG_SOF_SHELL_MTRACE_DUMP` (depends on `LOG_BACKEND_ADSP_MTRACE`)
255+
- Shell commands in [zephyr/sof_shell.c](zephyr/sof_shell.c).
256+
257+
### Notes / follow-ups
258+
259+
- Per-source runtime `log_level` setting was deliberately deferred: it
260+
requires `CONFIG_LOG_RUNTIME_FILTERING=y` (extra per-call overhead)
261+
and Zephyr already ships an equivalent `log` shell command
262+
(`CONFIG_LOG_CMDS=y`). If we ever need it we should reuse Zephyr's
263+
command rather than reimplement it.
264+
- `mtrace_dump` shows raw text exactly as the backend formatted it; a
265+
future option could format output in pages or filter by severity.
266+
- A `mtrace_dump --consume` mode (advance `host_ptr`) is intentionally
267+
not provided to avoid silently breaking host-side tooling.

zephyr/sof_shell.c

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1855,6 +1855,101 @@ __cold static int cmd_sof_sched_load(const struct shell *sh,
18551855

18561856
#endif /* CONFIG_SOF_SHELL_SCHED_INFO */
18571857

1858+
#if CONFIG_SOF_SHELL_LOG_INFO
1859+
1860+
#include <zephyr/logging/log_backend.h>
1861+
#include <zephyr/logging/log_ctrl.h>
1862+
1863+
__cold static int cmd_sof_log_status(const struct shell *sh,
1864+
size_t argc, char *argv[])
1865+
{
1866+
int n = log_backend_count_get();
1867+
int i;
1868+
1869+
shell_print(sh, "Log backends: %d, sources: %u",
1870+
n, log_src_cnt_get(Z_LOG_LOCAL_DOMAIN_ID));
1871+
shell_print(sh, " idx id active name");
1872+
1873+
for (i = 0; i < n; i++) {
1874+
const struct log_backend *be = log_backend_get(i);
1875+
1876+
if (!be)
1877+
continue;
1878+
shell_print(sh, " %3d %3u %-3s %s",
1879+
i, log_backend_id_get(be),
1880+
log_backend_is_active(be) ? "yes" : "no",
1881+
be->name ? be->name : "?");
1882+
}
1883+
1884+
return 0;
1885+
}
1886+
1887+
#endif /* CONFIG_SOF_SHELL_LOG_INFO */
1888+
1889+
#if CONFIG_SOF_SHELL_MTRACE_DUMP
1890+
1891+
#include <adsp_debug_window.h>
1892+
1893+
/* must match the layout used by zephyr/subsys/logging/backends/log_backend_adsp_mtrace.c */
1894+
struct sof_shell_mtrace_slot {
1895+
uint32_t host_ptr;
1896+
uint32_t dsp_ptr;
1897+
uint8_t data[ADSP_DW_SLOT_SIZE - 2 * sizeof(uint32_t)];
1898+
} __packed;
1899+
1900+
#define SOF_SHELL_MTRACE_BUF_SIZE (ADSP_DW_SLOT_SIZE - 2 * sizeof(uint32_t))
1901+
#define SOF_SHELL_MTRACE_TYPE(core) \
1902+
(ADSP_DW_SLOT_DEBUG_LOG | ((core) & ADSP_DW_SLOT_CORE_MASK))
1903+
1904+
__cold static int cmd_sof_mtrace_dump(const struct shell *sh,
1905+
size_t argc, char *argv[])
1906+
{
1907+
struct sof_shell_mtrace_slot *slot;
1908+
uint32_t r, w, len, i;
1909+
1910+
#ifdef CONFIG_INTEL_ADSP_DEBUG_SLOT_MANAGER
1911+
struct adsp_dw_desc desc = { .type = SOF_SHELL_MTRACE_TYPE(0) };
1912+
1913+
slot = adsp_dw_request_slot(&desc, NULL);
1914+
#else
1915+
slot = (struct sof_shell_mtrace_slot *)
1916+
ADSP_DW->slots[ADSP_DW_SLOT_NUM_MTRACE];
1917+
#endif
1918+
if (!slot) {
1919+
shell_print(sh, "mtrace slot not available");
1920+
return -ENODEV;
1921+
}
1922+
1923+
r = slot->host_ptr;
1924+
w = slot->dsp_ptr;
1925+
1926+
if (r == w) {
1927+
shell_print(sh, "mtrace: empty (host_ptr=dsp_ptr=%u)", r);
1928+
return 0;
1929+
}
1930+
1931+
if (w > r)
1932+
len = w - r;
1933+
else
1934+
len = SOF_SHELL_MTRACE_BUF_SIZE - r + w;
1935+
1936+
shell_print(sh,
1937+
"mtrace: host_ptr=%u dsp_ptr=%u unread=%u bytes (snapshot)",
1938+
r, w, len);
1939+
1940+
/* print byte-by-byte without advancing host_ptr; preserves host consumer */
1941+
for (i = 0; i < len; i++) {
1942+
uint32_t off = (r + i) % SOF_SHELL_MTRACE_BUF_SIZE;
1943+
1944+
shell_fprintf(sh, SHELL_NORMAL, "%c", slot->data[off]);
1945+
}
1946+
shell_fprintf(sh, SHELL_NORMAL, "\n");
1947+
1948+
return 0;
1949+
}
1950+
1951+
#endif /* CONFIG_SOF_SHELL_MTRACE_DUMP */
1952+
18581953
SHELL_STATIC_SUBCMD_SET_CREATE(sof_commands,
18591954
SHELL_CMD(test_inject_sched_gap, NULL,
18601955
"Inject a gap to audio scheduling\n",
@@ -2031,6 +2126,18 @@ SHELL_STATIC_SUBCMD_SET_CREATE(sof_commands,
20312126
cmd_sof_sched_load),
20322127
#endif
20332128

2129+
#if CONFIG_SOF_SHELL_LOG_INFO
2130+
SHELL_CMD(log_status, NULL,
2131+
"List Zephyr log backends with state and source count\n",
2132+
cmd_sof_log_status),
2133+
#endif
2134+
2135+
#if CONFIG_SOF_SHELL_MTRACE_DUMP
2136+
SHELL_CMD(mtrace_dump, NULL,
2137+
"Snapshot the mtrace SRAM ring buffer (does not advance host_ptr)\n",
2138+
cmd_sof_mtrace_dump),
2139+
#endif
2140+
20342141
SHELL_SUBCMD_SET_END
20352142
);
20362143

0 commit comments

Comments
 (0)