Skip to content

[BUG][Zephyr] multiple-pipeline-capture-200.sh fails on ADLP-NOCODEC #5556

Closed
Closed
[BUG][Zephyr] multiple-pipeline-capture-200.sh fails on ADLP-NOCODEC#5556
Assignees
kv2019i
Labels
ADLApplies to Alder Lake platformP1Blocker bugs or important featuresTGLApplies to Tiger LakeZephyrIssues only observed with Zephyr integratedbugSomething isn't working as expected
Milestone
v2.1

Description

@kv2019i
kv2019i
opened on Mar 16, 2022

Describe the bug

To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-adl-nocodec.tplg MODEL=ADLP_RVP_NOCODEC_ZEPHYR ~/sof-test/test-case/multiple-pipeline.sh -f c -l 200

Reproduction Rate
100% (with 200 iterations)

Expected behavior
Test passes

Impact
Recording fails.

Environment

  1. sof-2.1 stable branch SOF+Zephyr
  2. Name of the topology file
    • Topology: sof-cavs-nocodec
  3. Name of the platform(s) on which the bug is observed.
    • Platform: ADLP, TGLP

Screenshots or console output

[       52109.633346] (          22.187500) c2 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:962  INFO ssp_early_start(): SSE set for SSP0
[       52253.227090] (         143.593750) c2 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:1079 INFO ssp_trigger() cmd 1
[       52273.331256] (          20.104166) c2 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:977  INFO ssp_start()
[       80064.788485] (       27791.457031) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40517
[       86218.694491] (        6153.905762) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40763
[      136613.588321] (       50394.894531) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40503
[      148851.712835] (       12238.125000) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 41096
[      195152.388079] (       46300.675781) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40399
[      197192.440081] (        2040.052002) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40367
[      213275.356109] (       16082.916016) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40700
[      221436.084951] (        8160.729004) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 41717
[      229411.605467] (        7975.520508) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40619

Activity

  1. kv2019i
    added
    bugSomething isn't working as expected
    ZephyrIssues only observed with Zephyr integrated
    TGLApplies to Tiger Lake
    ADLApplies to Alder Lake platform
    on Mar 16, 2022
  2. kv2019i
    self-assigned this
    on Mar 16, 2022

  3. kv2019i commented on Mar 16, 2022

    @kv2019i
    kv2019i
    on Mar 16, 2022
    CollaboratorAuthor

    Some tidbits so far:

  4. ranj063 commented on Mar 16, 2022

    @ranj063
    ranj063
    on Mar 16, 2022
    Collaborator

    @kv2019i this must also include DMIC capture no? not just SSP capture? Interestingly, the chrome team brought an issue on ADL with DMIC capture (with noise cancellation on core 1) and HDMI playback with similar logs. Of course it doesnt use zephyr.

  5. lgirdwood
    added this to the v2.1 milestone on Mar 16, 2022

  6. lgirdwood commented on Mar 16, 2022

    @lgirdwood
    lgirdwood
    on Mar 16, 2022
    Member

    @kv2019i can we try the following patch to show the IRQs enabled and the status. We may see the culprit....

    diff --git a/src/lib/agent.c b/src/lib/agent.c
index 1aac47796..44753bb54 100644
--- a/src/lib/agent.c
+++ b/src/lib/agent.c
@@ -81,6 +81,9 @@ static enum task_state validate(void *data)
                else
                        tr_warn(&sa_tr, "validate(), ll drift detected, delta = %u",
                                (unsigned int)delta);
+               tr_warn(&sa_tr, "irq enabled %x status %x",
+                       arch_interrupt_get_enabled(),
+                       arch_interrupt_get_status());
        }
 
        /* update last_check to current */

  7. lgirdwood commented on Mar 16, 2022

    @lgirdwood
    lgirdwood
    on Mar 16, 2022
    Member

    @kv2019i I think we need to disable agent (so we only have 1 IRQ user for the timer - no context sharing) and add some checks like (untested).

    diff --git a/src/schedule/zephyr_domain.c b/src/schedule/zephyr_domain.c
index 6b9960268..1c38db6d7 100644
--- a/src/schedule/zephyr_domain.c
+++ b/src/schedule/zephyr_domain.c
@@ -101,6 +101,7 @@ static void zephyr_domain_timer_fn(struct k_timer *timer)
 	struct zephyr_domain *zephyr_domain = k_timer_user_data_get(timer);
 	uint64_t now = k_uptime_ticks();
 	int core;
+	int missed_irq_warn = 0;
 
 	if (!zephyr_domain)
 		return;
@@ -112,8 +113,13 @@ static void zephyr_domain_timer_fn(struct k_timer *timer)
 	 * struct task::start for a strictly periodic Zephyr-based LL scheduler
 	 * implementation, they will be removed after a short grace period.
 	 */
-	while (zephyr_domain->ll_domain->next_tick <= now)
+	while (zephyr_domain->ll_domain->next_tick <= now) {
 		zephyr_domain->ll_domain->next_tick += LL_TIMER_PERIOD_TICKS;
+		if (!missed_irq_warn++)
+			tr_err(&ll_tr, "missed IRQ now %ld next %ld delta %ld", now,
+				zephyr_domain->ll_domain->next_tick,
+				now - zephyr_domain->ll_domain->next_tick);
+	}
 
 	for (core = 0; core < CONFIG_CORE_COUNT; core++) {
 		struct zephyr_domain_thread *dt = zephyr_domain->domain_thread + core;
diff --git a/src/schedule/zephyr_ll.c b/src/schedule/zephyr_ll.c
index 5af538767..1c19330da 100644
--- a/src/schedule/zephyr_ll.c
+++ b/src/schedule/zephyr_ll.c
@@ -21,12 +21,18 @@ DECLARE_SOF_UUID("zll-schedule", zll_sched_uuid, 0x1547fe68, 0xde0c, 0x11eb,
 
 DECLARE_TR_CTX(ll_tr, SOF_UUID(zll_sched_uuid), LOG_LEVEL_INFO);
 
+/* headroom for scheduling, warning if 10uS late. */
+/* TODO: use Zephyr timing macros instead of hard codec clocks */
+#define HEADROOM_CYCLES		(38400 / 100)
+
 /* per-scheduler data */
 struct zephyr_ll {
 	struct list_item tasks;			/* list of ll tasks */
 	unsigned int n_tasks;			/* task counter */
 	struct ll_schedule_domain *ll_domain;	/* scheduling domain */
 	unsigned int core;			/* core ID of this instance */
+	unsigned int period_cycles;		/* period of LL tick in cycles */
+	unsigned int last_tick_cycles;		/* last tick cycles */
 };
 
 /* per-task scheduler data */
@@ -174,6 +180,18 @@ static void zephyr_ll_run(void *data)
 	struct task *task;
 	struct list_item *list;
 	uint32_t flags;
+	unsigned int cycles_now = k_cycle_get_32();
+	unsigned int cycles_target = sch->last_tick_cycles + sch->period_cycles
+				   + HEADROOM_CYCLES;
+
+	/* are we scheduled on time ? if not lets report it as we could be
+	 * blocked by other higher priority threads or IRQs.
+	 */
+	if (cycles_now > cycles_target) {
+		tr_err(&ll_tr, "LL scheduling %d cycles late",
+			cycles_now - cycles_target);
+	}
+	sch->last_tick_cycles = cycles_now;
 
 	zephyr_ll_lock(sch, &flags);
 
@@ -343,6 +361,8 @@ static int zephyr_ll_task_schedule_common(struct zephyr_ll *sch, struct task *ta
 
 	zephyr_ll_unlock(sch, &flags);
 
+	//TODO: is this the best place to initial set last tick cycles.
+	sch->last_tick_cycles = k_cycle_get_32();
 	ret = domain_register(sch->ll_domain, task, &zephyr_ll_run, sch);
 	if (ret < 0)
 		tr_err(&ll_tr, "zephyr_ll_task_schedule: cannot register domain %d",
@@ -534,6 +554,9 @@ int zephyr_ll_scheduler_init(struct ll_schedule_domain *domain)
 	sch->ll_domain = domain;
 	sch->core = cpu_get_id();
 
+	// TODO: get this from topology and use Zephyr API to calc cycles.
+	sch->period_cycles = 38400;
+
 	scheduler_init(domain->type, &z

  8. kv2019i commented on Mar 16, 2022

    @kv2019i
    kv2019i
    on Mar 16, 2022
    CollaboratorAuthor

    The timer tick does not seem to be systematically late at all. There is definitely some minor jitter in waking up the per-core threads (and this has increased lately, is less severe before the spinlock change), but when I've traced what happens on the n+1 cycle after agent notices the jitter, we always catch up.

    So it could be the actual failure is caused by too much "agent traffic" and then some DMA runs out of data. Like here:

    [   619607122.097775] (        6040.729004) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40708
[   619613215.587116] (        6093.489258) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40687
[   619617305.222370] (        4089.635254) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 41312
[   619627351.888638] (       10046.666016) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40494
[   619627546.888630] (         194.999985) c3 host         4.18          src/audio/host.c:481  INFO no bytes to copy, 0 avail in buffer, 384 free in DMA
[   619629445.846888] (        1898.958252) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40603

[   619635556.054978] (          40.677082) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 40688
[   619636555.065356] (         213.541656) c2 pipe         2.11  ....../pipeline-stream.c:261  INFO pipe trigger cmd 6
[   619636745.638265] (         102.760414) c0 pipe         21.71 ....../pipeline-stream.c:261  INFO pipe trigger cmd 6
[   619637490.481985] (         265.833313) c2 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe08c000 pipe-task
[   619635515.377897] (        6069.531250) c2 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[   619635590.794560] (          34.739582) c0 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[   619635710.065389] (         119.270828) c2 dai          2.10           src/audio/dai.c:882  ERROR dai_report_xrun(): overrun due to no space available
[   619635898.867465] (         188.802078) c0 dai          21.70          src/audio/dai.c:882  ERROR dai_report_xrun(): overrun due to no space available
[   619636122.200789] (         223.333328) c2 dai          2.10           src/audio/dai.c:766  ERROR comp_overrun(): sink->free = 756, copy_bytes = 0
[   619636341.523697] (         219.322906) c0 dai          21.70          src/audio/dai.c:766  ERROR comp_overrun(): sink->free = 512, copy_bytes = 0
[   619636642.877852] (          87.812500) c2 pipe         2.11  ....../pipeline-stream.c:134  ERROR pipeline_copy(): ret = -61, start->comp.id = 10, dir = 0
[   619636781.263263] (          35.625000) c0 pipe         21.71 ....../pipeline-stream.c:134  ERROR pipeline_copy(): ret = -61, start->comp.id = 70, dir = 0
[   619636978.971589] (         197.708328) c2 pipe         2.11  ..../pipeline-schedule.c:183  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[   619637224.648662] (         245.677078) c0 pipe         21.71 ..../pipeline-schedule.c:183  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.
[   619637510.169484] (          19.687500) c2 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 1 total_num_tasks 6
[   619637532.461150] (          22.291666) c2 zll-schedule       ......../zephyr_domain.c:209  INFO zephyr_domain_unregister domain->type 1 domain->clk 4
[   619637691.888227] (         159.427078) c0 zll-schedule       src/schedule/zephyr_ll.c:67   INFO task complete 0xbe087b80 pipe-task 
[   619637711.159060] (          19.270832) c0 zll-schedule       src/schedule/zephyr_ll.c:69   INFO num_tasks 3 total_num_tasks 5
[   619637775.742390] (          64.583328) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 42640
[   619638673.398605] (         897.656189) c0 dmic-dai     2.1   ....../intel/dmic/dmic.c:508  INFO dmic_irq_handler(), OUTSTAT0 = 0x3000000c, OUTSTAT1 = 0x28000000
[   619939207.240829] (      300515.000000) c1 zll-schedule       src/schedule/zephyr_ll.c:142  INFO ll task 0xbe084f80 pipe-task [   619638692.252771] (          18.854166) c0 dmic-dai     2.1   ....../intel/dmic/dmic.c:517  ERROR dmic_irq_handler(): full fifo B or PDM overrun avg 10722, max 12786
[   619939231.407495] (          24.166666) c1 zll-schedule       ......../zephyr_domain.c:89   INFO ll timer avg 11030, max 12994, overruns 0
[   619969135.208390] (       29903.800781) c3 zll-schedule       src/schedule/zephyr_ll.c:142  INFO ll task 0xbe089e00 pipe-task  avg 6765, max 7902
[   619969160.052139] (          24.843748) c3 zll-schedule       ......../zephyr_domain.c:89   INFO ll timer avg 6968, max 8115, overruns 0

    So in summary, we probably need to try removing the agent. It's adding to the problem here and if we have load issues, the DSP load traces will catch that.

  9. kv2019i commented on Mar 16, 2022

    @kv2019i
    kv2019i
    on Mar 16, 2022
    CollaboratorAuthor

    #5557 did not help. Logs are less cluttered, but there's a still failure in configuring SSP1 DAI (on core3).

  10. kv2019i commented on Mar 17, 2022

    @kv2019i
    kv2019i
    on Mar 17, 2022
    CollaboratorAuthor

    @lgirdwood Some log data with your patches. First the IRQs. The status doesn't change during any tests when measured at agent. Probably if some irq is blocked, that would have to be observed outside the agent:

    [ 25633407.734375] ( 9.739583) c0 sa src/lib/agent.c:87 WARN irq enabled 10040 status 222
    [ 25641487.421875] ( 10.520833) c0 sa src/lib/agent.c:87 WARN irq enabled 10040 status 222
    [ 25645529.895833] ( 11.119792) c0 sa src/lib/agent.c:87 WARN irq enabled 10040 status 222

  11. 1 remaining item

  12. kv2019i commented on Mar 17, 2022

    @kv2019i
    kv2019i
    on Mar 17, 2022
    CollaboratorAuthor

    Managed to reproduce on one of the CI machines now. There's a Zephyr OS panic. Debugging it now.

  13. kv2019i
    added
    P1Blocker bugs or important features
    on Mar 17, 2022

  14. kv2019i commented on Mar 17, 2022

    @kv2019i
    kv2019i
    on Mar 17, 2022
    CollaboratorAuthor

    Status update:

    • the Zephyr panic dumps are scrambled but @lyakh managed to descramble one and it points to dai_report_xrun()
    • but in today's testing, failure has happened in multiple ways, there is not always a Zephyr panic
    • common thing is an xrun on SSP0 on core0 when three other streams are already active
    • other observed failure patterns
      - running out of memory allocating a new pipe
      - no panic, no out-of-mem, just xrun in the FW log

    Bisect shows the spinlock #5286 makes this problem easier to reproduce.

  15. kv2019i commented on Mar 17, 2022

    @kv2019i
    kv2019i
    on Mar 17, 2022
    CollaboratorAuthor

    Another update:

    • issue hit without the new spinlock implementation (Convert spinlock to Zephyr API #5286) -- takes much longer, but can still be hit
    • issue hit on TGL -- harder to hit as well, but similar error footprint

  16. kv2019i commented on Mar 21, 2022

    @kv2019i
    kv2019i
    on Mar 21, 2022
    CollaboratorAuthor

    There's a draft workaround for the Zephyr timer reliability, but unfortunately the error is still happening with that workaround in place. There's still unexplained spikes in timer invocation, so there can still be a connection, but at least the error in timer average time does not explain the multiple-pipeline-capture fail.

  17. lgirdwood commented on Mar 21, 2022

    @lgirdwood
    lgirdwood
    on Mar 21, 2022
    Member

    @kv2019i Could be IRQs OFF in locks ?
    could we have a hack in k_spin_unlock() that does

    1. Check int timer status IRQ bit
    2. if 1 is pending then log delta between time now and timeout. Also log caller.

  18. kv2019i commented on Mar 21, 2022

    @kv2019i
    kv2019i
    on Mar 21, 2022
    CollaboratorAuthor

    I'll resume the IRQ timing tomorrow. I spent today with DW-DMA. The variety of symptoms still leaves me puzzling. Sometime the error happens at state transitions (either a Zephyr OS panic via invalid load or a timed out IPC), but often time the main failure is an xrun in stable state. There are four streams running on four cores, all using DW-DMA. Traces like these are very common:

    [ 374512296.472385] ( 18.750000) c2 ssp-dai 1.0 /drivers/intel/ssp/ssp.c:1001 INFO ssp_start() OUT
    [ 374849807.761057] ( 1738.541626) c2 zll-schedule ......../zephyr_domain.c:125 INFO domain tick avg 38400, max 41351
    [ 376558874.411895] ( 11971.875000) c2 zll-schedule src/schedule/zephyr_ll.c:142 INFO ll task 0xbe081f80 pipe-task avg 4581, max 8032
    [ 376558910.088977] ( 35.677082) c2 zll-schedule ......../zephyr_domain.c:89 INFO ll timer avg 4845, max 8375, overruns 0
    [ 376560620.453492] ( 1710.364502) c2 dw-dma src/drivers/dw/dma.c:1146 INFO dw_dma_get_data_size(): avail 3188078672 free 3188078676
    [ 376560639.411825] ( 18.958332) c2 dw-dma src/drivers/dw/dma.c:1148 INFO dw_dma_get_data_size(): av n1 496 n2 520 n3 520

    Note: sof-logger run with 19.2 clock reference, so timestamp are off by 2X in the output.

    The last trace is a local modification that prints the "avail bytes" value in three last invocations to get_data_size(). So previous iterations have been normal, but suddenly in middle of stable streaming state, the DW-DMA goes crazy (avail
    3188078672 ). One soon after this, the streams on other cores start returning errors.

  19. kv2019i commented on Mar 23, 2022

    @kv2019i
    kv2019i
    on Mar 23, 2022
    CollaboratorAuthor

    Status update:

  20. kv2019i commented on Mar 23, 2022

    @kv2019i
    kv2019i
    on Mar 23, 2022
    CollaboratorAuthor

    Status update:

  21. kv2019i
    added a commit that references this issue on Mar 25, 2022

    zephyr: ll-scheduler: k_sem handle must be in coherent memory

    c4fd060

  22. kv2019i commented on Mar 25, 2022

    @kv2019i
    kv2019i
    on Mar 25, 2022
    CollaboratorAuthor

    Performed a bisect of sort on all current fixes and it turns out the k_sem coherency fix is the key change. Others are probably valid fixed, but not required for this bug. Test details at #5588

  23. lgirdwood
    added a commit that references this issue on Mar 28, 2022

    zephyr: ll-scheduler: k_sem handle must be in coherent memory

    6a8b2e8

  24. kv2019i commented on Mar 29, 2022

    @kv2019i
    kv2019i
    on Mar 29, 2022
    CollaboratorAuthor

    No errors in Intel daily plan 11433, so potentially fixed by the fix to #5556.

  25. kv2019i commented on Apr 1, 2022

    @kv2019i
    kv2019i
    on Apr 1, 2022
    CollaboratorAuthor

    Not seen in Intel daily testing for multiple days, closing.

  26. kv2019i
    closed this as completedon Apr 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

ADLApplies to Alder Lake platformP1Blocker bugs or important featuresTGLApplies to Tiger LakeZephyrIssues only observed with Zephyr integratedbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions