Ipc uset kernel split

app/debug_stream_overlay.conf

@@ -8,6 +8,17 @@ CONFIG_SOF_DEBUG_STREAM_THREAD_INFO=y
 CONFIG_THREAD_NAME=y
 # For Zephyr to compile with thread names on PTL we need to increase THREAD_BYTES
 CONFIG_MAX_THREAD_BYTES=4
+# Shrink number of CPU sections
+# As the number of supported cores shrink, the available circular
+# buffer size increases. This means increased bandwidth. This is
+# particularly useful, when debugging a problem on core 0.
+#CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS=1
+
+# Direct the assert prints to debug stream
+# This option obeys CONFIG_EXCEPTION_DUMP_HOOK_ONLY. If it is selected
+# the assert print is sent only to debug stream. Without it the assert
+# prints are printed with vprintk too,
+CONFIG_SOF_DEBUG_STREAM_TEXT_MSG_ASSERT_PRINT=y
 
 # Debug window slot configuration 1
 # The CONFIG_SOF_TELEMETRY uses slot 2, but with performance and IO-performance

src/debug/debug_stream/Kconfig

@@ -45,6 +45,17 @@ config SOF_DEBUG_STREAM_THREAD_INFO_INTERVAL
 	  Decides how often thread info runs and checks execution cycle
 	  statistics and stack usage.
 
+config SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS
+	int "Number of cpu sections slot is divided to"
+	default MP_MAX_NUM_CPUS
+	range 1 MP_MAX_NUM_CPUS
+	help
+	  In some situations a high number of cpu sections shrinks the
+	  circular buffer size so much that it limit debugging. With
+	  this option its possible to use fewer sections. The downside
+	  is that the cpus above the number of sections can not send
+	  any debug stream messages.
+
 config SOF_DEBUG_STREAM_TEXT_MSG
 	bool "Enable text message sending through Debug-Stream"
 	help
@@ -54,4 +65,14 @@ config SOF_DEBUG_STREAM_TEXT_MSG
 	  ds_msg(). See include/user/debug_stream_text_msg.h for
 	  prototype.
 
+config SOF_DEBUG_STREAM_TEXT_MSG_ASSERT_PRINT
+	bool "Enable assert print sending through Debug-Stream"
+	depends on EXCEPTION_DUMP_HOOK && (ASSERT || ASSERT_VERBOSE)
+	select SOF_DEBUG_STREAM_TEXT_MSG
+	help
+	  Enable assert print sending over debug stream as text
+	  message. This feature is also sensitive to Zephyr option
+	  CONFIG_EXCEPTION_DUMP_HOOK_ONLY. If that is set then the
+	  asserts are not printed through printk interface.
+
 endif

src/debug/debug_stream/debug_stream_slot.c

@@ -19,7 +19,7 @@ struct cpu_mutex {
 } __aligned(CONFIG_DCACHE_LINE_SIZE);
 
 /* CPU specific mutexes for each circular buffer */
-static struct cpu_mutex cpu_mutex[CONFIG_MP_MAX_NUM_CPUS];
+static struct cpu_mutex cpu_mutex[CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS];
 
 #ifdef CONFIG_INTEL_ADSP_DEBUG_SLOT_MANAGER
 static struct debug_stream_slot_hdr *dbg_stream_slot;
@@ -54,6 +54,12 @@ debug_stream_get_circular_buffer(struct debug_stream_section_descriptor *desc, u
 		return NULL;
 	}
 
+	if (core >= CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS) {
+		LOG_DBG("No section for cpu %u >= %u ", core,
+			CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS);
+		return NULL;
+	}
+
 	*desc = hdr->section_desc[core];
 	LOG_DBG("Section %u (desc %u %u %u)", core, desc->core_id, desc->buf_words, desc->offset);
 
@@ -116,18 +122,19 @@ int debug_stream_slot_send_record(struct debug_stream_record *rec)
 static int debug_stream_slot_init(void)
 {
 	struct debug_stream_slot_hdr *hdr = debug_stream_get_slot();
-	size_t hdr_size = ALIGN_UP(offsetof(struct debug_stream_slot_hdr,
-					    section_desc[CONFIG_MP_MAX_NUM_CPUS]),
-				   CONFIG_DCACHE_LINE_SIZE);
+	size_t hdr_size = ALIGN_UP(
+		offsetof(struct debug_stream_slot_hdr,
+			 section_desc[CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS]),
+		CONFIG_DCACHE_LINE_SIZE);
 	size_t section_area_size = ADSP_DW_SLOT_SIZE - hdr_size;
 	size_t section_size = ALIGN_DOWN(section_area_size /
-					 CONFIG_MP_MAX_NUM_CPUS,
+					 CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS,
 					 CONFIG_DCACHE_LINE_SIZE);
 	size_t offset = hdr_size;
 	int i;
 
 	LOG_INF("%u sections of %u bytes, hdr %u, section area %u",
-		CONFIG_MP_MAX_NUM_CPUS, section_size, hdr_size,
+		CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS, section_size, hdr_size,
 		section_area_size);
 
 #ifdef CONFIG_INTEL_ADSP_DEBUG_SLOT_MANAGER
@@ -142,9 +149,9 @@ static int debug_stream_slot_init(void)
 
 	hdr->hdr.magic = DEBUG_STREAM_IDENTIFIER;
 	hdr->hdr.hdr_size = hdr_size;
-	hdr->total_size = hdr_size + CONFIG_MP_MAX_NUM_CPUS * section_size;
-	hdr->num_sections = CONFIG_MP_MAX_NUM_CPUS;
-	for (i = 0; i < CONFIG_MP_MAX_NUM_CPUS; i++) {
+	hdr->total_size = hdr_size + CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS * section_size;
+	hdr->num_sections = CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS;
+	for (i = 0; i < CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS; i++) {
 		hdr->section_desc[i].core_id = i;
 		hdr->section_desc[i].buf_words =
 			(section_size - offsetof(struct debug_stream_circular_buf, data[0]))/
@@ -154,7 +161,7 @@ static int debug_stream_slot_init(void)
 			i, section_size, offset);
 		offset += section_size;
 	}
-	for (i = 0; i < CONFIG_MP_MAX_NUM_CPUS; i++) {
+	for (i = 0; i < CONFIG_SOF_DEBUG_STREAM_SLOT_FORCE_MAX_CPUS; i++) {
 		struct debug_stream_section_descriptor desc = { 0 };
 		struct debug_stream_circular_buf *buf =
 			debug_stream_get_circular_buffer(&desc, i);

src/debug/debug_stream/debug_stream_text_msg.c

@@ -15,18 +15,15 @@
 
 LOG_MODULE_REGISTER(debug_stream_text_msg);
 
-void ds_msg(const char *format, ...)
+void ds_vamsg(const char *format, va_list args)
 {
-	va_list args;
 	struct {
 		struct debug_stream_text_msg msg;
 		char text[128];
 	} __packed buf = { 0 };
 	ssize_t len;
 
-	va_start(args, format);
 	len = vsnprintf(buf.text, sizeof(buf.text), format, args);
-	va_end(args);
 
 	if (len < 0)
 		return;
@@ -38,6 +35,15 @@ void ds_msg(const char *format, ...)
 	debug_stream_slot_send_record(&buf.msg.hdr);
 }
 
+void ds_msg(const char *format, ...)
+{
+	va_list args;
+
+	va_start(args, format);
+	ds_vamsg(format, args);
+	va_end(args);
+}
+
 #if defined(CONFIG_EXCEPTION_DUMP_HOOK)
 /* The debug stream debug window slot is 4k, and when it is split
  * between the cores and the header/other overhead is removed, with 5
@@ -49,39 +55,46 @@ void ds_msg(const char *format, ...)
  * in bursts, and sending more than one record in short time makes the
  * host-side decoder lose track of things.
  */
-static struct {
-	struct debug_stream_text_msg msg;
-	char text[640];
-} __packed ds_buf[CONFIG_MP_MAX_NUM_CPUS];
-static int reports_sent_cpu[CONFIG_MP_MAX_NUM_CPUS];
-static size_t ds_pos[CONFIG_MP_MAX_NUM_CPUS];
+
+/* Per-CPU state for exception dump and assert_print().
+ * Cache-line aligned to avoid false sharing between cores.
+ */
+static struct ds_cpu_state {
+	struct {
+		struct debug_stream_text_msg msg;
+		char text[640];
+	} __packed buf;
+	int reports_sent;
+	size_t pos;
+} __aligned(CONFIG_DCACHE_LINE_SIZE) ds_cpu[CONFIG_MP_MAX_NUM_CPUS];
 
 static void ds_exception_drain(bool flush)
 {
 	unsigned int cpu = arch_proc_id();
+	struct ds_cpu_state *cs = &ds_cpu[cpu];
 
 	if (flush) {
-		ds_pos[cpu] = 0;
-		reports_sent_cpu[cpu] = 0;
+		cs->pos = 0;
 		return;
 	}
 
-	if (ds_pos[cpu] == 0)
+	if (cs->pos == 0)
 		return;
 
-	if (reports_sent_cpu[cpu] > 0)
+	if (cs->reports_sent > 0)
 		return;
 
-	ds_buf[cpu].msg.hdr.id = DEBUG_STREAM_RECORD_ID_TEXT_MSG;
-	ds_buf[cpu].msg.hdr.size_words =
-		SOF_DIV_ROUND_UP(sizeof(ds_buf[cpu].msg) + ds_pos[cpu],
-				 sizeof(ds_buf[cpu].msg.hdr.data[0]));
+	cs->buf.msg.hdr.id = DEBUG_STREAM_RECORD_ID_TEXT_MSG;
+	cs->buf.msg.hdr.size_words =
+		SOF_DIV_ROUND_UP(sizeof(cs->buf.msg) + cs->pos,
+				 sizeof(cs->buf.msg.hdr.data[0]));
+
 	/* Make sure the possible up to 3 extra bytes at end of msg are '\0' */
-	memset(ds_buf[cpu].text + ds_pos[cpu], 0,
-	       ds_buf[cpu].msg.hdr.size_words * sizeof(ds_buf[cpu].msg.hdr.data[0]) - ds_pos[cpu]);
-	debug_stream_slot_send_record(&ds_buf[cpu].msg.hdr);
-	reports_sent_cpu[cpu] = 1;
-	ds_pos[cpu] = 0;
+	memset(cs->buf.text + cs->pos, 0,
+	       cs->buf.msg.hdr.size_words * sizeof(cs->buf.msg.hdr.data[0]) - cs->pos);
+	debug_stream_slot_send_record(&cs->buf.msg.hdr);
+	cs->reports_sent = 1;
+	cs->pos = 0;
 }
 
 static void ds_exception_dump(const char *format, va_list args)
@@ -90,11 +103,12 @@ static void ds_exception_dump(const char *format, va_list args)
 	size_t avail;
 	size_t written;
 	unsigned int cpu = arch_proc_id();
+	struct ds_cpu_state *cs = &ds_cpu[cpu];
 
-	if (reports_sent_cpu[cpu] > 0)
+	if (cs->reports_sent > 0)
 		return;
 
-	avail = sizeof(ds_buf[cpu].text) - ds_pos[cpu];
+	avail = sizeof(cs->buf.text) - cs->pos;
 	if (avail == 0) {
 		ds_exception_drain(false);
 		return;
@@ -108,9 +122,9 @@ static void ds_exception_dump(const char *format, va_list args)
 	    format[0] == ' ' && format[1] == '*' && format[2] == '*' && format[3] == ' ')
 		format += 4;
 
-	len = vsnprintf(ds_buf[cpu].text + ds_pos[cpu], avail, format, args);
+	len = vsnprintf(cs->buf.text + cs->pos, avail, format, args);
 	if (len < 0) {
-		ds_pos[cpu] = 0;
+		cs->pos = 0;
 		return;
 	}
 
@@ -122,18 +136,46 @@ static void ds_exception_dump(const char *format, va_list args)
 	else
 		written = (size_t)len;
 
-	ds_pos[cpu] += written;
+	cs->pos += written;
 
-	if (ds_pos[cpu] >= sizeof(ds_buf[cpu].text))
+	if (cs->pos >= sizeof(cs->buf.text))
 		ds_exception_drain(false);
 }
 
 static int init_exception_dump_hook(void)
 {
-	set_exception_dump_hook(ds_exception_dump, ds_exception_drain);
+	arch_exception_set_dump_hook(ds_exception_dump, ds_exception_drain);
 	LOG_INF("exception_dump_hook set");
 	return 0;
 }
 
 SYS_INIT(init_exception_dump_hook, APPLICATION, CONFIG_KERNEL_INIT_PRIORITY_DEFAULT);
+
+#if defined(CONFIG_SOF_DEBUG_STREAM_TEXT_MSG_ASSERT_PRINT)
+void assert_print(const char *fmt, ...)
+{
+	va_list ap;
+
+	/* Do not print assert after exception has been dumped */
+	if (ds_cpu[arch_proc_id()].reports_sent > 0)
+		return;
+
+	va_start(ap, fmt);
+#if !defined(CONFIG_EXCEPTION_DUMP_HOOK_ONLY)
+	{
+		va_list ap2;
+
+		va_copy(ap2, ap);
+#endif
+		ds_vamsg(fmt, ap);
+#if !defined(CONFIG_EXCEPTION_DUMP_HOOK_ONLY)
+		vprintk(fmt, ap2);
+		va_end(ap2);
+	}
+#endif
+	ds_vamsg(fmt, ap);
+	va_end(ap);
+}
+EXPORT_SYMBOL(assert_print);
+#endif
 #endif

src/idc/zephyr_idc.c

@@ -115,23 +115,38 @@ static void idc_handler(struct k_p4wq_work *work)
 
 /*
  * Used for *target* CPUs, since the initiator (usually core 0) can launch
- * several IDC messages at once
+ * several IDC messages at once. Also we need 2 work items per target core,
+ * because the p4wq thread might just have returned from the work handler, but
+ * hasn't released the work buffer yet (hasn't set thread pointer to NULL).
+ * Then submitting the same work item again can result in an assertion failure.
  */
-static struct zephyr_idc_msg idc_work[CONFIG_CORE_COUNT];
+static struct zephyr_idc_msg idc_work[CONFIG_CORE_COUNT * 2];
+/* Protect the above array */
+static K_MUTEX_DEFINE(idc_mutex);
 
 int idc_send_msg(struct idc_msg *msg, uint32_t mode)
 {
 	struct idc *idc = *idc_get();
 	struct idc_payload *payload = idc_payload_get(idc, msg->core);
 	unsigned int target_cpu = msg->core;
-	struct zephyr_idc_msg *zmsg = idc_work + target_cpu;
+	struct zephyr_idc_msg *zmsg = idc_work + target_cpu * 2;
 	struct idc_msg *msg_cp = &zmsg->msg;
 	struct k_p4wq_work *work = &zmsg->work;
 	int ret;
 	int idc_send_memcpy_err __unused;
 
+	k_mutex_lock(&idc_mutex, K_FOREVER);
+
+	if (unlikely(work->thread)) {
+		/* See comment above the idc_work[] array. */
+		zmsg++;
+		work = &zmsg->work;
+		msg_cp = &zmsg->msg;
+	}
+
 	idc_send_memcpy_err = memcpy_s(msg_cp, sizeof(*msg_cp), msg, sizeof(*msg));
 	assert(!idc_send_memcpy_err);
+
 	/* Same priority as the IPC thread which is an EDF task and under Zephyr */
 	work->priority = CONFIG_EDF_THREAD_PRIORITY;
 	work->deadline = 0;
@@ -158,6 +173,8 @@ int idc_send_msg(struct idc_msg *msg, uint32_t mode)
 
 	k_p4wq_submit(q_zephyr_idc + target_cpu, work);
 
+	k_mutex_unlock(&idc_mutex);
+
 #ifdef CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS
 	/* Increment performance counters */
 	io_perf_monitor_update_data(idc->io_perf_out_msg_count, 1);