diff --git a/src/audio/dai.c b/src/audio/dai.c index db99bbe86ed4..c9f47d37be61 100644 --- a/src/audio/dai.c +++ b/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."); diff --git a/src/audio/pipeline.c b/src/audio/pipeline.c index 345773b7dea0..12a7cec24724 100644 --- a/src/audio/pipeline.c +++ b/src/audio/pipeline.c @@ -33,6 +33,8 @@ #include #include +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 */ diff --git a/src/drivers/intel/cavs/interrupt.c b/src/drivers/intel/cavs/interrupt.c index 4f2756e407f6..0e77c612b9dc 100644 --- a/src/drivers/intel/cavs/interrupt.c +++ b/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 diff --git a/src/drivers/intel/cavs/timer.c b/src/drivers/intel/cavs/timer.c index 8d67ec508e47..3c99a083a69a 100644 --- a/src/drivers/intel/cavs/timer.c +++ b/src/drivers/intel/cavs/timer.c @@ -18,7 +18,7 @@ #include /** \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) + diff --git a/src/include/kernel/mailbox.h b/src/include/kernel/mailbox.h index c9fad0885b69..3ac2ca2fca34 100644 --- a/src/include/kernel/mailbox.h +++ b/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) /** @}*/ diff --git a/src/include/sof/audio/pipeline.h b/src/include/sof/audio/pipeline.h index 511a3cde14b9..19d534c4a4fc 100644 --- a/src/include/sof/audio/pipeline.h +++ b/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 */ diff --git a/src/platform/intel/cavs/lib/clk.c b/src/platform/intel/cavs/lib/clk.c index c48c8ecc0ded..14587a485733 100644 --- a/src/platform/intel/cavs/lib/clk.c +++ b/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); diff --git a/src/schedule/ll_schedule.c b/src/schedule/ll_schedule.c index a649cc084d36..4a8843f4e846 100644 --- a/src/schedule/ll_schedule.c +++ b/src/schedule/ll_schedule.c @@ -38,6 +38,8 @@ DECLARE_SOF_UUID("ll-schedule", ll_sched_uuid, 0x4f9c3ec7, 0x7b55, 0x400c, DECLARE_TR_CTX(ll_tr, SOF_UUID(ll_sched_uuid), LOG_LEVEL_INFO); +void *_debug_task_watch; + /* one instance of data allocated per core */ struct ll_schedule_data { struct list_item tasks; /* list of ll tasks */ @@ -48,6 +50,9 @@ struct ll_schedule_data { struct ll_schedule_domain *domain; /* scheduling domain */ }; +atomic_t *_debug_num_tasks; +void *_debug_ll_domain; + const struct scheduler_ops schedule_ll_ops; #define perf_ll_sched_trace(pcd, ll_sched) \ @@ -55,6 +60,31 @@ const struct scheduler_ops schedule_ll_ops; (uint32_t)((pcd)->plat_delta_peak), \ (uint32_t)((pcd)->cpu_delta_peak)) +static void _debug_dump_ll_regs(struct ll_schedule_data *sch, uint32_t line) +{ + int cpu = cpu_get_id(); + + mailbox_sw_reg_write(SRAM_FOO_START, 0x1337); // Magic word + mailbox_sw_reg_write(SRAM_FOO_NUM_TASKS, atomic_read(&sch->num_tasks)); + mailbox_sw_reg_write(SRAM_FOO_TOTAL_TASKS, + atomic_read(&sch->domain->total_num_tasks)); + mailbox_sw_reg_write(SRAM_FOO_CLIENTS, + atomic_read(&sch->domain->num_clients)); + mailbox_sw_reg_write(SRAM_FOO_REGISTERED, sch->domain->registered[cpu]); + mailbox_sw_reg_write(SRAM_FOO_ENABLED, sch->domain->enabled[cpu]); + mailbox_sw_reg_write64(SRAM_FOO_LAST_TICK, sch->domain->last_tick); + mailbox_sw_reg_write(SRAM_FOO_CLK, sch->domain->clk); + mailbox_sw_reg_write(SRAM_FOO_LINE, line); +} + +static inline void _debug_dump_task_state(struct task *task, uint32_t line) +{ + if (task == _debug_task_watch) { + mailbox_sw_reg_write(SRAM_FOO_LL_TASK_STATE, task->state); + mailbox_sw_reg_write(SRAM_FOO_LL_TASK_LINE, line); + } +} + static bool schedule_ll_is_pending(struct ll_schedule_data *sch) { struct list_item *tlist; @@ -71,6 +101,7 @@ static bool schedule_ll_is_pending(struct ll_schedule_data *sch) if (domain_is_pending(sch->domain, task, &sched_comp)) { task->state = SOF_TASK_STATE_PENDING; + _debug_dump_task_state(task, __LINE__); pending_count++; } } @@ -102,10 +133,15 @@ static void schedule_ll_tasks_execute(struct ll_schedule_data *sch, int cpu = cpu_get_id(); int count; + _debug_num_tasks = &sch->num_tasks; + _debug_ll_domain = sch->domain; + /* check each task in the list for pending */ list_for_item_safe(wlist, tlist, &sch->tasks) { task = container_of(wlist, struct task, list); + _debug_dump_task_state(task, __LINE__); + /* run task if its pending and remove from the list */ if (task->state != SOF_TASK_STATE_PENDING) continue; @@ -129,9 +165,13 @@ static void schedule_ll_tasks_execute(struct ll_schedule_data *sch, /* update task's start time */ schedule_ll_task_update_start(sch, task, last_tick); } + + _debug_dump_task_state(task, __LINE__); } platform_shared_commit(sch->domain, sizeof(*sch->domain)); + + _debug_dump_ll_regs(sch, __LINE__); } static void schedule_ll_clients_enable(struct ll_schedule_data *sch) @@ -145,6 +185,8 @@ static void schedule_ll_clients_enable(struct ll_schedule_data *sch) sch->domain->enabled[i] = true; } } + + _debug_dump_ll_regs(sch, __LINE__); } static void schedule_ll_clients_reschedule(struct ll_schedule_data *sch) @@ -156,6 +198,8 @@ static void schedule_ll_clients_reschedule(struct ll_schedule_data *sch) } platform_shared_commit(sch->domain, sizeof(*sch->domain)); + + _debug_dump_ll_regs(sch, __LINE__); } static void schedule_ll_tasks_run(void *data) @@ -164,6 +208,7 @@ static void schedule_ll_tasks_run(void *data) uint32_t num_clients = 0; uint64_t last_tick; uint32_t flags; + bool pending; domain_disable(sch->domain, cpu_get_id()); @@ -192,8 +237,11 @@ static void schedule_ll_tasks_run(void *data) notifier_event(sch, NOTIFIER_ID_LL_PRE_RUN, NOTIFIER_TARGET_CORE_LOCAL, NULL, 0); + pending = schedule_ll_is_pending(sch); + mailbox_sw_reg_write(SRAM_FOO_LL_PENDING, pending); + /* run tasks if there are any pending */ - if (schedule_ll_is_pending(sch)) + if (pending) schedule_ll_tasks_execute(sch, last_tick); notifier_event(sch, NOTIFIER_ID_LL_POST_RUN, @@ -207,6 +255,8 @@ static void schedule_ll_tasks_run(void *data) if (!num_clients) schedule_ll_clients_reschedule(sch); + _debug_dump_ll_regs(sch, __LINE__); + spin_unlock(&sch->domain->lock); irq_local_enable(flags); @@ -253,6 +303,9 @@ static int schedule_ll_domain_set(struct ll_schedule_data *sch, platform_shared_commit(sch->domain, sizeof(*sch->domain)); + _debug_dump_ll_regs(sch, __LINE__); + _debug_dump_task_state(task, __LINE__); + spin_unlock(&sch->domain->lock); return 0; @@ -291,6 +344,9 @@ static void schedule_ll_domain_clear(struct ll_schedule_data *sch, platform_shared_commit(sch->domain, sizeof(*sch->domain)); + _debug_dump_ll_regs(sch, __LINE__); + _debug_dump_task_state(task, __LINE__); + spin_unlock(&sch->domain->lock); domain_unregister(sch->domain, task, atomic_read(&sch->num_tasks)); @@ -322,6 +378,8 @@ static void schedule_ll_task_insert(struct task *task, struct list_item *tasks) static int schedule_ll_task(void *data, struct task *task, uint64_t start, uint64_t period) { + static uint32_t _debug_num_sched = 0; + static uint32_t _debug_num_set_fail = 0; struct ll_schedule_data *sch = data; struct ll_task_pdata *pdata; struct list_item *tlist; @@ -331,6 +389,10 @@ static int schedule_ll_task(void *data, struct task *task, uint64_t start, irq_local_disable(flags); + if (task == _debug_task_watch) { + mailbox_sw_reg_write(SRAM_FOO_LL_TASK_SCHED, ++_debug_num_sched); + } + /* check if task is already scheduled */ list_for_item(tlist, &sch->tasks) { curr_task = container_of(tlist, struct task, list); @@ -359,6 +421,7 @@ static int schedule_ll_task(void *data, struct task *task, uint64_t start, /* set schedule domain */ ret = schedule_ll_domain_set(sch, task, period); if (ret < 0) { + mailbox_sw_reg_write(SRAM_FOO_LL_SET_FAIL, ++_debug_num_set_fail); list_item_del(&task->list); goto out; } @@ -372,6 +435,9 @@ static int schedule_ll_task(void *data, struct task *task, uint64_t start, platform_shared_commit(sch->domain, sizeof(*sch->domain)); + _debug_dump_ll_regs(sch, __LINE__); + _debug_dump_task_state(task, __LINE__); + out: irq_local_enable(flags); @@ -416,6 +482,7 @@ static int schedule_ll_task_free(void *data, struct task *task) /* release the resources */ task->state = SOF_TASK_STATE_FREE; + _debug_dump_task_state(task, __LINE__); ll_pdata = ll_sch_get_pdata(task); rfree(ll_pdata); ll_sch_set_pdata(task, NULL); @@ -427,6 +494,7 @@ static int schedule_ll_task_free(void *data, struct task *task) static int schedule_ll_task_cancel(void *data, struct task *task) { + static uint32_t _debug_num_cancel = 0; struct ll_schedule_data *sch = data; struct list_item *tlist; struct task *curr_task; @@ -447,10 +515,16 @@ static int schedule_ll_task_cancel(void *data, struct task *task) } } + if (task == _debug_task_watch) + mailbox_sw_reg_write(SRAM_FOO_LL_CANCEL, ++_debug_num_cancel); + /* remove work from list */ task->state = SOF_TASK_STATE_CANCEL; + _debug_dump_task_state(task, __LINE__); list_item_del(&task->list); + _debug_dump_ll_regs(sch, __LINE__); + irq_local_enable(flags); return 0; @@ -489,6 +563,8 @@ static int reschedule_ll_task(void *data, struct task *task, uint64_t start) out: platform_shared_commit(sch->domain, sizeof(*sch->domain)); + _debug_dump_ll_regs(sch, __LINE__); + irq_local_enable(flags); return 0; @@ -514,11 +590,14 @@ static void scheduler_free_ll(void *data) static void ll_scheduler_recalculate_tasks(struct ll_schedule_data *sch, struct clock_notify_data *clk_data) { + static uint32_t _debug_num_recalc = 0; uint64_t current = platform_timer_get(timer_get()); struct list_item *tlist; struct task *task; uint64_t delta_ms; + mailbox_sw_reg_write(SRAM_FOO_LL_RECALC, ++_debug_num_recalc); + list_for_item(tlist, &sch->tasks) { task = container_of(tlist, struct task, list); delta_ms = (task->start - current) / @@ -527,6 +606,8 @@ static void ll_scheduler_recalculate_tasks(struct ll_schedule_data *sch, task->start = delta_ms ? current + sch->domain->ticks_per_ms * delta_ms : current + (sch->domain->ticks_per_ms >> 3); + + _debug_dump_task_state(task, __LINE__); } } diff --git a/src/schedule/timer_domain.c b/src/schedule/timer_domain.c index 10697d0180d0..b63a602fd139 100644 --- a/src/schedule/timer_domain.c +++ b/src/schedule/timer_domain.c @@ -75,6 +75,8 @@ struct timer_zdata zdata[CONFIG_CORE_COUNT]; const struct ll_schedule_domain_ops timer_domain_ops; +extern uint32_t _debug_last_clk_time; + static inline void timer_report_delay(int id, uint64_t delay) { uint32_t ll_delay_us = (delay * 1000) / @@ -86,12 +88,15 @@ static inline void timer_report_delay(int id, uint64_t delay) return; #endif - if (delay <= UINT_MAX) - tr_err(&ll_tr, "timer_report_delay(): timer %d delayed by %d uS %d ticks", - id, ll_delay_us, (unsigned int)delay); - else - tr_err(&ll_tr, "timer_report_delay(): timer %d delayed by %d uS, ticks > %u", - id, ll_delay_us, UINT_MAX); + //if (delay <= UINT_MAX) + // tr_err(&ll_tr, "timer_report_delay(): timer %d delayed by %d uS %d ticks", + // id, ll_delay_us, (unsigned int)delay); + //else + // tr_err(&ll_tr, "timer_report_delay(): timer %d delayed by %d uS, ticks > %u", + // id, ll_delay_us, UINT_MAX); + + tr_err(&ll_tr, "timer_report_delay(): @@@ lask clk time %d", + _debug_last_clk_time); /* Fix compile error when traces are disabled */ (void)ll_delay_us; diff --git a/src/trace/trace.c b/src/trace/trace.c index 52a4b3ce4fe0..d4b04883a69a 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -107,7 +107,7 @@ static inline bool trace_filter_pass(uint32_t lvl, { STATIC_ASSERT(LOG_LEVEL_CRITICAL < LOG_LEVEL_VERBOSE, LOG_LEVEL_CRITICAL_MUST_HAVE_LOWEST_VALUE); - return lvl <= ctx->level; + return lvl <= LOG_LEVEL_WARNING; } void trace_log(bool send_atomic, const void *log_entry,