[BUG][BYT] pause release error: Device or resource busy when do playback/capture test.

Describe the bug
Pause release error: Device or resource busy when do playback/capture test on BYT platform.

To Reproduce
1.Playback via "aplay -Dhw:0,0 -r48000 -c2 -fs16_le 1.wav -vv -i"
2.Pause aplay
3.Resume aplay

Reproduction Rate
1/20

Environment
Firmware: fee2517 https://github.com/thesofproject/sof/commits/master
Kernel: df832fb https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-byt-nocodec.tplg
platform： BYT

Screenshots or console output

ubuntu@cd-byt-mb-nocodec-04:~$ aplay -Dhw:0,0 -fS16_LE -c2 -r 48000 audio-files/raw/test-c2-r48000-fs16_le-d60.raw -vv -i
Playing raw data 'audio-files/raw/test-c2-r48000-fs16_le-d60.raw' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Hardware PCM card 0 'sof-nocodec' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 48000
  exact rate   : 48000 (48000/1)
  msbits       : 16
  buffer_size  : 16368
  period_size  : 4080
  period_time  : 85000
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 4080
  period_event : 0
  start_threshold  : 16368
  stop_threshold   : 16368
  silence_threshold: 0
  silence_size : 0
  boundary     : 9214364837600034816
  appl_ptr     : 0
  hw_ptr       : 0
=== PAUSE ===                                                             aplay: do_pause:1508: pause release error: Device or resource busy

sof-logger

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1         WAIT          67877602.239583  67877600.000000       src/lib/wait.c:89     ewt
    0      1          DMA          67877608.541667         6.302083 src/drivers/dw/dma.c:375    dw_dma_stop() error: dma 1 channel 1 timeout
    0      1          DMA          67891738.281250     14129.739258 src/drivers/dw/dma.c:218    dw_dma_start() error: dma 1 channel 1 not ready ena 0x2 status 0x3
    0      1          IPC          67891750.677083        12.395833 src/audio/pipeline.c:701    pipeline_trigger() error: ret = -16, host->comp.id = 1, cmd = 3
    0      1          IPC          67891760.833333        10.156250    src/ipc/handler.c:489    ipc: comp 1 trigger 0x70000 failed -16
    0      1          DMA          78763174.114583  10871413.000000 src/drivers/dw/dma.c:218    dw_dma_start() error: dma 1 channel 1 not ready ena 0x2 status 0x3
    0      1          IPC          78763186.510417        12.395833 src/audio/pipeline.c:701    pipeline_trigger() error: ret = -16, host->comp.id = 1, cmd = 3
    0      1          IPC          78763196.666667        10.156250    src/ipc/handler.c:489    ipc: comp 1 trigger 0x70000 failed -16
    0      1         COMP          78764922.291667      1725.625000 rc/audio/component.c:192    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          78764931.979167         9.687500 rc/audio/component.c:192    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          78764941.614583         9.635417 rc/audio/component.c:192    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          78764952.656250        11.041667 rc/audio/component.c:192    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET

dmesg

[   67.398671] sof-audio-acpi 80860F28:01: posn : host 0x39c0 dai 0x106680 wall 0x17c5a1
[   67.398700] sof-audio-acpi 80860F28:01: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   67.398736] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 268704
[   67.400662] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 268704
[   67.400684] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
[   67.400701] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   67.401400] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   67.411109] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
[   67.411118] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   67.411203] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   67.411368] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 268704
[   68.018975] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 3696 DAI position 268704
[   68.018997] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
[   68.019015] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   68.020565] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   68.034475] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
[   68.034484] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   68.035160] sof-audio-acpi 80860F28:01: error: ipc error for 0x60070000 size 12
[   68.035175]  Low Latency: ASoC: trigger FE failed -16
[   68.035188] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
[   68.035195] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   68.035273] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   78.908624] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 4
[   78.908646] sof-audio-acpi 80860F28:01: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   78.908811] sof-audio-acpi 80860F28:01: error: ipc error for 0x60070000 size 12
[   78.908886]  Low Latency: ASoC: trigger FE failed -16
[   78.908909] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 3
[   78.908924] sof-audio-acpi 80860F28:01: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   78.910347] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   78.910383] sof-audio-acpi 80860F28:01: pcm: free stream 0 dir 0
[   78.910398] sof-audio-acpi 80860F28:01: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   78.911004] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   78.911047] sof-audio-acpi 80860F28:01: pcm: close stream 0 dir 0

This issue also can be observed on apl platform.

@Jiangxinx

@Jiangxinx Please provide FW logs from APL.

Add apl logs:

Screenshots or console output

ubuntu@cd-apl-up2-pcm512x-07:~$ aplay -Dhw:0,0 -r48000 -c2 -fs16_le audio-files/raw/test-c2-r48000-fs32_le-d60.raw -vv -i
Playing raw data 'audio-files/raw/test-c2-r48000-fs32_le-d60.raw' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Hardware PCM card 0 'sof-bxt-pcm512x' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 48000
  exact rate   : 48000 (48000/1)
  msbits       : 16
  buffer_size  : 16368
  period_size  : 4080
  period_time  : 85000
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 4080
  period_event : 0
  start_threshold  : 16368
  stop_threshold   : 16368
  silence_threshold: 0
  silence_size : 0
  boundary     : 9214364837600034816
  appl_ptr     : 0
  hw_ptr       : 0
=== PAUSE ===                                                                                         aplay: do_pause:1497: pause push error: Connection timed out
=== PAUSE ===                                                                                          aplay: do_pause:1497: pause push error: Connection timed out
=== PAUSE ===                                                                            aplay: do_pause:1497: pause push error: Connection timed out
=== PAUSE ===                                                                     aplay: do_pause:1497: pause push error: Connection timed out
=== PAUSE ===                                                                            aplay: do_pause:1497: pause push error: Connection timed out
=== PAUSE ===                                                            aplay: do_pause:1497: pause push error: Connection timed out
#+                                                 | 00%aplay: pcm_write:2011: write error: Input/output error

dmesg

[ 1335.974267] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 4
[ 1335.975061] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x14001e successful
[ 1335.975084] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 1336.478119] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60070000 size 12
[ 1336.478131] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 1336.478141] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1336.478189] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1336.478199] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 1336.478204] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1336.478212] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1336.478217] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1336.478226]  Port5: ASoC: trigger FE failed -110
[ 1336.478416] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 3
[ 1336.478425] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 1336.982135] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60060000 size 12
[ 1336.982148] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 1336.982158] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1336.982207] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1336.982219] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 1336.982224] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1336.982233] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1336.982239] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1336.983044] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x140000 successful
[ 1336.983064]  Port5: ASoC: trigger FE failed -110
[ 1336.983092] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 4
[ 1336.983101] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x14001e successful
[ 1336.983112] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 1337.486122] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60070000 size 12
[ 1337.486136] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 1337.486146] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1337.486194] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1337.486206] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 1337.486211] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1337.486220] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1337.486226] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1337.486236]  Port5: ASoC: trigger FE failed -110
[ 1338.598284] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[ 1338.598299] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1339.102151] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60050000 size 12
[ 1339.102165] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 1339.102174] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1339.102222] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1339.102234] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 1339.102240] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1339.102248] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1339.102254] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1339.102267] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x140000 successful
[ 1339.102275]  Port5: ASoC: trigger FE failed -110
[ 1339.102318] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[ 1339.102327] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1339.606115] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[ 1339.606128] sof-audio-pci 0000:00:0e.0: info: preventing DSP entering D3 state to preserve context
[ 1339.606137] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1339.606184] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[ 1339.606195] sof-audio-pci 0000:00:0e.0: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[ 1339.606200] sof-audio-pci 0000:00:0e.0: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 1339.606208] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1339.606213] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1339.620836] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0

sof-logger

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1          MEM         1311519395.104167              nan      src/lib/alloc.c:273   error: 4 blocks needed for allocation but only 1 blocks are remaining
    0      1          MEM         1311676056.927083    156661.828125      src/lib/alloc.c:273   error: 6 blocks needed for allocation but only 0 blocks are remaining
    0      1          DAI 1.8     1317018733.437500   5342676.500000      src/audio/dai.c:586   dai_check_for_xrun() error: underrun due to no data available
    0      1         COMP         1317018739.166667         5.729167 of/audio/component.h:743   comp_underrun() error: dev->comp.id = 8, source->avail = 768, copy_bytes = 0
    0      1         PIPE         1317018872.708333       133.541672 src/audio/pipeline.c:830   pipeline_copy() error: ret = -61
    0      1         PIPE 1.9     1317018879.062500         6.354167 src/audio/pipeline.c:1034  pipeline_task(): xrun recover failed! pipeline will be stopped!

Environment
Firmware: c8bc4b2 https://github.com/thesofproject/sof/commits/master
Kernel: 0f665a4 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-apl-pcm512x.tplg
platform： APL

@Jiangxinx

@Jiangxinx Are you playing on HDA?

@tlauda

@tlauda No, I played using I2S device ( -Dhw:0,0 ).

This issues still can be reproduced on BYT platform. However, the phenomenon is very strange.
I tested it on two similar devices (byt-nocodec) ,and one can reproduce it, another cannot reproduced it. It seems that this issue is not related to the sof version, and will suddenly appear from time to time.

Environment
Firmware: b5982a4 https://github.com/thesofproject/sof/commits/master
Kernel: 5edcfdf https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-byt-nocodec.tplg
platform： BYT

test result
device: ubuntu@sh-byt-mb-nocodec-03
result: pass
alsamixer setting:
03-asound.txt

device: ubuntu@cd-byt-mb-nocodec-04
result: failed
alsamixer setting:
04-asound.txt

ack. will start checking tomorrow...

@tlauda

using latest kernel & fw, very easy to reproduce this error with pause/release:
aplay: pcm_write:2011: write error: Input/output error

attaching fw log, @tlauda any idea?
byt_fw_log.txt

is byt affected by the 3 periods change?

and the above was with nocodec topology

@juimonen

@juimonen Could you verify if #1984 improves it?

@tlauda

@tlauda yes #1984 seems to help and I can't reporoduce it now.

@Jiangxinx

@Jiangxinx can you also try/verify with #1984? my test's we're very minimal, but could not reproduce the issue..

@juimonen

@juimonen @tlauda Very strange, I tried #1984 , I still can reproduce it on my device.

Environment
Kernel: 2114793 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-byt-nocodec.tplg
platform： BYT

sof-logger

ubuntu@cd-byt-mb-nocodec-04:~$ sudo sof-logger -l /etc/sof/sof-byt.ldc
 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1         WAIT          52291068.854167  52291068.000000       src/lib/wait.c:89     ewt
    0      1          DMA          52291076.093750         7.239583 src/drivers/dw/dma.c:381    dw_dma_stop() error: dma 1 channel 1 timeout
    0      1          DMA          52299603.072917      8526.979492 src/drivers/dw/dma.c:224    dw_dma_start() error: dma 1 channel 1 not ready ena 0x2 status 0x3
    0      1          IPC          52299616.197917        13.125000 src/audio/pipeline.c:679    pipeline_trigger() error: ret = -16, host->comp.id = 1, cmd = 3
    0      1          IPC          52299627.031250        10.833333    src/ipc/handler.c:489    ipc: comp 1 trigger 0x70000 failed -16
    0      1         WAIT          52739869.427083    440242.406250       src/lib/wait.c:89     ewt
    0      1       BUFFER          52739876.562500         7.135417 rc/trace/dma-trace.c:71     trace_work() error: dma_copy_to_host_nowait() failed
    0      1          DMA          56748092.239583   4008215.750000 src/drivers/dw/dma.c:224    dw_dma_start() error: dma 1 channel 1 not ready ena 0x3 status 0x3
    0      1          IPC          56748105.312500        13.072917 src/audio/pipeline.c:679    pipeline_trigger() error: ret = -16, host->comp.id = 1, cmd = 3
    0      1          IPC          56748116.145833        10.833333    src/ipc/handler.c:489    ipc: comp 1 trigger 0x70000 failed -16
    0      1         COMP          56749400.416667      1284.270874 rc/audio/component.c:165    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          56749411.510417        11.093750 rc/audio/component.c:165    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          56749422.500000        10.989583 rc/audio/component.c:165    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET
    0      1         COMP          56749440.416667        17.916666 rc/audio/component.c:165    comp_set_state() error: wrong state = 4, COMP_TRIGGER_RESET

@Jiangxinx

@Jiangxinx Could you attach full log from sof-logger -t? Also does it reproduce only on one machine or on couple of them. This particular error looks like some kind of HW problem.

@tlauda

@tlauda Attached the full fw log:
logger.log

@tlauda

@tlauda Yes, I tried two machines, another one still can not reproduce it, but my device is very easy to reproduce it.

@Jiangxinx

@Jiangxinx I have no idea what is going on with this particular platform. I can't reproduce the issue on any other BYT. After stopping and restarting DMA there is no interrupt coming and we cannot stop DMA. Hardware is stuck. Could you look for the differences between platforms? Maybe BIOS is different or has different settings? I've tried 3 different platforms and it didn't reproduce.

@tlauda

@tlauda @Jiangxinx same here also: I've been hitting the space bar like crazy in my byt-mb-> no error... it just works for me with #1984

Close it as it is HW problem.

Navigation Menu

Repository navigation

[BUG][BYT] pause release error: Device or resource busy when do playback/capture test. #1911

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG][BYT] pause release error: Device or resource busy when do playback/capture test. #1911

Description

Activity

Jiangxinx commented on Oct 9, 2019

tlauda commented on Oct 9, 2019

Jiangxinx commented on Oct 9, 2019

tlauda commented on Oct 9, 2019

Jiangxinx commented on Oct 9, 2019

Jiangxinx commented on Oct 16, 2019

juimonen commented on Oct 22, 2019

juimonen commented on Oct 23, 2019

juimonen commented on Oct 23, 2019

tlauda commented on Oct 23, 2019

juimonen commented on Oct 23, 2019

juimonen commented on Oct 23, 2019

Jiangxinx commented on Oct 23, 2019

tlauda commented on Oct 23, 2019

Jiangxinx commented on Oct 23, 2019

Jiangxinx commented on Oct 23, 2019

tlauda commented on Oct 23, 2019

juimonen commented on Oct 23, 2019

Jiangxinx commented on Oct 25, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions