ipc4: handler: Kconfig option to add IPC processing timing prints

Kconfig option DEBUG_IPC_TIMINGS to add logging after IPC handling
right before sending IPC reply. 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

@@ -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 right before sending IPC
+	  reply. 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

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