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 <jyri.sarha@linux.intel.com>

Author: Jyri Sarha

Kconfig.sof

@@ -205,6 +205,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

src/ipc/ipc4/handler.c

@@ -1558,11 +1558,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;
@@ -1676,9 +1684,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);
 	}
 }