From f4ec37c68996d777a2c285628fc46b4f6dc736b3 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 11 Mar 2025 23:36:27 +0200 Subject: [PATCH] ipc4: handler: Kconfig option to add IPC processing timing prints Kconfig option DEBUG_IPC_TIMINGS to add logging after IPC handling before putting IPC reply to send queue. The logging contains both the reply and the original request message headers and the time that it took to process the request in micro seconds. The value can be used to collect statistics on changes in firmware response times. This also disables the logging of the received request on core 0 to avoid flooding the logs too much. Signed-off-by: Jyri Sarha --- Kconfig.sof | 13 +++++++++++++ src/ipc/ipc4/handler.c | 17 +++++++++++++++-- 2 files changed, 28 insertions(+), 2 deletions(-) diff --git a/Kconfig.sof b/Kconfig.sof index be5bdc2f35b0..aad34fc1ca5f 100644 --- a/Kconfig.sof +++ b/Kconfig.sof @@ -198,6 +198,19 @@ config DEBUG_IPC_COUNTERS help Select for enabling tracing IPC counter in SRAM_REG mailbox +config DEBUG_IPC_TIMINGS + bool "Enable IPC message handling time logging" + depends on DEBUG + default n + help + Adds a logging after IPC handling before putting IPC reply + to send queue. The logging contains both the reply and the + original request message headers and the time that it took + to process the request in micro seconds. The value can be + used to collect statistics on changes in firmware response + times. This also disables the logging of the received + request on core 0 to avoid flooding the logs too much. + config SCHEDULE_LOG_CYCLE_STATISTICS bool "Log cycles per tick statistics for each task separately" default y diff --git a/src/ipc/ipc4/handler.c b/src/ipc/ipc4/handler.c index 3fb49696f343..2d2e6c9a0f88 100644 --- a/src/ipc/ipc4/handler.c +++ b/src/ipc/ipc4/handler.c @@ -1556,11 +1556,19 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr) { struct ipc4_message_request *in = ipc4_get_message_request(); enum ipc4_message_target target; +#ifdef CONFIG_DEBUG_IPC_TIMINGS + struct ipc4_message_request req; + uint64_t tstamp; +#endif int err; +#ifdef CONFIG_DEBUG_IPC_TIMINGS + req = *in; + tstamp = sof_cycle_get_64(); +#else if (cpu_is_primary(cpu_get_id())) tr_info(&ipc_tr, "rx\t: %#x|%#x", in->primary.dat, in->extension.dat); - +#endif /* no process on scheduled thread */ atomic_set(&msg_data.delayed_reply, 0); msg_data.delayed_error = 0; @@ -1674,9 +1682,14 @@ void ipc_cmd(struct ipc_cmd_hdr *_hdr) msg_reply.header = reply.primary.dat; +#ifdef CONFIG_DEBUG_IPC_TIMINGS + tr_info(&ipc_tr, "tx-reply\t: %#x|%#x to %#x|%#x in %llu us", msg_reply.header, + msg_reply.extension, req.primary.dat, req.extension.dat, + k_cyc_to_us_near64(sof_cycle_get_64() - tstamp)); +#else tr_dbg(&ipc_tr, "tx-reply\t: %#x|%#x", msg_reply.header, msg_reply.extension); - +#endif ipc4_send_reply(&reply); } }