[DEBUG] LL, timer and pipeline debug

src/audio/dai.c

@@ -432,6 +432,62 @@ static int dai_capture_params(struct comp_dev *dev, uint32_t period_bytes,
 	return 0;
 }
 
+struct _debug_ll_schedule_domain {
+	uint64_t last_tick;		/**< timestamp of last run */
+	spinlock_t lock;		/**< standard lock */
+	atomic_t total_num_tasks;	/**< total number of registered tasks */
+	atomic_t num_clients;		/**< number of registered cores */
+	uint32_t ticks_per_ms;		/**< number of clock ticks per ms */
+	int type;			/**< domain type */
+	int clk;			/**< source clock */
+	bool synchronous;		/**< are tasks should be synchronous */
+	void *priv_data;		/**< pointer to private data */
+	bool registered[CONFIG_CORE_COUNT];		/**< registered cores */
+	bool enabled[CONFIG_CORE_COUNT];		/**< enabled cores */
+	const void *ops;	/**< domain ops */
+};
+
+extern atomic_t *_debug_num_tasks;
+extern void *_debug_ll_domain;
+
+static void _debug_debug_ll(struct comp_dev *dev)
+{
+	uint64_t REG_SHIM_DSPWCT0C = shim_read64(SHIM_DSPWCT0C);
+	uint32_t REG_SHIM_DSPWCT0C_HI = REG_SHIM_DSPWCT0C >> 32;
+	uint32_t REG_SHIM_DSPWCT0C_LO = REG_SHIM_DSPWCT0C;
+
+	comp_err(dev, "@@@ SHIM_DSPWCT0C %X%X",
+		 REG_SHIM_DSPWCT0C_HI, REG_SHIM_DSPWCT0C_LO);
+
+	comp_err(dev, "@@@ SHIM_DSPWCTCS %X",
+		 shim_read(SHIM_DSPWCTCS));
+
+	uint64_t REG_SHIM_DSPWC = shim_read64(SHIM_DSPWC);
+	uint32_t REG_SHIM_DSPWC_HI = REG_SHIM_DSPWC >> 32;
+	uint32_t REG_SHIM_DSPWC_LO = REG_SHIM_DSPWC;
+
+	comp_err(dev, "@@@ SHIM_DSPWC %X%X",
+		 REG_SHIM_DSPWC_HI, REG_SHIM_DSPWC_LO);
+
+	struct _debug_ll_schedule_domain *ll =
+		(struct _debug_ll_schedule_domain *)_debug_ll_domain;
+
+	int cpu = cpu_get_id();
+
+	if (_debug_num_tasks && ll) {
+		comp_err(dev, "@@@ NUM TASKS %d TOTAL NUM TASKS %d NUM CLIENTS %d REG %d",
+			atomic_read(_debug_num_tasks),
+			atomic_read(&ll->total_num_tasks),
+			atomic_read(&ll->num_clients),
+			ll->registered[cpu]);
+
+		comp_err(dev, "@@@ LL ENABLED %d LL CLK %d TYPE %d",
+			 ll->enabled[cpu],
+			 ll->clk,
+			 ll->type);
+	}
+}
+
 static int dai_params(struct comp_dev *dev,
 		      struct sof_ipc_stream_params *params)
 {
@@ -448,6 +504,8 @@ static int dai_params(struct comp_dev *dev,
 
 	comp_dbg(dev, "dai_params()");
 
+	_debug_debug_ll(dev);
+
 	err = dai_verify_params(dev, params);
 	if (err < 0) {
 		comp_err(dev, "dai_params(): pcm params verification failed.");

src/audio/pipeline.c

@@ -33,6 +33,8 @@
 #include <stddef.h>
 #include <stdint.h>
 
+extern void *_debug_task_watch;
+
 /* generic pipeline data used by pipeline_comp_* functions */
 struct pipeline_data {
 	struct comp_dev *start;
@@ -73,6 +75,8 @@ struct pipeline *pipeline_new(struct sof_ipc_pipe_new *pipe_desc,
 	struct pipeline *p;
 	int ret;
 
+	pipe_cl_err("@@@ SCHED MARGIN FIX");
+
 	pipe_cl_info("pipeline new pipe_id %d period %d priority %d",
 		     pipe_desc->pipeline_id, pipe_desc->period,
 		     pipe_desc->priority);
@@ -1181,6 +1185,7 @@ void pipeline_schedule_copy(struct pipeline *p, uint64_t start)
 	if (!pipeline_is_timer_driven(p))
 		sa_set_panic_on_delay(false);
 
+	_debug_task_watch = p->pipe_task;
 	schedule_task(p->pipe_task, start, p->ipc_pipe.period);
 }
 
@@ -1195,13 +1200,31 @@ static void pipeline_schedule_cancel(struct pipeline *p)
 		sa_set_panic_on_delay(true);
 }
 
+extern uint64_t _debug_irqs;
+extern uint32_t _debug_clk_time;
+extern int _debug_cur_clk;
+
 static enum task_state pipeline_task(void *arg)
 {
 	struct pipeline *p = arg;
 	int err;
+	uint32_t _debug_irq_delta;
 
 	pipe_dbg(p, "pipeline_task()");
 
+	p->heartbeat++;
+
+	if (p->heartbeat > 2000) {
+		_debug_irq_delta = _debug_irqs - p->last_irqs;
+
+		pipe_err(p, "@@@ PIPELINE HEARTBEAT, IRQ DELTA %d, CLK TIME %d, CUR CLK %d",
+			 _debug_irq_delta, _debug_clk_time, _debug_cur_clk);
+
+		p->last_irqs = _debug_irqs;
+		p->heartbeat = 0;
+		_debug_clk_time = 0;
+	}
+
 	/* are we in xrun ? */
 	if (p->xrun_bytes) {
 		/* try to recover */

src/drivers/intel/cavs/interrupt.c

@@ -125,6 +125,8 @@ static inline void irq_lvl2_handler(void *data, int level, uint32_t ilxsd,
 	}
 }
 
+uint64_t _debug_irqs = 0;
+
 #define IRQ_LVL2_HANDLER(n) int core = cpu_get_id(); \
 				irq_lvl2_handler(data, \
 				 IRQ_NUM_EXT_LEVEL##n, \
@@ -134,6 +136,7 @@ static inline void irq_lvl2_handler(void *data, int level, uint32_t ilxsd,
 #if CONFIG_INTERRUPT_LEVEL_2
 static void irq_lvl2_level2_handler(void *data)
 {
+	_debug_irqs++;
 	IRQ_LVL2_HANDLER(2);
 }
 #endif
@@ -155,6 +158,7 @@ static void irq_lvl2_level4_handler(void *data)
 #if CONFIG_INTERRUPT_LEVEL_5
 static void irq_lvl2_level5_handler(void *data)
 {
+	_debug_irqs++;
 	IRQ_LVL2_HANDLER(5);
 }
 #endif

src/drivers/intel/cavs/timer.c

@@ -18,7 +18,7 @@
 #include <stdint.h>
 
 /** \brief Minimum number of timer recovery cycles in case of delay. */
-#define TIMER_MIN_RECOVER_CYCLES	100
+#define TIMER_MIN_RECOVER_CYCLES	240
 
 void platform_timer_start(struct timer *timer)
 {
@@ -42,8 +42,11 @@ int64_t platform_timer_set(struct timer *timer, uint64_t ticks)
 	if (ticks == 0)
 		ticks = 1;
 
+	mailbox_sw_reg_write64(SRAM_FOO_CUR_TIME, shim_read64(SHIM_DSPWC));
+	mailbox_sw_reg_write64(SRAM_FOO_REQ_TIME, ticks);
+
 	/* Check if requested time is not past time */
-	if (ticks > shim_read64(SHIM_DSPWC))
+	if (ticks > shim_read64(SHIM_DSPWC) + TIMER_MIN_RECOVER_CYCLES)
 		shim_write64(SHIM_DSPWCT0C, ticks);
 	else
 		shim_write64(SHIM_DSPWCT0C, shim_read64(SHIM_DSPWC) +

src/include/kernel/mailbox.h

@@ -36,7 +36,25 @@
 #define SRAM_REG_R0_STATE_TRACE			SRAM_REG_R_STATE_TRACE_BASE
 #define SRAM_REG_R1_STATE_TRACE			0x38
 #define SRAM_REG_R2_STATE_TRACE			0x40
-#define SRAM_REG_FW_END				(SRAM_REG_R2_STATE_TRACE + 0x8)
+#define SRAM_FOO_START 0x48
+#define SRAM_FOO_NUM_TASKS 0x4C
+#define SRAM_FOO_TOTAL_TASKS 0x50
+#define SRAM_FOO_CLIENTS 0x54
+#define SRAM_FOO_REGISTERED 0x58
+#define SRAM_FOO_ENABLED 0x5C
+#define SRAM_FOO_LAST_TICK 0x60
+#define SRAM_FOO_CLK 0x68
+#define SRAM_FOO_LINE 0x6C
+#define SRAM_FOO_CUR_TIME 0x70
+#define SRAM_FOO_REQ_TIME 0x78
+#define SRAM_FOO_LL_TASK_SCHED 0x80
+#define SRAM_FOO_LL_TASK_STATE 0x84
+#define SRAM_FOO_LL_PENDING 0x88
+#define SRAM_FOO_LL_SET_FAIL 0x8C
+#define SRAM_FOO_LL_CANCEL 0x90
+#define SRAM_FOO_LL_RECALC 0x94
+#define SRAM_FOO_LL_TASK_LINE 0x98
+#define SRAM_REG_FW_END				(SRAM_FOO_LL_TASK_LINE + 0x4)
 
 /** @}*/
 

src/include/sof/audio/pipeline.h

@@ -110,6 +110,9 @@ struct pipeline {
 	/* sink component for this pipe */
 	struct comp_dev *sink_comp;
 
+	uint32_t heartbeat;
+	uint64_t last_irqs;
+
 	struct list_item list;	/**< list in walk context */
 
 	/* position update */

src/platform/intel/cavs/lib/clk.c

@@ -17,6 +17,10 @@
 
 static SHARED_DATA struct clock_info platform_clocks_info[NUM_CLOCKS];
 
+uint32_t _debug_clk_time;
+uint32_t _debug_last_clk_time;
+int _debug_cur_clk;
+
 #if CAVS_VERSION == CAVS_VERSION_1_5
 static inline void select_cpu_clock_hw(int freq_idx, bool release_unused)
 {
@@ -32,6 +36,8 @@ static inline void select_cpu_clock_hw(int freq_idx, bool release_unused)
 {
 	uint32_t enc = cpu_freq_enc[freq_idx];
 	uint32_t status_mask = cpu_freq_status_mask[freq_idx];
+	uint64_t t_begin = 0;
+	uint64_t t_end = 0;
 
 #if CONFIG_TIGERLAKE
 	/* TGL specific HW recommended flow */
@@ -43,11 +49,21 @@ static inline void select_cpu_clock_hw(int freq_idx, bool release_unused)
 	io_reg_write(SHIM_BASE + SHIM_CLKCTL,
 		     io_reg_read(SHIM_BASE + SHIM_CLKCTL) | enc);
 
+	t_begin = platform_timer_get(timer_get());
+
 	/* wait for requested clock to be on */
 	while ((io_reg_read(SHIM_BASE + SHIM_CLKSTS) &
 		status_mask) != status_mask)
 		idelay(PLATFORM_DEFAULT_DELAY);
 
+	t_end = platform_timer_get(timer_get());
+
+	_debug_last_clk_time = t_end - t_begin;
+	_debug_cur_clk = freq_idx;
+
+	if (_debug_last_clk_time > _debug_clk_time)
+		_debug_clk_time = _debug_last_clk_time;
+
 	/* switch to requested clock */
 	io_reg_update_bits(SHIM_BASE + SHIM_CLKCTL,
 			   SHIM_CLKCTL_OSC_SOURCE_MASK, enc);