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); } }