[BUG][TGL][Chrome] DSP Panic on opening Internal Mic after plugging/unplugging a headset #4648

Activity

1. lancedkhou

   added

   bugSomething isn't working as expectedSomething isn't working as expected

   on Aug 18, 2021
2. sathya-nujella

   added

   TGLApplies to Tiger LakeApplies to Tiger Lake

   on Aug 18, 2021
3. mengdonglin

   added

   DSP panicDSP panic observedDSP panic observed

   IGO NCObserved in IGO NC integrationObserved in IGO NC integration

   Fix confirmedFix for the issue has been found and verifiedFix for the issue has been found and verified

   on Aug 19, 2021
4. bkokoszx

   self-assigned this

   on Aug 19, 2021
5. abonislawski commented on Aug 19, 2021

   

   abonislawski

   on Aug 19, 2021

   Member

   More actions

   @lancedkhou could please include also linux crash/coredump file? (with fw elf)
   @lgirdwood can we make this a standard for dsp panic cases? It would be much easier to run coredump-reader and immediately see backtrace for dsp panic rather than things like "EPC1 0xbe02e437" in logs
6. lancedkhou commented on Aug 20, 2021

   

   lancedkhou

   on Aug 20, 2021

   Author

   More actions

   linux-messages.txt
   sof-dump-dsp-panic.txt
7. sathya-nujella commented on Aug 20, 2021

   

   sathya-nujella

   on Aug 20, 2021

   Last edited by sathya-nujella

   Contributor

   More actions

   Hi,
   Here is the script to reproduce the issue via command line:

   1. Connect headset to DUT

   2. run the below script and monitor "dmesg -w | grep sof " .. we can see "DSP panic" prints

   ==
   #!/bin/bash
   stop ui

   for i in {1..50}
   do
   cras_test_client --playback_f /dev/zero --select_output 6:0 --duration_seconds 10 &
   cras_test_client --capture_f /tmp/a.wav --select_input 9:0 --duration_seconds 10
   sleep 5

   cras_test_client --playback_f /dev/zero --select_output 7:0 --duration_seconds 30 &
   cras_test_client --capture_f /tmp/a.wav --select_input 10:0 --duration_seconds 10
   cras_test_client --capture_f /tmp/a.wav --select_input 9:0 --duration_seconds 15
   sleep 10

   done

   ===
   PS / Note:
   Node ID's in above script are from here:

   localhost ~ # cras_test_client
   ..
   Output Devices:
   Output Nodes:
   Stable Id ID Vol UI Plugged L/R swapped Time Hotword Type MaxCha Name
   (62f96cde) 7:0 72 0.000000 yes no 1629499743 HEADPHONE 2 Headphone
   (72a57953) 6:0 100 0.000000 yes no 1629499742 INTERNAL_SPEAKER 2*Speaker

   Input Devices:
   Input Nodes:
   Stable Id ID Gain UI Plugged L/R swapped Time Hotword Type MaxCha Name
   (61aab6ba) 10:0 20 1.000000 yes no 1629499743 MIC X Mic
   (0039c920) 9:0 26 1.000000 yes no 1629499742 INTERNAL_MIC X*Internal Mic
8. keyonjie commented on Aug 23, 2021

   

   keyonjie

   on Aug 23, 2021

   Contributor

   More actions

   @lancedkhou could please include also linux crash/coredump file? (with fw elf)
   @lgirdwood can we make this a standard for dsp panic cases? It would be much easier to run coredump-reader and immediately see backtrace for dsp panic rather than things like "EPC1 0xbe02e437" in logs

   @abonislawski can you share how to use the coredump tool? e.g. in the documentation https://thesofproject.github.io/latest/developer_guides/debugability/coredump-reader/index.html?highlight=coredump,

   -i INFILE
   path to sys dump bin
   

   what is the "sys dump bin" here?
9. abonislawski commented on Aug 23, 2021

   

   abonislawski

   on Aug 23, 2021

   Member

   More actions

   @keyonjie simply by ./sof-coredump-to-gdb.sh elf dump_file

   what is the "sys dump bin" here?

   Linux core dump file with stack, regs dump (see panic.c)
10. sathya-nujella commented on Aug 23, 2021

    

    sathya-nujella

    on Aug 23, 2021

    Contributor

    More actions

    I reproduced "DSP panic", but exception file size is zero.

    localhost /sys/kernel/debug/sof # ls -ls
    total 0
    0 -r--r--r--. 1 root root 0 Aug 23 22:38 exception

    Let me cross check the CONFIG as per this comment: #3965 (comment)
11. sathya-nujella commented on Aug 23, 2021

    

    sathya-nujella

    on Aug 23, 2021

    Contributor

    More actions

    Hi @bkokoszx - FYI.

    Thanks to @yongzhi1 for pointing out this CONFIG change.
    I am now able to get sof/exception after enabling the below kernel config:
    CONFIG_SND_SOC_SOF_DEBUG=y
    CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE=y
    CONFIG_SND_SOC_SOF_DEVELOPER_SUPPORT=y
    CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE=y

    "DSP panic" is reproduced and attached exception file.
    cat /sys/kernel/debug/sof/exception > ~/oops.bin
    oops.zip
12. paulstelian97 commented on Aug 24, 2021

    

    paulstelian97

    on Aug 24, 2021

    Collaborator

    More actions

    I reproduced "DSP panic", but exception file size is zero.

    localhost /sys/kernel/debug/sof # ls -ls
    total 0
    0 -r--r--r--. 1 root root 0 Aug 23 22:38 exception

    Do not trust stat here, it will report 0 for files that aren't actually 0-sized.

    👍React with 👍1Reacted by Sathyanarayana Nujella
13. lgirdwood commented on Aug 25, 2021

    

    lgirdwood

    on Aug 25, 2021

    Member

    More actions

    @lancedkhou could please include also linux crash/coredump file? (with fw elf)
    @lgirdwood can we make this a standard for dsp panic cases? It would be much easier to run coredump-reader and immediately see backtrace for dsp panic rather than things like "EPC1 0xbe02e437" in logs

    @abonislawski can you share how to use the coredump tool? e.g. in the documentation https://thesofproject.github.io/latest/developer_guides/debugability/coredump-reader/index.html?highlight=coredump,

    -i INFILE
    path to sys dump bin
    

    what is the "sys dump bin" here?

    I think the goal should be to update the core dump script to parse for the dmesg for the FW oops.
14. abonislawski commented on Aug 30, 2021

    

    abonislawski

    on Aug 30, 2021

    Last edited by abonislawski

    Member

    More actions

    Detailed description what happened in this case:

    

    1. Two interesting buffers from (added) FW logs, both with the same buffer->addr 0xbe17ae80 and different buffer->size (0x180 and 0x6000)
       They are not allocated at the same time so all is ok.

    2. Regs dump from host_get_copy_bytes_normal() during normal operation:
       a) local_buffer addr 0xbe162e40
       b) local_buffer size 0x6000
       c) dma_buffer addr 0xbe17ae80
       d) dma_buffer size 0x6000
       e) calculated copy_bytes 0x3000
       f) latest allocated size for buffer 0xbe17ae80 0x6000

    So we have two buffers with size 0x6000, copy_bytes 0x3000, all is ok.

    3. Regs dump from host_get_copy_bytes_normal() during normal operation:
       a) local_buffer addr 0xbe156740
       b) local_buffer size 0x0300
       c) dma_buffer addr 0xbe17ae80
       d) dma_buffer size 0x0180
       e) calculated copy_bytes 0x00cc
       f) latest allocated size for buffer 0xbe17ae80 0x0180

    Similar data with second case when buffer 0xbe17ae80 size is 0x180, everything works as expected.

    4. Panic case.
       a) local_buffer addr 0xbe162e40
       b) local_buffer size 0x6000
       c) dma_buffer addr 0xbe17ae80
       d) dma_buffer size 0x0180 !!!
       e) calculated copy_bytes 0x3000 !!!
       f) latest allocated size for buffer 0xbe17ae80 0x6000 !!!

    From the buffer pairs a) and c) we can easily see that this should be case from point 2. when we have two buffers with size 0x6000 and calculated copy_bytes 0x3000 but something is wrong and in buffer description data size is 0x180, just like in the previous allocation.
    Also in f) we can see that the latest allocation size for buffer 0xbe17ae80 was 0x6000 so we have cache/multicore issue here.

    So the bad things starts here and FW will end with dsp panic in several steps, it could be easily stopped if the copy_bytes was limited to smaller buffer (even if fw only thinks he is smaller).
    Next steps: dma_buffer_copy_to() -> audio_stream_produce(), here we will update buffer->w_ptr in audio_stream_wrap(buffer, (char *)buffer->w_ptr + bytes) with simple check:

    if (ptr >= buffer->end_addr)
    		ptr = (char *)buffer->addr +
    			((char *)ptr - (char *)buffer->end_addr);
    

    this code is not prepared for case where copy_bytes is bigger than buffer size so in result it will set buffer->w_ptr > end_addr, this is a second place where we could still avoid panic with simple check if the new ptr > end_addr.

    In the next iteration fw will crash in dma_buffer_copy_to() -> audio_stream_writeback() because of faulty buffer->w_ptr (head_size 0xffffd200).

    From our tests allocating buffer description struct (with w_ptr, size etc.) in SOF_MEM_ZONE_RUNTIME_SHARED should be enough but please make more tests @sathya-nujella (PR #4696 )
    It could be also avoided with some writeback/invalidate calls but probably the best way is to just alloc it as SHARED

    👍React with 👍1Reacted by Keyon Jie
15. lgirdwood commented on Aug 31, 2021

    

    lgirdwood

    on Aug 31, 2021

    Member

    More actions

    @abonislawski good update and info here. Any validation news on whether #4696 will fix this issue ?
16. mwasko

    closed this as completedin #4696on Sep 2, 2021