Skip to content

[BUG] [TGL] WOV capture fails for the second time on TGL Chrome DUT #2511

Closed

Description

@RDharageswari

Describe the bug
WOV capture fails for the second time.

To Reproduce
1)Start the WOV capture:
arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv
2)Start tapping on the DMIC and the WOV capture starts.
3)Press Ctrl+C
4)Second time start the WOV capture.
localhost ~ #
tmp.wav -vvv arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000
Recording WAVE 'tmp.wav' : Signed 16 bit Little Endian, Rate 16000 Hz, Stereo
arecord: set_params:1403: Unable to install hw params:
ACCESS: MMAP_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 16000
PERIOD_TIME: 999000
PERIOD_SIZE: 15984
PERIOD_BYTES: 63936
PERIODS: (4 5)
BUFFER_TIME: 3999000
BUFFER_SIZE: 63984
BUFFER_BYTES: 255936
TICK_TIME: 0

This capture shows failure. From the failure logs, it looks like the first capture stream did not freed
completely.(The allocated stream1 is not freed) and hence the second time capture does not start.

Reproduction Rate
Always

Keyword:
after Ctrl+C of first WOV capture
[ 376.026507] sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
[ 376.026531] sof-audio-pci 0000:00:1f.3: error: transition from 0 to 4 not allowed
[ 376.026532] sof-audio-pci 0000:00:1f.3: error: failed to power down DSP during suspend -22
[ 376.026543] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -22)
PFA the kernel & firmware logs.

first_wov_failure_fw_logs.txt
first_wov_failure_kernellogs.txt
second_capture_failure_kernel_logs.txt

Activity

  1. changed the title [-][BUG] [TGL] WOV capture fails for the second time,[/-] [+][BUG] [TGL] WOV capture fails for the second time on TGL Chrome DUT[/+] on Mar 9, 2020
  2. RDharageswari commented on Mar 9, 2020

    @RDharageswari
    Author
  3. RDharageswari commented on Mar 10, 2020

    @RDharageswari
    Author

    WOV_Working.zip
    Adding the topology patches

  4. lbetlej commented on Mar 12, 2020

    @lbetlej
    Collaborator

    @RDharageswari Is the issue reproduced with arecord option
    -d, --duration=# Interrupt after # seconds ?

  5. RDharageswari commented on Mar 12, 2020

    @RDharageswari
    Author

    Yes i could reproduce the issue with 10 seconds also:
    arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10

    dmesg logs: first time:
    [ 2866.862857] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
    [ 2866.862902] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
    [ 2866.862910] sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
    [ 2866.862953] sof-audio-pci 0000:00:1f.3: error: transition from 0 to 4 not allowed
    [ 2866.862954] sof-audio-pci 0000:00:1f.3: error: failed to power down DSP during suspend -22
    [ 2866.862963] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -22)
    localhost ~ # arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10
    second time capture fails:
    localhost ~ # arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10
    Recording WAVE 'tmp.wav' : Signed 16 bit Little Endian, Rate 16000 Hz, Stereo
    arecord: set_params:1403: Unable to install hw params:
    ACCESS: MMAP_INTERLEAVED
    FORMAT: S16_LE
    SUBFORMAT: STD
    SAMPLE_BITS: 16
    FRAME_BITS: 32
    CHANNELS: 2
    RATE: 16000
    PERIOD_TIME: 999000
    PERIOD_SIZE: 15984
    PERIOD_BYTES: 63936
    PERIODS: (4 5)
    BUFFER_TIME: 3999000
    BUFFER_SIZE: 63984
    BUFFER_BYTES: 255936
    TICK_TIME: 0

    [ 2880.905186] sof-audio-pci 0000:00:1f.3: pcm: open stream 7 dir 1
    [ 2880.905189] sof-audio-pci 0000:00:1f.3: period min 192 max 256000 bytes
    [ 2880.905190] sof-audio-pci 0000:00:1f.3: period count 2 max 160
    [ 2880.905191] sof-audio-pci 0000:00:1f.3: buffer max 1280000 bytes
    [ 2880.905417] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 7 dir 1
    [ 2880.905421] sof-audio-pci 0000:00:1f.3: generating page table for 000000001e00a2d0 size 0x3e7c0 pages 63
    [ 2880.905436] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
    [ 2880.906741] sof-audio-pci 0000:00:1f.3: error: stream reset failed
    [ 2880.906743] sof-audio-pci 0000:00:1f.3: error: hdac prepare failed: ffffff92
    [ 2880.906744] sof-audio-pci 0000:00:1f.3: error: platform hw params failed
    [ 2880.906747] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -110
    [ 2880.906749] DMIC16k: ASoC: hw_params FE failed -110
    [ 2880.906752] sof-audio-pci

  6. RDharageswari commented on Mar 12, 2020

    @RDharageswari
    Author

    Yes i could reproduce the issue with 10 seconds also:
    arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10

    dmesg logs: first time:
    [ 2866.862857] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
    [ 2866.862902] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
    [ 2866.862910] sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
    [ 2866.862953] sof-audio-pci 0000:00:1f.3: error: transition from 0 to 4 not allowed
    [ 2866.862954] sof-audio-pci 0000:00:1f.3: error: failed to power down DSP during suspend -22
    [ 2866.862963] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -22)
    localhost ~ # arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10
    second time capture fails:
    localhost ~ # arecord -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=64000 tmp.wav -vvv -d 10
    Recording WAVE 'tmp.wav' : Signed 16 bit Little Endian, Rate 16000 Hz, Stereo
    arecord: set_params:1403: Unable to install hw params:
    ACCESS: MMAP_INTERLEAVED
    FORMAT: S16_LE
    SUBFORMAT: STD
    SAMPLE_BITS: 16
    FRAME_BITS: 32
    CHANNELS: 2
    RATE: 16000
    PERIOD_TIME: 999000
    PERIOD_SIZE: 15984
    PERIOD_BYTES: 63936
    PERIODS: (4 5)
    BUFFER_TIME: 3999000
    BUFFER_SIZE: 63984
    BUFFER_BYTES: 255936
    TICK_TIME: 0

    [ 2880.905186] sof-audio-pci 0000:00:1f.3: pcm: open stream 7 dir 1
    [ 2880.905189] sof-audio-pci 0000:00:1f.3: period min 192 max 256000 bytes
    [ 2880.905190] sof-audio-pci 0000:00:1f.3: period count 2 max 160
    [ 2880.905191] sof-audio-pci 0000:00:1f.3: buffer max 1280000 bytes
    [ 2880.905417] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 7 dir 1
    [ 2880.905421] sof-audio-pci 0000:00:1f.3: generating page table for 000000001e00a2d0 size 0x3e7c0 pages 63
    [ 2880.905436] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
    [ 2880.906741] sof-audio-pci 0000:00:1f.3: error: stream reset failed
    [ 2880.906743] sof-audio-pci 0000:00:1f.3: error: hdac prepare failed: ffffff92
    [ 2880.906744] sof-audio-pci 0000:00:1f.3: error: platform hw params failed
    [ 2880.906747] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -110
    [ 2880.906749] DMIC16k: ASoC: hw_params FE failed -110
    [ 2880.906752] sof-audio-pci

  7. wwittbrx commented on Mar 13, 2020

    @wwittbrx
    Contributor

    I can't reproduce this issue on TGL RVP with slim driver tests.

    Running on
    https://github.com/mrajwa/sof/commits/tgl_dev_2
    746cb8b965d362a99b10d140fa869da80dc9cefa

    Are we running on the same FW? Also, could you provide us with the kernel source?

  8. RDharageswari commented on Mar 13, 2020

    @RDharageswari
    Author

    I am currently using the OTC repo with few changes from broonie tree:
    31f37b4d5033 ASoC: SOF: Intel: hda-loader: clear the IPC ack bit after FW_PURGE done
    2337f615bf53 ASoC: SOF: ipc: check ipc return value before data copy
    907e9be8f1ac ASoC: SOF: pcm: skip DMA buffer pre-allocation
    Firmware used was:
    TGL FW memory layout changing
    @Rajwa, Marcin have a simple test branch for the reference KWD HDA generic tplg in https://github.com/mrajwa/sof/tree/tgl_dev 
    @xiulipan Can you please help with the kernel?

  9. mrajwa commented on Mar 15, 2020

    @mrajwa
    Contributor

    @RDharageswari, kernel has a problem with triggering stream. This is unknown kernel so I can't tell why is it failing, please provide link to the source.

  10. keyonjie commented on Mar 16, 2020

    @keyonjie
    Contributor

    Hi @xiulipan can we try if we can reproduce this issue with Ubuntu on RVP?

  11. xiulipan commented on Mar 16, 2020

    @xiulipan
    Contributor

    @keyonjie @RDharageswari @mrajwa confirmed with master(47420dc) + #2405
    Kernel thesofproject/linux@0f90705
    kconfig https://github.com/thesofproject/kconfig/blob/master/kconfig-sof-default.sh

    $ sudo sof-logger -l sof-tgl.ldc
             TIMESTAMP              DELTA  C# COMPONENT          LOCATION                       CONTENT
    [2387521387.031250] (             nan) c0 MEM                         src/lib/alloc.c:280   ERROR error: 171 blocks needed for allocation but only 170 blocks are remaining
    [2387523072.760417] (     1685.729126) c0 SA                          src/lib/agent.c:56    ERROR validate(), ll drift detected, delta = 51166
    [2387538287.812500] (    15215.051758) c0 kpb          11.53          src/audio/kpb.c:391   ERROR kpb_params(): kpb has been already configured.
    [2429327494.218750] ( 41789208.000000) c0 SA                          src/lib/agent.c:56    ERROR validate(), ll drift detected, delta = 59315
    [2429327996.770833] (      502.552094) c0 kpb                         src/audio/kpb.c:443   ERROR kpb_prepare() error: wrong host params.
    [2429328033.593750] (       36.822918) c0 PIPE                   src/audio/pipeline.c:527   ERROR pipeline_prepare() error: ret = -22, dev->comp.id = 52
    [2429328074.114583] (       40.520832) c0 IPC                       src/ipc/handler.c:311   ERROR ipc: pipe 11 comp 52 prepare failed -22
    

    dmesg

    [ 1214.673646] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
    [ 1214.681850] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
    [ 1214.681857] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 2
    [ 1214.681860] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -22
    [ 1214.681865]  DMIC16k: ASoC: hw_params FE failed -22
    [ 1214.681872] sof-audio-pci 0000:00:1f.3: pcm: free stream 7 dir 1
    [ 1214.682121] sof-audio-pci 0000:00:1f.3: pcm: close stream 7 dir 1
    [ 1215.270366] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
    [ 1215.270408] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
    
    

    Full DMA trace log is attached.
    kwd.txt

  12. 12 remaining items

  13. RDharageswari commented on Mar 18, 2020

    @RDharageswari
    Author

    Hi @mrajwa
    I did check with the firmware on my kernel and still see issues.
    First 2 /3 iterations go well and the moment i hit the failure..subsequent capture fails.
    I am using the FW built out of https://github.com/mrajwa/sof/tree/tgl_dev_2
    For the kernel i am trying to re-test with v5.4.Will update once i test.
    command i use:
    record -Dhw:0,7 -M -N -c 2 -f S16_LE -r 16000 --buffer-size=68000 tmp.wav -vvv

  14. xiulipan commented on Mar 18, 2020

    @xiulipan
    Contributor

    @mrajwa @RDharageswari I run more times on my DUT, did not see issue like your said that failed on 3/3.

    Below is my 5/5 tests

    $ sudo sof-logger -l sof-tgl.ldc
             TIMESTAMP              DELTA  C# COMPONENT          LOCATION                       CONTENT
    [136439847616.093750] (             nan) c0 kpb                         src/audio/kpb.c:1492  ERROR validate_host_params() period_size 135936 buffer_size 543936 min size 0
    [136439855744.635422] (     8128.541504) c0 MEM                         src/lib/alloc.c:280   ERROR error: 171 blocks needed for allocation but only 170 blocks are remaining
    [136439855823.489594] (       78.854164) c0 SA                          src/lib/agent.c:56    ERROR validate(), ll drift detected, delta = 40395
    [136439872406.250000] (    16582.759766) c0 kpb          11.53          src/audio/kpb.c:392   ERROR kpb_params(): kpb has been already configured.
    [136444600150.781250] (  4727744.500000) c0 SA                          src/lib/agent.c:56    ERROR validate(), ll drift detected, delta = 46752
    [136444600653.385422] (      502.604156) c0 kpb                         src/audio/kpb.c:1492  ERROR validate_host_params() period_size 135936 buffer_size 543936 min size 537600
    [136444615473.333344] (    14819.948242) c0 kpb          11.53          src/audio/kpb.c:392   ERROR kpb_params(): kpb has been already configured.
    [136444619830.208344] (     4356.875000) c0 kpb          11.53          src/audio/kpb.c:652   ERROR kpb_copy() error: nothing to copy sink->free 5120 source->avail 0
    [136446709969.218750] (  2090139.000000) c0 kpb                         src/audio/kpb.c:1492  ERROR validate_host_params() period_size 135936 buffer_size 543936 min size 537600
    [136446724901.979172] (    14932.760742) c0 kpb          11.53          src/audio/kpb.c:392   ERROR kpb_params(): kpb has been already configured.
    [136450551972.708344] (  3827070.750000) c0 kpb                         src/audio/kpb.c:1492  ERROR validate_host_params() period_size 135936 buffer_size 543936 min size 537600
    [136450566884.687500] (    14911.979492) c0 kpb          11.53          src/audio/kpb.c:392   ERROR kpb_params(): kpb has been already configured.
    [136452514863.489594] (  1947978.750000) c0 SA                          src/lib/agent.c:56    ERROR validate(), ll drift detected, delta = 60441
    [136452515366.770844] (      503.281250) c0 kpb                         src/audio/kpb.c:1492  ERROR validate_host_params() period_size 135936 buffer_size 543936 min size 537600
    [136452530451.250000] (    15084.479492) c0 kpb          11.53          src/audio/kpb.c:392   ERROR kpb_params(): kpb has been already configured.
    
  15. mengdonglin commented on Mar 18, 2020

    @mengdonglin
    Collaborator

    @mrajwa Can you please share a PR for master branch to support KWD on TGL?

  16. mrajwa commented on Mar 18, 2020

    @mrajwa
    Contributor

    @mengdonglin, sure however we still don't know what is the reason of the issue @RDharageswari is describing.
    @RDharageswari, on the beginning you said the second capture fails, now you are saying "First 2 /3 iterations go well..." so something changed recently?
    The issue seems to be on kernel side not being able to change states.
    I am waiting for your tests results with different kernel.

  17. ranj063 commented on Mar 18, 2020

    @ranj063
    Collaborator

    @RDharageswari looking at the original logs: It looks like after you start the WoV stream, the DSP enters D0I3 but never exits back to D0I0 when you close the stream. And this is why you see that the transition from D0I3 -> D3 ( 0 to 4 in the logs) is not allowed.

    [ 348.303273] sof-audio-pci 0000:00:1f.3: New DSP state 0 substate 1 --> DSP is in D0I3
    [ 365.964915] sof-audio-pci 0000:00:1f.3: ipc rx: 0x50050034
    [ 365.964918] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x50050034
    [ 373.523923] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 7 dir 1 cmd 0
    [ 373.523930] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000
    [ 373.524110] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000
    [ 373.524160] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x240000 successful
    [ 373.524167] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000
    [ 373.525255] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000
    [ 373.525336] sof-audio-pci 0000:00:1f.3: pcm: free stream 7 dir 1
    [ 373.525437] sof-audio-pci 0000:00:1f.3: pcm: close stream 7 dir 1
    [ 373.525577] sof-audio-pci 0000:00:1f.3: received event 4 for widget DETECT12.0
    [ 373.525581] sof-audio-pci 0000:00:1f.3: received event 8 for widget DETECT12.0
    [ 373.525587] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000
    [ 373.525727] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000
    [ 373.525736] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000
    [ 373.526774] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000
    [ 376.026120] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
    [ 376.026154] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000
    [ 376.026337] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000
    [ 376.026432] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
    [ 376.026437] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
    [ 376.026440] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
    [ 376.026500] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at 00000044
    [ 376.026507] sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
    [ 376.026531] sof-audio-pci 0000:00:1f.3: error: transition from 0 to 4 not allowed --> DSP tries to enter D3 and fails
    [ 376.026532] sof-audio-pci 0000:00:1f.3: error: failed to power down DSP during suspend -22
    [ 376.026543] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -22)

  18. ranj063 commented on Mar 19, 2020

    @ranj063
    Collaborator

    problem root caused to a missing patch in the chrome backport:
    "ASoC: SOF: Intel: CNL: add set_power_state() ops" thesofproject/linux@73b51957122d

    @sathya-nujella FYI

  19. RDharageswari commented on Mar 19, 2020

    @RDharageswari
    Author

    Since we work remotely i was just able to do
    arecord
    Ctrl+C
    multiple times and verify. I couldn't still validate the end to end stack.
    As of now using the board from India,will verify the complete functionality with and without S0ix tonight when someone is there at lab and update

  20. ranj063 commented on Mar 20, 2020

    @ranj063
    Collaborator

    @RDharageswari can you please close this issue once you've verified with the added kernel patch?

  21. RDharageswari commented on Mar 20, 2020

    @RDharageswari
    Author

    @ranj063 , I couldnt verify the functionality lsat night due to limited board availability. Will get the board only on Monday.

  22. xiulipan commented on Mar 23, 2020

    @xiulipan
    Contributor

    I have create sof-tgl-max98373-rt5682.tplg with KWD in #2405

    @RDharageswari @emilchudzik could you have a try on the Chrome DUT?
    I am using the latest master FW 9da1fce
    and sof-dev kernel 9b5b6c2

  23. RDharageswari commented on Mar 24, 2020

    @RDharageswari
    Author

    i verified the Wov functionality with the latest master FW 9da1fce
    and the missed patch "ASoC: SOF: Intel: CNL: add set_power_state() ops" thesofproject/linux@73b5195
    functionality works fine.

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

Metadata

Metadata

Labels

Keyword DetectionApplies to Keyword DetectionP1Blocker bugs or important featuresTGLApplies to Tiger LakebugSomething 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