Skip to content

[BUG IMX] Loopback implementation using demux #3818

New issue
New issue
Open
Open
[BUG IMX] Loopback implementation using demux#3818
Assignees
dbalutaiuliana-prodan
Labels
enhancementNew feature or request
Milestone
TBD

Description

@giuzan
giuzan
opened on Feb 4, 2021

Premise

I think that the loopback feature could be very useful in SOF. With loopback I basically mean a capture PCM from which we can read the samples that are written in playback. You can find this functionality in ALSA, known as ALSA Loopback. I think that performing the loopback job inside the DSP would be very useful. Developers who want to integrate its own echo canceller block can really take advantage of this feature.

I think that I have found a good example of that in sof-apl-demux-pcm512x.m4 topology.

I tried to port that topology into imx8 cs42888. You can find the m4 file here https://github.com/giuzan/sof/blob/c5f4111078e052597e233d3770d773f02f18f1e2/tools/topology/sof-imx8-cs42888-demux.m4.

The topology I build is shown in the following picture:

sof-imx8-cs42888-demux

Unfortunately, I experienced an issue (see description below). It is the reason why I opened this [BUG]. If you think that the loopback topic is beyond this issue, please let me know if it should be treated as a proposed [FEATURE].

Describe the bug

If you run the command
arecord -D hw:1,1 -c 2 -r 48000 -f S16_LE record.wav
the following error is printed
arecord: pcm_read:2149: read error: Input/output error

Moreover, if you arecord during an aplay, the playback stream stops until the arecord does not exit after the error.

To reproduce

arecord -D hw:1,1 -c 2 -r 48000 -f S16_LE record.wav

or

aplay -D hw:1,0 file.wav & arecord -D hw:1,1 -c 2 -r 48000 -f S16_LE record.wav

Reproduction rate

100%

Expected behavior

The file record.wav recorded through the capture pipeline should contain the samples processed by the playback pipeline.

Impact

I cannot implement loopback for echo cancellation.

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
  2. Name of the topology file
    • Topology: sof-imx8-cs42888-demux.m4
  3. Name of the platform(s) on which the bug is observed.
    • Platform: i.MX8QM

Activity

  1. giuzan
    added
    bugSomething isn't working as expected
    on Feb 4, 2021
  2. giuzan
    changed the title [-][BUG IMX][/-] [+][BUG IMX] Loopback implementation using demux[/+] on Feb 4, 2021
  3. dbaluta
    added this to the v1.8 milestone on Feb 4, 2021

  4. lgirdwood commented on Feb 5, 2021

    @lgirdwood
    lgirdwood
    on Feb 5, 2021
    Member

    @giuzan buffers cant do any processing here. i.e. your buf2.0 has 2 inputs. Shouldn't this be demix1.0 -> buf -> echoref2 instead ?

  5. giuzan commented on Feb 6, 2021

    @giuzan
    giuzan
    on Feb 6, 2021
    Author

    @lgirdwood

    Yes, I agree, it sounds weird to me too that a buffer has two input streams. I would expect that the only components which are allowed to have more than one stream (in input or in output) should be only: mixer (that mixes N streams into one) and demux/mux (the first creates one stream from many, the second creates more streams from one). Am I wrong? Or in general is it allowed also for other non-buffer components?

    Anyway, I took inspiration from sof-apl-demux-pcm512x that has the same "double input". See picture below.

    sof-apl-demux-pcm512x

    Do you think the issue I experienced is related to this kind of configuration in general or it could be limited to imx platform only?

  6. giuzan commented on Feb 6, 2021

    @giuzan
    giuzan
    on Feb 6, 2021
    Author

    @lgirdwood

    About your suggestion demix1.0 -> buf -> echoref2

    Do you mean something like that?

    sof-imx8-cs42888-demux

  7. slawblauciak
    added
    enhancementNew feature or request
    and removed
    bugSomething isn't working as expected
    on Feb 9, 2021

  8. lgirdwood commented on Feb 9, 2021

    @lgirdwood
    lgirdwood
    on Feb 9, 2021
    Member

    @giuzan so a buffer only has 1 sink and 1 source but a processing component can have N sinks and N sources (it's upto the component designer). Your pipeline above should have a buffer between ESAI0.IN and ECHO_REF2 but otherwise looks good. Your first pipeline is good if you also connect MUX to ECHO REF (i.e. echo ref has 2 inputs). Note you will need to tell topology that it's OK for some buffer to overrun/underrun (since the user can start PCM0P and PCM0C at different times and in different orders).

  9. giuzan commented on Mar 4, 2021

    @giuzan
    giuzan
    on Mar 4, 2021
    Author

    Hi @lgirdwood and @dbaluta,

    I tried the topology in the picture below. You can find the M4 here https://github.com/giuzan/sof/blob/giuzan_imx-stable-v1.6_loop/tools/topology/sof-imx8-cs42888-demux-loop.m4.

    I implemented a custom component (test loop) that takes as sources the demux output (BUF2.2) and the DAI input (BUF2.1). My wish is that this component would couple the two 2-channels input sources in an output sink containing 2+2 channels (2 from BUF2.2 and 2 from BUF2.1). As first step I tried with a simpler scenario where the sink has only 2 channels, for the moment the DAI input samples are discarded.

    Unfortunately I experienced the same input/output error above in capture scenario. And dmesg shows the following errors:

    [  101.618087] sof-audio-of 556e8000.dsp: error: ipc timed out for 0x60050000 size 12
[  101.625698] sof-audio-of 556e8000.dsp: error: waking up any trace sleepers
[  101.632639] sof-audio-of 556e8000.dsp: error: trace IO error
[  101.634108]  Capture: ASoC: trigger FE cmd: 0 failed: -110
[  102.162080] sof-audio-of 556e8000.dsp: error: ipc timed out for 0x60030000 size 12
[  102.169689] sof-audio-of 556e8000.dsp: error: waking up any trace sleepers
[  104.722083] sof-audio-of 556e8000.dsp: error: ipc timed out for 0x40010000 size 7

    About buffer overrun/underrun, I did not be able to allow it through topology configuration. Hence I hardcoded in buffer.c (just to perform the test):

    buffer->stream.underrun_permitted = true;
buffer->stream.overrun_permitted = true;

    sof-imx8-cs42888-demux-loop

    I tried also another scenario (M4 in https://github.com/giuzan/sof/blob/giuzan_imx-stable-v1.6_loop/tools/topology/sof-testloop-imx8qm-cs42888.m4) where I used the test loop component also in playback, to copy the source in two sinks. I experienced the same issue, in playback also. Could be that is there something wrong with my test component? The code is here https://github.com/giuzan/sof/blob/giuzan_imx-stable-v1.6_loop/src/audio/test_loop/test_loop.c.

    sof-testloop-imx8qm-cs42888

    In particular, I have the issue when I connect the two pipelines, in other words if I remove the following lines from the the topology M4 the streaming (both playback and capture) works:

    SectionGraph."PIPE_LOOP" {
	index "0"

	lines [
		dapm(PIPELINE_LOOPBACK_IN_BUFFER_2, PIPELINE_LOOPBACK_OUT_1)
		dapm(PIPELINE_LOOPBACK_IN_2, PIPELINE_LOOPBACK_IN_BUFFER_2)
	]
}

  10. iuliana-prodan commented on Mar 4, 2021

    @iuliana-prodan
    iuliana-prodan
    on Mar 4, 2021
    Contributor

    Hi @giuzan,

    I intend to look on the loopback, also. So, please, let me give it a try and I'll come back to you.

    First thing to notice on your topology is that you should have two registrable tasks since you have ESAI input and ESAI output.
    The SCHEDULE_TIME_DOMAIN_DMA was written with the assumption that there is only one registrable task.

    Also, after how many iterations do you get the ipc timeout?
    Maybe, try to apply this commit.

    Thanks,
    Iulia

  11. giuzan commented on Mar 5, 2021

    @giuzan
    giuzan
    on Mar 5, 2021
    Author

    Hi @iuliana-prodan,

    Thanks for your feedback.

    I get the ipc at the first iteration.

    Ok, let me know after your try. In the middle, I'll try to apply the commit you linked and repeat the test.

  12. iuliana-prodan commented on Mar 5, 2021

    @iuliana-prodan
    iuliana-prodan
    on Mar 5, 2021
    Contributor

    I get the ipc at the first iteration.

    Great, this will be much easier to reproduce :)

  13. lgirdwood commented on Mar 5, 2021

    @lgirdwood
    lgirdwood
    on Mar 5, 2021
    Member

    @giuzan the IPC timout looks like a hang somewhere ?

  14. giuzan commented on Mar 5, 2021

    @giuzan
    giuzan
    on Mar 5, 2021
    Author

    @lgirdwood On DSP side is difficult to evaluate that, because the sof-logger crashes after the error. I cannot see the log prints before, since I guess that they are not yet flushed.

  15. 7 remaining items

  16. iuliana-prodan commented on Mar 8, 2021

    @iuliana-prodan
    iuliana-prodan
    on Mar 8, 2021
    Contributor

    One more thing for the sof-logger.
    I'm also debugging an ipc timed out issue. I get something like this:

    ...
Playing raw data '16/j16.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Recording WAVE 'test_record.pcm' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
[  582.814139] sof-audio-of 556e8000.dsp: error: ipc timed out for 0x60050000 size 12
[  582.821802] sof-audio-of 556e8000.dsp: info: preventing DSP entering D3 state to preserve context
[  582.830906] sof-audio-of 556e8000.dsp: invalid header size 0x2000200. FW oops is bogus
[  582.838989] sof-audio-of 556e8000.dsp: error: unexpected fault 0x00000000 trace 0x00000000
[  582.847530] sof-audio-of 556e8000.dsp: error: waking up any trace sleepers
[  582.854601] sof-audio-of 556e8000.dsp: error: trace IO error
[  582.861198] sof-audio-of 556e8000.dsp: ASoC: error at snd_soc_pcm_component_trigger on 556e8000.dsp: -110
[  582.871466]  Port0: ASoC: trigger FE cmd: 0 failed: -110
Playing raw data '16/j16.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Recording WAVE 'test_record.pcm' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
aplay: pcm_write:2061: write error: Input/output error
(null)      1  TFAIL  :  ltpapicmd.c:188: Test 568 Playback failed

    While running my test, I have the sof-logger started:

    root@imx8qxpc0mek:~# ./sof-logger -t -l /lib/firmware/imx/sof/sof-imx8x.ldc 2>&1 | tee trace.txt
...
[19469098836.770836] (       96.666664) c0 ipc                       src/ipc/handler.c:457  handler: ipc_glb_stream_message: SOF_IPC_STREAM_PCM_PARAMS = 0x10000
[19469099490.572918] (      653.802063) c0 pipe         1.5       src/audio/pipeline.c:543  pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000
[19469099601.041668] (      110.468750) c0 pipe         1.5       src/audio/pipeline.c:547  pipe params stream_tag 0 channels 2 sample_valid_bytes 2 sample_container_bytes 2
[19469100828.697918] (     1227.656250) c0 dai          1.4            src/audio/dai.c:351  dai_playback_params() dest_dev = 8029 stream_id = 0 src_width = 4 dest_width = 4
[19469100967.604168] (      138.906250) c0 dai          1.4            src/audio/dai.c:357  dai_playback_params() fifo 0x59050020
[19469101452.395836] (      484.791656) c0 pipe         1.5       src/audio/pipeline.c:670  pipe prepare
[19469102562.604168] (     1110.208374) c0 edma                 src/drivers/imx/edma.c:362  EDMA: set config
[19469173324.739586] (    70762.132812) c0 ipc                       src/ipc/handler.c:1400 handler: ipc_cmd: command type 1610612736 or hex = 0x60000000
[19469173453.072918] (      128.333328) c0 ipc                       src/ipc/handler.c:1421 handler: ipc_cmd: command SOF_IPC_GLB_STREAM_MSG = 0x60000000
**error: in logger_read(), fread(..., /sys/kernel/debug/sof/trace) failed: Operation not permitted(-1)**

    When the ipc timed out error occurs I see the above failure in the sof-logger.
    But, next, if I check again the trace, I have the rest of it:

    root@imx8qxpc0mek:~# ./sof-logger -t -l /lib/firmware/imx/sof/sof-imx8x.ldc 2>&1 | tee trace.txt
...
[19469173453.072918] (      128.333328) c0 ipc                       src/ipc/handler.c:1421 handler: ipc_cmd: command SOF_IPC_GLB_STREAM_MSG = 0x60000000
[19469173563.437500] (      110.364586) c0 ipc                       src/ipc/handler.c:468  handler: ipc_glb_stream_message: SOF_IPC_STREAM_TRIG_START/STOP...
[19469173683.750000] (      120.312500) c0 ipc                       src/ipc/handler.c:416  ipc: ipc_stream_trigger: comp 0 -> trigger cmd 0x40000
[19469173794.166668] (      110.416664) c0 pipe         1.5       src/audio/pipeline.c:933  pipe trigger cmd 1, time is = 338afa601f
[19469174030.052086] (      235.885422) c0 edma                 src/drivers/imx/edma.c:137  EDMA: start(15)
[19469174168.020836] (      137.968750) c0 sai          5.1      src/drivers/imx/sai.c:376  SAI: sai_trigger
[19469174260.208336] (       92.187500) c0 sai          5.1      src/drivers/imx/sai.c:32   SAI: sai_start
[19469174378.541668] (      118.333336) c0 sai          5.1      src/drivers/imx/sai.c:41   SAI: sai_start 1: dir = 0, TCSR - 0x90100000
...

    You can check the timestamp.

  17. giuzan commented on Mar 9, 2021

    @giuzan
    giuzan
    on Mar 9, 2021
    Author

    Hi @iuliana-prodan, thanks!

    About:

    If you want to capture on -D hw:1,1 I believe you should have another card 1 (another sub-device, like the mixer topology).
    ...
    Using sof-imx8-cs42888-demux-loop.tplg I was able to playback on hw1,0 but the capture on hw:1,1 gives errors, which is expected, there is no 1,1 sub-device.

    The hw:1,1 device is present but, being a capture device, is made visible by arecord -l command:

    root@imx8qmmek:~# arecord -l
**** List of CAPTURE Hardware Devices ****
card 0: btscoaudio [bt-sco-audio], device 0: 59040000.sai-bt-sco-pcm-wb bt-sco-pcm-wb-0 []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: sofimxcs42888 [sof-imx-cs42888], device 1: Capture (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0

    About your try, ok you have the same result of mine (with the first topology you playback and never capture, with the second you never playback and capture). Anyway, you didn't experience an ipc timeout error, but a generic ipc error. The difference could be related to the fact that you have applied the patches to the master branch?

    About sof-logger, I confirm that I built it on imx-stable-v1.6.

    Yes, I experienced the same error
    **error: in logger_read(), fread(..., /sys/kernel/debug/sof/trace) failed: Operation not permitted(-1)**
    but if I check again the trace I cannot see any log line.

  18. lgirdwood commented on Mar 9, 2021

    @lgirdwood
    lgirdwood
    on Mar 9, 2021
    Member

    @giuzan @iuliana-prodan looks like the pipeline state is inconsistent i.e. a component has an unexpected state at TRIGGER_START.

    [21606872758.645836] (      120.729164) c0 tdfb         1.1      src/audio/component.c:438  WARN comp_get_data_blob(): blob_handler->data is not set.
[21606873354.114586] (      595.468750) c0 edma                 src/drivers/imx/edma.c:352  EDMA: set config
[21607134806.406250] (   261452.296875) c0 pipe         1.6       src/audio/pipeline.c:878  pipe trigger cmd 1
[21607135012.031250] (      205.625000) c0 tdfb         1.1      src/audio/tdfb/tdfb.c:514  tdfb_trigger(), command = 1
[21607135129.375000] (      117.343750) c0 tdfb         1.1      src/audio/component.c:190  ERROR comp_set_state(): wrong state = 1, COMP_TRIGGER_START
[21607135339.843750] (      210.468750) c0 pipe         1.6       src/audio/pipeline.c:899  ERROR pipeline_trigger(): ret = -22, host->comp.id = 0, cmd = 1
[21607135591.927086] (      252.083328) c0 ipc                       src/ipc/handler.c:443  ERROR ipc: comp 0 trigger 0x40000 failed -22
[21607866347.447918] (   730755.500000) c0 pipe         1.6       src/audio/pipeline.c:878  pipe trigger cmd 0
[21607866502.864586] (      155.416672) c0 tdfb         1.1      src/audio/tdfb/tdfb.c:514  tdfb_trigger(), command = 0
[21607866618.333336] (      115.468750) c0 tdfb         1.1      src/audio/component.c:209  ERROR comp_set_state(): wrong state = 1, COMP_TRIGGER_STOP
[21607866828.906250] (      210.572922) c0 pipe         1.6       src/audio/pipeline.c:899  ERROR pipeline_trigger(): ret = -22, host->comp.id = 0, cmd = 0
[21607867079.739586] (      250.833328) c0 ipc                       src/ipc/handler.c:443  ERROR ipc: comp 0 trigger 0x50000 failed -22

    Stream IPC messages are notifications, this means they can be async to the pipeline copy(), could they be trashing the mailbox data ??

    [19469173324.739586] (    70762.132812) c0 ipc                       src/ipc/handler.c:1400 handler: ipc_cmd: command type 1610612736 or hex = 0x60000000
[19469173453.072918] (      128.333328) c0 ipc                       src/ipc/handler.c:1421 handler: ipc_cmd: command SOF_IPC_GLB_STREAM_MSG = 0x60000000

    Also it may be worth dumping the mailbox contents and taking a look for any obvious problems.

  19. lgirdwood commented on May 10, 2021

    @lgirdwood
    lgirdwood
    on May 10, 2021
    Member

    @dbaluta any update here ? Should we close or move to v1.9 ?

  20. iuliana-prodan commented on May 10, 2021

    @iuliana-prodan
    iuliana-prodan
    on May 10, 2021
    Contributor

    @dbaluta any update here ? Should we close or move to v1.9 ?

    @lgirdwood @dbaluta this won't be available for v1.8, we should move it to v1.9.

  21. lgirdwood
    modified the milestones: v1.8, v1.9 on May 10, 2021

  22. lgirdwood commented on Jun 3, 2021

    @lgirdwood
    lgirdwood
    on Jun 3, 2021
    Member

    @giuzan any update ? can we close ?

  23. lgirdwood
    assigned
    dbaluta
    and
    iuliana-prodan
    on Jun 3, 2021

  24. dbaluta commented on Jun 24, 2021

    @dbaluta
    dbaluta
    on Jun 24, 2021
    Collaborator

    This is for v1.9 or later.

  25. giuzan commented on Jul 2, 2021

    @giuzan
    giuzan
    on Jul 2, 2021
    Author

    @lgirdwood sorry for my late answer, but i was moved for a while to another project, i had not chances to work on it.

  26. kv2019i
    modified the milestones: v1.9, TBD on Feb 15, 2023

  27. kv2019i commented on Feb 15, 2023

    @kv2019i
    kv2019i
    on Feb 15, 2023
    Collaborator

    @dbaluta I assigned this to "TBD" milestone, feel free to assing based on your plans.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

enhancementNew feature or request

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions