Skip to content

[BUG][TGL Chrome] Failed to open Internal Microphone on plugging/unplugging a headset #4593

Closed
Closed
[BUG][TGL Chrome] Failed to open Internal Microphone on plugging/unplugging a headset#4593
Assignees
bkokoszx
Labels
Fix confirmedFix for the issue has been found and verifiedIGO NCObserved in IGO NC integrationTGLApplies to Tiger LakebugSomething isn't working as expectedmulticoreIssues observed when not only core#0 is used.

Description

@lancedkhou
lancedkhou
opened on Aug 3, 2021

Describe the bug
Using online voice record to do recording.
Plug and unplug a headset while recording via internal Mic would fail.

To Reproduce

  1. Start recording by "Online Voice Recorder" on Chrome Browser. During the following steps, make the sound and check the waveform to make sure the recording is still valid.
  2. (No headset is plugged) record by Internal Microphone.
  3. Plug the headset, and record by headset Mic.
  4. Switch the input to Internal Microphone by UI, and record by Internal Microphone.
  5. Un-plug the headset, and record by Internal Microphone
  6. Repeat step3, 4, 5 if the recording is still fine.

Reproduction Rate
1/10

Expected behavior
The recording is always valid

Impact
blocker

Environment
tgl-13 branch with IGO patches & IGO binary
Issue still reproduced with PR #4575

Screenshots or console output
messages: (Withour PR #4575)

2021-08-02T08:54:53.233950Z ERR cras_server[9552]: hw_params: Timer expired: rate: 48000, ret_rate: 48000, channel: 2, format: 2
2021-08-02T08:54:53.234014Z ERR kernel: [ 1788.544852] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x80010000 size 12
2021-08-02T08:54:53.234028Z ERR kernel: [ 1788.544860] sof-audio-pci 0000:00:1f.3: error: failed to set DAI config for SSP1-Codec
2021-08-02T08:54:53.234030Z ERR kernel: [ 1788.544864] sof-audio-pci 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on SSP1 Pin: -62
2021-08-02T08:54:53.234031Z ERR kernel: [ 1788.544868] SSP1-Codec: ASoC: hw_params BE failed -62
2021-08-02T08:54:53.234033Z ERR kernel: [ 1788.544870] smart373-spk: ASoC: hw_params BE failed -62

sof-logger:( Without PR #4575)
[ 3578745940.241330] ( 2503.489502) c0 dmic-dai 2.1 src/drivers/intel/dmic.c:1560 dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
[ 3578745950.449663] ( 10.208333) c0 dmic-dai 2.1 src/drivers/intel/dmic.c:1563 ERROR dmic_irq_handler(): full fifo A or PDM overrun
[ 3578745961.178829] ( 10.729166) c0 dmic-dai 2.1 src/drivers/intel/dmic.c:1450 dmic_stop(), dmic_active_fifos = 1
[ 3578745973.001745] ( 11.822916) c0 ll-schedule ./schedule/ll_schedule.c:539 task cancel 0x9e265908 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e>
[ 3578763481.178133] ( 17508.175781) c0 idc src/idc/idc.c:113 ERROR idc_wait_in_blocking_mode() error: timeout

Activity

  1. lancedkhou
    added
    bugSomething isn't working as expected
    on Aug 3, 2021

  2. lancedkhou commented on Aug 3, 2021

    @lancedkhou
    lancedkhou
    on Aug 3, 2021
    Author

    uploading sof-logger and kernel/system messages.

    sof-logger.txt
    messages.txt

  3. lgirdwood commented on Aug 3, 2021

    @lgirdwood
    lgirdwood
    on Aug 3, 2021
    Member

    @bkokoszx @RDharageswari @sathya-nujella @keyonjie fyi.

  4. lgirdwood commented on Aug 3, 2021

    @lgirdwood
    lgirdwood
    on Aug 3, 2021
    Member

    This could be related to #4584 and #4568 as it seems we have some MCPS overshoot which cascades into a DMIC FIFO overrun. It could be the IDC starting and blocking the DMIC being drained.

    [  3578608315.090549] (           9.322916) c0 ssp-dai      1.1   /drivers/intel/ssp/ssp.c:758  ssp_start()
[  3578608415.507211] (         100.416664) c0 ll-schedule        ./schedule/ll_schedule.c:413  task add 0xbe2d0240 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[  3578608424.361377] (           8.854166) c0 ll-schedule        ./schedule/ll_schedule.c:417  task params pri 0 flags 0 start 0 period 1000
[  3578608441.965543] (          17.604166) c0 ll-schedule        ./schedule/ll_schedule.c:329  new added task->start 2672608419 at 2672597481
[  3578608450.350960] (           8.385416) c0 ll-schedule        ./schedule/ll_schedule.c:332  num_tasks 3 total_num_tasks 4
[  3578617173.683947] (        8723.333008) c1 igo-nr       4.20  ../audio/igo_nr/igo_nr.c:699  igo_nr_copy()
[  3578617184.204779] (          10.520833) c1 igo-nr       4.20  ../audio/igo_nr/igo_nr.c:716  src_frames = 778, sink_frames = 1536.
[  3578743353.731016] (      126169.523438) c0 dai                           src/lib/dai.c:164  dai_get type 1 index 1 new sref 3
[  3578743365.762265] (          12.031249) c0 ssp-dai      1.1   /drivers/intel/ssp/ssp.c:167  ssp_set_config(): playback/capture active. Ignore config
[  3578743374.981015] (           9.218750) c0 dai                           src/lib/dai.c:188  dai_put type 1 index 1 new sref 2
[  3578743387.897681] (          12.916666) c0 dai          1.5            src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275000
[  3578743396.387264] (           8.489583) c0 dai          1.5            src/audio/dai.c:710  dai_config(): Component is in active state. Ignore config
[  3578743436.751846] (          40.364582) c0 dai          11.67          src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275900
[  3578745940.241330] (        2503.489502) c0 dmic-dai     2.1   src/drivers/intel/dmic.c:1560 dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
[  3578745950.449663] (          10.208333) c0 dmic-dai     2.1   src/drivers/intel/dmic.c:1563 ERROR dmic_irq_handler(): full fifo A or PDM overrun
[  3578745961.178829] (          10.729166) c0 dmic-dai     2.1   src/drivers/intel/dmic.c:1450 dmic_stop(), dmic_active_fifos = 1
[  3578745973.001745] (          11.822916) c0 ll-schedule        ./schedule/ll_schedule.c:539  task cancel 0x9e265908 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e>
[  3578763481.178133] (       17508.175781) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3578766300.500937] (        2819.322754) c0 dai                           src/lib/dai.c:164  dai_get type 1 index 1 new sref 3
[  3578766312.375937] (          11.875000) c0 ssp-dai      1.1   /drivers/intel/ssp/ssp.c:167  ssp_set_config(): playback/capture active. Ignore config
[  3578766321.594687] (           9.218750) c0 dai                           src/lib/dai.c:188  dai_put type 1 index 1 new sref 2
[  3578766334.511353] (          12.916666) c0 dai          1.5            src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275000
[  3578766342.948852] (           8.437500) c0 dai          1.5            src/audio/dai.c:710  dai_config(): Component is in active state. Ignore config
[  3578766382.271767] (          39.322914) c0 dai          11.67          src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275900
[  3578786412.270971] (       20030.000000) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3578812667.894928] (       26255.623047) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3578834021.696163] (       21353.800781) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3578855342.424482] (       21320.728516) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3578875935.288248] (       20592.863281) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3580791353.805886] (     1915418.500000) c0 dai                           src/lib/dai.c:164  dai_get type 1 index 1 new sref 3
[  3580791365.837135] (          12.031249) c0 ssp-dai      1.1   /drivers/intel/ssp/ssp.c:167  ssp_set_config(): playback/capture active. Ignore config
[  3580791375.264218] (           9.427083) c0 dai                           src/lib/dai.c:188  dai_put type 1 index 1 new sref 2
[  3580791388.545467] (          13.281249) c0 dai          1.5            src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275000
[  3580791397.191300] (           8.645833) c0 dai          1.5            src/audio/dai.c:710  dai_config(): Component is in active state. Ignore config
[  3580791436.930882] (          39.739582) c0 dai          11.67          src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275900
[  3580811473.857170] (       20036.925781) c0 idc                           src/idc/idc.c:113  ERROR idc_wait_in_blocking_mode() error: timeout
[  3580814061.409150] (        2587.552002) c0 dai                           src/lib/dai.c:164  dai_get type 1 index 1 new sref 3
[  3580814073.284150] (          11.875000) c0 ssp-dai      1.1   /drivers/intel/ssp/ssp.c:167  ssp_set_config(): playback/capture active. Ignore config
[  3580814082.763316] (           9.479166) c0 dai                           src/lib/dai.c:188  dai_put type 1 index 1 new sref 2
[  3580814095.888315] (          13.124999) c0 dai          1.5            src/audio/dai.c:706  dai_config() dai type = 1 index = 1 dd 0x9e275000
[  3580814104.429982] (           8.541666) c0 dai          1.5            src/audio/dai.c:710  dai_config(): Component is in active state. Ignore config
  5. mengdonglin
    added
    multicoreIssues observed when not only core#0 is used.
    TGLApplies to Tiger Lake
    on Aug 3, 2021
  6. mengdonglin
    changed the title [-][BUG][TGL] Failed to open Internal Microphone on plugging/unplugging a headset[/-] [+][BUG][TGL Chrome] Failed to open Internal Microphone on plugging/unplugging a headset[/+] on Aug 3, 2021

  7. johnylin76 commented on Aug 4, 2021

    @johnylin76
    johnylin76
    on Aug 4, 2021
    Contributor

    Hi Lance, thanks for the bug creation. In fact we have some updates in the following comments in the original bug.
    After adopting PR #4575 fix, the situation you mentioned above seems quite hard to be reproduced then.

    But we also have observed another issue with PR #4575 fix, the scenario is using "Google Meet". It would be observed that it failed to start capturing with PCM99 and Google Meet lost the audio input.

    To Reproduce

    1. Disable Google assistant in Settings.
    2. Join Google meet (output: internal speaker, input: internal mic)
    3. Plug in 3.5mm jack headset (output: headset speaker, input: headset mic)
    4. Switch input to internal mic by UI (output: headset speaker, input: internal mic)
    5. Unplug 3.5mm jack headset (output: headset speaker, input: headset mic)
    6. Repeat step 3~5 few times to check whether input capture is still alive.

    Reproduction Rate
    1/10

    Expected behavior
    The capture (Google Meet input) is always valid.

    Here are some logs:
    sof-logger.txt
    messages.txt

    From messages log there are DSP panic issue which is much alike PR #4584

  8. lgirdwood commented on Aug 4, 2021

    @lgirdwood
    lgirdwood
    on Aug 4, 2021
    Member

    Thanks @johnylin76 fwiw the log is very similar to above.

    1. SSP start
    2. New pipeline task
    3. igo copy()
    4. DMIC underun IRQ.
    5. IDC blocking timeouts.

    @lancedkhou are you able to apply this FW debug patch and reproduce. @sathya-nujella @bkokoszx I'm suspicious in this instance we send the IDC and block for too long.

    diff --git a/src/idc/idc.c b/src/idc/idc.c
index 3ec1274f4..7c34972e8 100644
--- a/src/idc/idc.c
+++ b/src/idc/idc.c
@@ -274,6 +274,8 @@ void idc_cmd(struct idc_msg *msg)
        uint32_t type = iTS(msg->header);
        int ret = 0;
 
+       tr_info(&idc_tr, "idc_cmd start type %d to core %d", type, msg->core);
+
        switch (type) {
        case iTS(IDC_MSG_POWER_DOWN):
                cpu_power_down_core();
@@ -302,6 +304,8 @@ void idc_cmd(struct idc_msg *msg)
        }
 
        idc_msg_status_set(ret, cpu_get_id());
+       tr_info(&idc_tr, "idc_cmd done type %d from core %d ret %d",
+                       type, msg->core, ret);
 }
 
 /* Runs on each CPU */

  9. johnylin76 commented on Aug 5, 2021

    @johnylin76
    johnylin76
    on Aug 5, 2021
    Contributor

    Hi @lgirdwood , I repro-ed with your patch. Logs are as attached.

    sof-logger.txt
    messages.txt

  10. bkokoszx
    self-assigned this
    on Aug 5, 2021

  11. lgirdwood commented on Aug 6, 2021

    @lgirdwood
    lgirdwood
    on Aug 6, 2021
    Member

    @lancedkhou can you try #4608
    This probably wont fix the issue, but it will give more insights for the team.

  12. johnylin76 commented on Aug 9, 2021

    @johnylin76
    johnylin76
    on Aug 9, 2021
    Contributor

    Hi @lgirdwood , I tried with #4608. Logs are as attached.

    sof-logger.txt
    messages.txt

    btw I have removed the code for printing igo copy() message because I found out somehow the error log will disappear if I print igo copy() this time.

  13. lgirdwood commented on Aug 9, 2021

    @lgirdwood
    lgirdwood
    on Aug 9, 2021
    Member

    @johnylin76 thanks for the logs. @bkokoszx the logs are giving an idea that the following flow may be happening

    1. IGO is running on core 1
    2. blocking IDC is sent c0 -> c1 (PM IDC ??? 0x4000000)
    3. IDC on C1 is not processed as IGO still running
    4. IDC blocking on C0 prevents pipeline running on C0 and DMIC overruns.....

    @lancedkhou @johnylin76 can someone try 98e8016 as this allows IDC not run in the background and not block.

  14. keyonjie commented on Aug 10, 2021

    @keyonjie
    keyonjie
    on Aug 10, 2021
    Contributor

    Hi Lance, thanks for the bug creation. In fact we have some updates in the following comments in the original bug.
    After adopting PR #4575 fix, the situation you mentioned above seems quite hard to be reproduced then.

    But we also have observed another issue with PR #4575 fix, the scenario is using "Google Meet". It would be observed that it failed to start capturing with PCM99 and Google Meet lost the audio input.

    To Reproduce

    1. Disable Google assistant in Settings.
    2. Join Google meet (output: internal speaker, input: internal mic)
    3. Plug in 3.5mm jack headset (output: headset speaker, input: headset mic)
    4. Switch input to internal mic by UI (output: headset speaker, input: internal mic)
    5. Unplug 3.5mm jack headset (output: headset speaker, input: headset mic)
    6. Repeat step 3~5 few times to check whether input capture is still alive.

    Reproduction Rate
    1/10

    Expected behavior
    The capture (Google Meet input) is always valid.

    Here are some logs:
    sof-logger.txt
    messages.txt

    From messages log there are DSP panic issue which is much alike PR #4584

    Hi @lrgirdwo @johnylin76 FYI that @fuyuntsuo is debugging this form the IGO library side.

  15. fuyuntsuo commented on Aug 13, 2021

    @fuyuntsuo
    fuyuntsuo
    on Aug 13, 2021
    Contributor

    @keyonjie is this the same issue as #4418 ?

  16. lgirdwood commented on Aug 17, 2021

    @lgirdwood
    lgirdwood
    on Aug 17, 2021
    Member

    @keyonjie is this the same issue as #4418 ?

    Yes, I think we have several issues potentially related to blocking IDC. @kv2019i fyi.
    @lancedkhou did you get a chance to try 98e8016
    @keyonjie I'm wondering if we should have IGO run in core 1 EDF context so it's preemptable by the short term IDC ?

  17. keyonjie commented on Aug 18, 2021

    @keyonjie
    keyonjie
    on Aug 18, 2021
    Contributor

    @johnylin76 @lancedkhou could you please let us know if #4515 + #4612 + #4640 can already fix this issue?

    @lgirdwood hopefully we don't need more extra commits.

  18. lancedkhou commented on Aug 18, 2021

    @lancedkhou
    lancedkhou
    on Aug 18, 2021
    Author

    Hi Keyon,

    With #4515 + #4612 + #4640 the issue can be fixed.
    However, somehow there was still DSP panic found.

    4575+4612+4640-DSP-panic-messages.txt

  19. keyonjie commented on Aug 18, 2021

    @keyonjie
    keyonjie
    on Aug 18, 2021
    Contributor

    Hi Keyon,

    With #4515 + #4612 + #4640 the issue can be fixed.
    However, somehow there was still DSP panic found.

    4575+4612+4640-DSP-panic-messages.txt

    @lancedkhou thanks, can you file it as another issue and share the reproduce steps there?

  20. lancedkhou commented on Aug 18, 2021

    @lancedkhou
    lancedkhou
    on Aug 18, 2021
    Author

    Hi Keyon,

    Please be informed that a new issue #4648 was created to trace DSP panic.

  21. mengdonglin
    added
    IGO NCObserved in IGO NC integration
    Fix confirmedFix for the issue has been found and verified
    on Aug 19, 2021

  22. lgirdwood commented on Aug 27, 2021

    @lgirdwood
    lgirdwood
    on Aug 27, 2021
    Member

    @lancedkhou can we close ?

  23. lancedkhou commented on Aug 30, 2021

    @lancedkhou
    lancedkhou
    on Aug 30, 2021
    Author

    @lgirdwood Yes. Please.

  24. sathya-nujella commented on Aug 30, 2021

    @sathya-nujella
    sathya-nujella
    on Aug 30, 2021
    Contributor

    Hi,

    Below PR's are used to test and confirm that this issue is not reproduced.
    can you please help merge these, if reviews are done?

    #4575
    #4612
    #4640

  25. lgirdwood commented on Aug 30, 2021

    @lgirdwood
    lgirdwood
    on Aug 30, 2021
    Member

    @mwasko @abonislawski fyi - this can be closed once backport PRs are merged.

  26. mengdonglin
    closed this as completedon Jan 3, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Fix confirmedFix for the issue has been found and verifiedIGO NCObserved in IGO NC integrationTGLApplies to Tiger LakebugSomething isn't working as expectedmulticoreIssues observed when not only core#0 is used.

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions