Skip to content

[ADL/RPL] [Bug] BT HFP offload capture stops working from second time #7548

Closed
Closed
[ADL/RPL] [Bug] BT HFP offload capture stops working from second time#7548
Assignees
kv2019i
Labels
ADLApplies to Alder Lake platformP1Blocker bugs or important featuresbugSomething isn't working as expected

Description

@Vamshigopal
Vamshigopal
opened on Apr 26, 2023

[ transferred - previously filed to SOF Linux driver as https://github.com/thesofproject/linux/issues/4330 ]

Description
with BToffload enabled , when we connect HFP-only supported bt headset, mic stops working from second try, from sof trace logs we see
[ 85209608.124491] ( 1869.218628) c0 dw-dma src/drivers/dw/dma.c:1062 INFO dw_dma_avail_data_size() size is 0!
[ 85209633.593240] ( 25.468748) c0 dw-dma src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
dmesg.log

sof-logger.log

btsnoop.log

steps to reproduce

  1. Connect to an HFP-only bt headset
  2. Start a youtube clip via BT output
  3. Start mic recording via BT input
  4. Stop mic recording via BT input
  5. Start mic recording via BT input

Expected
Mic should start at step 5

Result
Mic fails to start

repro rate
10/10

SW Configuration
kernel: https://chromium.googlesource.com/chromiumos/third_party/kernel/+/refs/heads/chromeos-5.15
sof FW: https://github.com/thesofproject/sof/tree/cavs2.5-001-drop-stable
sof topology: sof-adl-max98360a-rt5682.tplg

Activity

  1. Vamshigopal
    assigned
    kv2019i
    on Apr 26, 2023

  2. Vamshigopal commented on Apr 26, 2023

    @Vamshigopal
    Vamshigopal
    on Apr 26, 2023
    ContributorAuthor

    cc: @sathyap-chrome @sathya-nujella @ranj063 @plbossart @ujfalusi @juimonen

  3. kv2019i
    added
    bugSomething isn't working as expected
    P1Blocker bugs or important features
    ADLApplies to Alder Lake platform
    on Apr 27, 2023

  4. kv2019i commented on Apr 27, 2023

    @kv2019i
    kv2019i
    on Apr 27, 2023
    Collaborator

    @Vamshigopal I replicated the exact sequence without real BT connection and FW seems to behave as expected. The cavs2.5-001 branch has some recent updates for early BCLK/MCLK, but these don't seem to cause trouble in this sequence. When the playback is running constantly on the background, the FW will ignore most of the setup and teardown in steps 2+3+4 as the SSP2 hardware is already programmed and running. Both in my local tests and the provided logs, these seem to be good.

    So it does seem there is no data transferred from BT to ADSP in step 5 and the ADSP times out.

    One experiment is to enable loopback mode in topology for SSP2 (set LBM bit and set ADSP as clock master) and run through the test sequence. I'd expect data flow to continue in step 5. This is good test to make in any case to ensure the ADSP side is working correctly.

  5. sathyap-chrome commented on Apr 27, 2023

    @sathyap-chrome
    sathyap-chrome
    on Apr 27, 2023
    Contributor

    @kv2019i this issue only happens when you try HFP only headset. If headset supports A2DP, this issue doesnt happen

    best way to confirm is at this step:
    Start a youtube clip via BT output - > check btmon logs for a SCO connection

    Also can you confirm which OS version you used from CHROME - currently offload is disabled and we need to enable from OS manually

  6. kv2019i commented on Apr 27, 2023

    @kv2019i
    kv2019i
    on Apr 27, 2023
    Collaborator

    @sathyap-chrome I think the link to A2DP support is because A2DP is not offloaded on these devices. So what happens is that with A2DP enabled headset, step 1 (youtube clip) is not offloaded and ADSP is not active in the use-case. Not sure what happens in step 2 on these systems, it either keeps offload disabled, or switches playback to HFP, but the flow is anyways different.

    With HFP only headset, step 1 already starts ADSP use, so step 2-5 requre a different flow, starting and stopping capture over an already running SSP/I2S interface.

    I did not test with actual BT/Chrome device, just replicated the steps on a development system. I wanted to check we don't have a regression in start/stopping capture when playback is already active. This does not seem to be the case.

  7. Vamshigopal commented on Apr 27, 2023

    @Vamshigopal
    Vamshigopal
    on Apr 27, 2023
    ContributorAuthor

    Copying this message from partner bug , as it explains the flow.

    Actionoin timeline: -> start-P ----> start-C --------> stop-C ---------> start-C
Active stream(s)       1P            1P1C              1P                1P1C

A2DP+HFP device:       use A2DP      switch to HFP     PCMC stop         switch to HFP
                                     PCMP start        PCMP stop         PCMP start
                                     PCMC start        switch to A2DP    PCMC start

HFP-only device:       PCMP start    PCMC start        PCMC stop         PCMC start(error)

    with A2DP+HFP device , as soon as the capture starts , cras will switch to HFP profile and ADSP will become active.
    whereas in HFP only device, ADSP is active during intial playback itself.

  8. Vamshigopal commented on Apr 28, 2023

    @Vamshigopal
    Vamshigopal
    on Apr 28, 2023
    ContributorAuthor

    @kv2019i with LBM bit set and ADSP as master, we would able reproduce the issue.

    We see the same error signature in SSP loopback mode also

    [    74093953.618271] (        1874.010376) c0 dw-dma                 src/drivers/dw/dma.c:1062 INFO dw_dma_avail_data_size() size is 0!
    [    74093978.722436] (          25.104166) c0 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected

    The rec1 is the first capture, rec2 and rec3 are 2nd and 3rd captures.

    dmesg.log
    sof-logger.log
    rec.zip

  9. kv2019i commented on May 2, 2023

    @kv2019i
    kv2019i
    on May 2, 2023
    Collaborator

    Ack @Vamshigopal -- so this seems like an issue with SSP stop/stat flow. Trying to reproduce this on a local setup now.

  10. kv2019i commented on May 2, 2023

    @kv2019i
    kv2019i
    on May 2, 2023
    Collaborator

    And managed to hit this now locally, debug ongoing.

  11. kv2019i commented on May 2, 2023

    @kv2019i
    kv2019i
    on May 2, 2023
    Collaborator

    This seems to only affect the capture/record device, and specific to mode where codec is clocking provider (like the A2DP SCO case). If the use-case is reversed so that recording is kept running, playback stream can be stopped and restarted multiple times, no problem seen. The hardware programming flow seems correct, but alas record restart fails...

  12. kv2019i commented on May 2, 2023

    @kv2019i
    kv2019i
    on May 2, 2023
    Collaborator

    Did also a short bisect and seems this problem appears also with older SOF releases, so this is a problem that has existed for a while.

  13. kv2019i commented on May 2, 2023

    @kv2019i
    kv2019i
    on May 2, 2023
    Collaborator

    This seems to be a clear FW issue, so moving to the correct tracker. Not a kernel driver issue.

    The SSP fifo can be seen getting data, so we can conclude BT is sending data and we do receive, but for some reason DMA is stuck in this specific sequence.

  14. 22 remaining items

  15. mwasko
    added a commit that references this issue on May 15, 2023

    intel: ssp: drain RX fifo when starting

    2c3f370
  16. kv2019i
    added a commit that references this issue on May 15, 2023

    intel: ssp: drain RX fifo when starting

    c5a8b6a
  17. Vamshigopal
    reopened this on May 30, 2023

  18. Vamshigopal commented on May 30, 2023

    @Vamshigopal
    Vamshigopal
    on May 30, 2023
    ContributorAuthor

    Hi @kv2019i

    Re-opened as we observe issue reproduced again with same error signature ,
    dmesg.log
    trace.log

    
[    65181836.472407] (          20.104166) c0 ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1007 INFO ssp_start()
[    65182083.295313] (         246.822906) c0 sa                          src/lib/agent.c:96   WARN validate(), ll drift detected, delta = 85992
[    65182172.409893] (          89.114578) c0 dw-dma                 src/drivers/dw/dma.c:1062 INFO dw_dma_avail_data_size() size is 0!
[    65182197.149476] (          24.739582) c0 dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
[    65182219.180725] (          22.031250) c0 dai          14.72          src/audio/dai.c:884  ERROR dai_report_xrun(): overrun due to no space available
[    65182241.680724] (          22.500000) c0 dai          14.72          src/audio/dai.c:806  ERROR comp_overrun(): sink->free = 64, copy_bytes = 0
[    65182259.649473] (          17.968750) c0 pipe         14.73 ....../pipeline-stream.c:270  INFO pipe trigger cmd 6
[    65182293.607805] (          33.958332) c0 pipe         14.73 ....../pipeline-stream.c:143  ERROR pipeline_copy(): ret = -61, start->comp.id = 72, dir = 0
[    65182315.795304] (          22.187500) c0 pipe         14.73 ..../pipeline-schedule.c:208  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.

    steps to reproduce

    1. Connect to an HFP-only bt headset
    2. Start a youtube clip via BT output
    3. Start mic recording via BT input
    4. Stop mic recording via BT input
    5. repeat 3,4 steps for couple of times
    6. reboot the device
    7. start youtube pb via BT output
    8. repeat 3,4
    9. you will hit issue In second repeat.

  19. kv2019i commented on May 30, 2023

    @kv2019i
    kv2019i
    on May 30, 2023
    Collaborator

    @Vamshigopal we managed to repro this now. running a stress test with aplay running and arecord repeatedl start/stopped seems to catch this sooner or later. There seems to be some timing issue and/or race with how we flush the RX queue upon start.

  20. Vamshigopal commented on May 30, 2023

    @Vamshigopal
    Vamshigopal
    on May 30, 2023
    ContributorAuthor

    @kv2019i is it with nocodec tplg ?

  21. kv2019i
    added a commit that references this issue on May 30, 2023

    intel: ssp: fix RX fifo drain logic

    e1d648e

  22. kv2019i commented on May 30, 2023

    @kv2019i
    kv2019i
    on May 30, 2023
    Collaborator

    @Vamshigopal Ack, also with nocodec. It seems the drain at start is too slow and the RX fifo manages to get filled up by the time DMA starts up, leading to the XRUN. A tentative fix in #7711 -- this is directly on stable-v2.2 branch for easier testing.

  23. kv2019i commented on May 31, 2023

    @kv2019i
    kv2019i
    on May 31, 2023
    Collaborator

    Updated patch -> #7717

  24. ujfalusi commented on Jun 7, 2023

    @ujfalusi
    ujfalusi
    on Jun 7, 2023
    Contributor

    I think there is another angle to this issue which is brought to light by the TX FIFO drain simplifications.
    The setup is
    SSP1 - clock provider, playback only to speaker, want MCLK as 19200000
    SSP2 - clock receiver, playback/capture to BT, want MCLK as 38400000

    We see this sequence in case of a failure:
    SSP2 start (sets MCLK to 38400000)

    ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 7
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:900  INFO ssp_pre_start()
mn                 ./drivers/intel/ssp/mn.c:259  INFO mclk_rate 38400000, mclk_source_clock 1
mn                 ./drivers/intel/ssp/mn.c:220  INFO mclk_id 0 mdivr_val 1
mn                 ./drivers/intel/ssp/mn.c:330  INFO find_mn for freq 38400000 bclk 128000
mn                 ./drivers/intel/ssp/mn.c:628  INFO bclk_rate 128000, *out_scr_div 300, m 1, n 1
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:234  INFO ssp_bclk_prepare_enable(): sscr0 = 0xc0c12b7f
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:993  INFO ssp_early_start(): SSE set for SSP2
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 1
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1008 INFO ssp_start()

    SSP2 start (clocks have been configured for SSP2 already)

    ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 7
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:900  INFO ssp_pre_start()
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:993  INFO ssp_early_start(): SSE set for SSP2
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 1
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1008 INFO ssp_start()

    SSP2 RX stop
    SSP2 start

    ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 7
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:900  INFO ssp_pre_start()
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:993  INFO ssp_early_start(): SSE set for SSP2
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 1
ssp-dai      1.2   /drivers/intel/ssp/ssp.c:1008 INFO ssp_start()

    SSP2 TX stop

    At this point we have SSP2 RX still running, MCLK is configured for 38400000

    SSP1 start (fails to set the MCLK to 19200000)

    ssp-dai      1.1   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 7
ssp-dai      1.1   /drivers/intel/ssp/ssp.c:900  INFO ssp_pre_start()
mn                 ./drivers/intel/ssp/mn.c:180  INFO MCLK 19200000, source = 1
mn                 ./drivers/intel/ssp/mn.c:192  ERROR Can't set MCLK 0 to 19200000, it is already configured to 38400000
ssp-dai      1.1   /drivers/intel/ssp/ssp.c:161  ERROR ssp_mclk_prepare_enable(): invalid mclk_rate = 19200000 for mclk_id = 0
ssp-dai      1.1   /drivers/intel/ssp/ssp.c:993  INFO ssp_early_start(): SSE set for SSP1
demux        1.2        src/audio/mux/mux.c:693  INFO mux_trigger(), command = 1
ssp-dai      1.1   /drivers/intel/ssp/ssp.c:1111 INFO ssp_trigger() cmd 1
ssp-dai      1.1   /drivers/intel/ssp/ssp.c:1008 INFO ssp_start()

    Note that the MCLK request fails since the same clock is already used by SSP2 and it is set to 38400000, the MCLK request fail is handled by skipping the BCLK setup for SSP1 but the error from ssp_pre_start() is ignored, so we go on and start the SSP1 anyways.
    This will lead to:

    dw-dma                 src/drivers/dw/dma.c:1093 INFO dw_dma_free_data_size() size is 0!
dw-dma                 src/drivers/dw/dma.c:1128 ERROR dw_dma_get_data_size(): xrun detected
dai          1.6            src/audio/dai.c:881  ERROR dai_report_xrun(): underrun due to no data available
dai          1.6            src/audio/dai.c:775  ERROR comp_underrun(): dev->comp.id = 6, source->avail = 192, copy_bytes = 0
pipe         1.7   ....../pipeline-stream.c:270  INFO pipe trigger cmd 6
pipe         1.7   ....../pipeline-stream.c:143  ERROR pipeline_copy(): ret = -61, start->comp.id = 6, dir = 1
pipe         1.7   ..../pipeline-schedule.c:187  ERROR pipeline_task(): xrun recovery failed! pipeline is stopped.

    Which is not a surprise without BCLK setup for a clock provider.

    I think this setup is not correct. SSP1 and SSP2 can be used at the same time and they want the very same MCLK to run in different speeds. A clock cannot be 38400000 and 19200000 at the same time.
    Either both SSPs should be asking for the same MCLK rate
    or
    the two SSP should use different mclk_id from topology (if it is possible at all).

  25. kv2019i commented on Jun 14, 2023

    @kv2019i
    kv2019i
    on Jun 14, 2023
    Collaborator

    Closing this issue, let's follow-up on MCLK configuration question in separate bug #7803 as that seems to be a separate issue (albeit uncovered by same testing steps).

  26. kv2019i
    closed this as completedon Jun 14, 2023
  27. johnylin76
    added a commit that references this issue on Feb 17, 2025

    intel: ssp: drain RX fifo when starting

    8eabff7
  28. abonislawski
    added a commit that references this issue on Feb 17, 2025

    intel: ssp: drain RX fifo when starting

    01fbc23
  29. macchian
    added a commit that references this issue on Feb 18, 2025

    intel: ssp: drain RX fifo when starting

    f40b462
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 featuresbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions