Skip to content

[BUG][WHL][CML][DMIC] IPC timeout in tests incorporating DMIC interface #2347

New issue
New issue
Closed
Closed
[BUG][WHL][CML][DMIC] IPC timeout in tests incorporating DMIC interface#2347
Assignees
tlaudazrombel
Labels
CMLApplies to Comet Lake platformIPC timeoutIPC timeout observedP1Blocker bugs or important featuresWHLApplies to WhiskeyLake platformbugSomething isn't working as expected
Milestone
v1.5

Description

@zrombel
zrombel
opened on Feb 3, 2020

Describe the bug
Bug occurs on WHL platform, in tests with DMIC interface.
IPC timeout happens when sending IPC DaiConfig or PcmParams to FW.
No Trace Logs are received, memory window debug might be needed.
After bisect commit bce7f24 is found to introduce the bug.

To Reproduce
Any Python scripts DMIC test with option --iterations=100

Reproduction Rate
25%

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
    • Python script tests: 99e665ecf5d62a9710875fd4163e09b85b705009
    • SOF: bce7f24
  2. Example test: 05_06_TestDmicBothFifoSimpleCapture16000hz16b16b2ch --iterations=100

Logs
05_06_TestDmicBothFifoSimpleCapture48000hz32b32b2ch.zip
05_06_TestDmicBothFifoSimpleCapture16000hz16b16b2ch.zip

Activity

  1. zrombel
    added
    bugSomething isn't working as expected
    WHLApplies to WhiskeyLake platform
    CMLApplies to Comet Lake platform
    on Feb 3, 2020
  2. zrombel
    assigned
    tlauda
    on Feb 3, 2020
  3. lgirdwood
    added this to the v1.5 milestone on Feb 3, 2020
  4. lgirdwood
    added
    IPC timeoutIPC timeout observed
    P1Blocker bugs or important features
    on Feb 12, 2020

  5. lgirdwood commented on Feb 12, 2020

    @lgirdwood
    lgirdwood
    on Feb 12, 2020
    Member

    I think this is a duplicate of #2265
    This also appears to happen with SSP DAI config too (taken from recent CI failures on APL).

    src/ipc/handler.c:556 	ipc: dai 1.0 -> config 
    0      2          DAI 1.8        353178.385417         4.270833      src/audio/dai.c:680 	dai_config() dai 1.0
    0      2          DMA            353182.135417         3.750000 src/drivers/dw/dma.c:182 	dw_dma_channel_get(): dma 0 request channel 0
    0      2          SSP            353190.729167         8.593750 ers/intel/cavs/ssp.c:140 	ssp_set_config(), config->format = 0x4001
    0      2          SSP            353201.666667        10.937500 ers/intel/cavs/ssp.c:619 	ssp_set_config(), sscr0 = 0xc1c00f7f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2100000
    0      2          SSP            353204.843750         3.177083 ers/intel/cavs/ssp.c:622 	ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x03030000, ssioc = 0x00000020
    0      2          SSP            353207.395833         2.552083 ers/intel/cavs/ssp.c:624 	ssp_set_config(), ssrsa = 0x00000003, sstsa = 0x00000003
    0      2          DAI 2.14       353210.833333         3.437500      src/audio/dai.c:680 	dai_config() dai 1.0
    0      2          DMA            353213.854167         3.020833 src/drivers/dw/dma.c:182 	dw_dma_channel_get(): dma 1 request channel 0
    0      2          SSP            353220.833333         6.979167 ers/intel/cavs/ssp.c:140 	ssp_set_config(), config->format = 0x4001
    0      2          SSP            353228.802083         7.968750 ers/intel/cavs/ssp.c:619 	ssp_set_config(), sscr0 = 0xc1c00f7f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2100000
    0      2          SSP            353231.822917         3.020833 ers/intel/cavs/ssp.c:622 	ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x03030000, ssioc = 0x00000020
    0      2          SSP            353234.375000         2.552083 ers/intel/cavs/ssp.c:624 	ssp_set_config(), ssrsa = 0x00000003, sstsa = 0x00000003
    0      2          IPC            353281.250000        46.875000    src/ipc/handler.c:556 	ipc: dai 1.0 -> config 
    0      2          DAI 1.8        353284.895833         3.645833      src/audio/dai.c:680 	dai_config() dai 1.0
    0      2          SSP            353295.416667        10.520833 ers/intel/cavs/ssp.c:140 	ssp_set_config(), config->format = 0x4001
    0      2          SSP            353303.854167         8.437500 ers/intel/cavs/ssp.c:619 	ssp_set_config(), sscr0 = 0xc1c00f7f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2100000
    0      2          SSP            353322.447917        18.593750 ers/intel/cavs/ssp.c:140 	ssp_set_config(), config->format = 0x4001
    0      2          SSP            353330.468750         8.020833 ers/intel/cavs/ssp.c:619 	ssp_set_config(), sscr0 = 0xc1c00f7f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2100000
    0      2          SSP            353333.333333         2.864583 ers/intel/cavs/ssp.c:622 	ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x03030000, ssioc = 0x00000020
    0      2          SSP            353335.989583         2.656250 ers/intel/cavs/ssp.c:624 	ssp_set_config(), ssrsa = 0x00000003, sstsa = 0x00000003

    The funny thing is that we iterate over the same component twice here ? @tlauda list corruption ?

    int ipc_comp_dai_config(struct ipc *ipc, struct sof_ipc_dai_config *config)
{
	bool comp_on_core[PLATFORM_CORE_COUNT] = { false };
	struct sof_ipc_comp_dai *dai;
	struct sof_ipc_reply reply;
	struct ipc_comp_dev *icd;
	struct list_item *clist;
	int ret = -ENODEV;
	int i;

	/* for each component */
	list_for_item(clist, &ipc->comp_list) {
		icd = container_of(clist, struct ipc_comp_dev, list);
		/* make sure we only config DAI comps */
		if (icd->type != COMP_TYPE_COMPONENT) {
			platform_shared_commit(icd, sizeof(*icd));
			continue;
		}

		if (!cpu_is_me(icd->core)) {
			comp_on_core[icd->core] = true;
			ret = 0;
			platform_shared_commit(icd, sizeof(*icd));
			continue;
		}

		if (icd->cd->comp.type == SOF_COMP_DAI ||
		    icd->cd->comp.type == SOF_COMP_SG_DAI) {
			dai = (struct sof_ipc_comp_dai *)&icd->cd->comp;
			platform_shared_commit(icd, sizeof(*icd));
			/*
			 * set config if comp dai_index matches
			 * config dai_index.
			 */
			if (dai->dai_index == config->dai_index &&
			    dai->type == config->type) {
				ret = comp_dai_config(icd->cd, config);
				platform_shared_commit(icd, sizeof(*icd));
				if (ret < 0)
					break;
			}
		}
	}

	if (ret < 0) {
		trace_ipc_error("ipc_comp_dai_config() error: "
				"comp_dai_config() failed");
		return ret;
	}

	/* message forwarded only by master core */
	if (!cpu_is_slave(cpu_get_id())) {
		for (i = 0; i < PLATFORM_CORE_COUNT; ++i) {
			if (!comp_on_core[i])
				continue;

			ret = ipc_process_on_core(i);
			if (ret < 0)
				return ret;

			/* check whether IPC failed on slave core */
			mailbox_hostbox_read(&reply, sizeof(reply), 0,
					     sizeof(reply));
			if (reply.error < 0)
				/* error reply already written */
				return 1;
		}
	}

	return ret;
}

  6. zrombel commented on Feb 12, 2020

    @zrombel
    zrombel
    on Feb 12, 2020
    Author

    Seems like bug no longer occurs.
    Fix found in commit 9985b01 - no error in 400 iterations.
    Confirming on top master 7e88cc0 - no error in 400 and still running up to 1000 iterations. I will give update tomorrow when test are over.

  7. lgirdwood commented on Feb 13, 2020

    @lgirdwood
    lgirdwood
    on Feb 13, 2020
    Member

    @zrombel ok, thanks for checking. I will keep checking CI too.

  8. zrombel commented on Feb 13, 2020

    @zrombel
    zrombel
    on Feb 13, 2020
    Author

    Confimed fix on top master 7e88cc0 - no error in 1000 iterations. Funny thing is that commit 9985b01 only touches traces, is it possible that bug still exists but is well hidden ? @lgirdwood what do you thing about closing the bug?

  9. lgirdwood commented on Feb 13, 2020

    @lgirdwood
    lgirdwood
    on Feb 13, 2020
    Member

    @xiulipan @mengdonglin any objections ?

  10. xiulipan commented on Feb 14, 2020

    @xiulipan
    xiulipan
    on Feb 14, 2020
    Contributor

    @lgirdwood @lgirdwood
    This looks like the race condition with APL NOCODEC, same error with HW PARAMS

    IPC timeout happens when sending IPC DaiConfig or PcmParams to FW.

    This bug will also influence WHL

    @zrombel are you testing with XCC FW or GCC FW?

  11. zrombel commented on Feb 14, 2020

    @zrombel
    zrombel
    on Feb 14, 2020
    Author

    @xiulipan I'm testing only XCC builds

  12. tlauda commented on Feb 14, 2020

    @tlauda
    tlauda
    on Feb 14, 2020
    Contributor

    @lgirdwood @xiulipan I've rootcaused this issue to too small default stack size for EDF tasks. Here is the fix: #2388. Let's see if it will also help with APL failures.

  13. xiulipan commented on Feb 16, 2020

    @xiulipan
    xiulipan
    on Feb 16, 2020
    Contributor

    @tlauda Thanks for the fix, it seems the issue on APL is gone.

  14. lgirdwood commented on Feb 17, 2020

    @lgirdwood
    lgirdwood
    on Feb 17, 2020
    Member

    @zrombel can we close ?

  15. slawblauciak
    assigned
    zrombel
    on Feb 18, 2020

  16. zrombel commented on Feb 18, 2020

    @zrombel
    zrombel
    on Feb 18, 2020
    Author

    I will run tests once again on top of master and if the bug doesn't reproduce I will close the bug.

  17. zrombel commented on Feb 18, 2020

    @zrombel
    zrombel
    on Feb 18, 2020
    Author

    No reproduction on master top 53d35e4. Closing Issue.

  18. zrombel
    closed this as completedon Feb 18, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

CMLApplies to Comet Lake platformIPC timeoutIPC timeout observedP1Blocker bugs or important featuresWHLApplies to WhiskeyLake platformbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions