aplay failed after speaker test with Dhw:0,1 on BYT-mb-rt5651

[Jiangxinx]

Summary:
Aplay with Dhw:0,0 failed after speaker test with Dhw:0,1 on BYT-mb-rt5651.

Step:
1.speaker-test -Dhw:0,1 -c2 -t wav

speaker-test 1.1.3

Playback device is hw:0,1
Stream parameters are 48000Hz, S16_LE, 2 channels
WAV file(s)
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 384 to 2095104
Period size range from 192 to 65472
Using max buffer size 2095104
Periods = 4
Unable to set hw params for playback: Invalid argument
Setting of hwparams failed: Invalid argument

2.aplay -Dhw:0,0 -c2 -r48000 -fS16_LE Music/California_Dreaming_48k_16bit.wav -vv -i

Playing WAVE 'Music/California_Dreaming_48k_16bit.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Hardware PCM card 0 'sof-bytcr-rt5651' 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  : 16320
  period_size  : 4032
  period_time  : 84000
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 4032
  period_event : 0
  start_threshold  : 16320
  stop_threshold   : 16320
  silence_threshold: 0
  silence_size : 0
  boundary     : 9187343239835811840
  appl_ptr     : 0
  hw_ptr       : 0
#+                                                 | 00%aplay: pcm_write:2011: write error: Input/output error

Dmesg:

[   19.998283] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[   20.300654] sof-audio-acpi 80860F28:01: ipc rx: 0x90020000: GLB_TRACE_MSG
[   20.300664] sof-audio-acpi 80860F28:01: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   20.800929] sof-audio-acpi 80860F28:01: ipc rx: 0x90020000: GLB_TRACE_MSG
[   20.800943] sof-audio-acpi 80860F28:01: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   22.381706] systemd-journald[1429]: File /var/log/journal/925896dd495840eca8c6be1ff455ace4/user-1000.journal corrupted or uncleanly shut down, renaming and replacing.
[   23.825355] igb 0000:03:00.0 enp3s0: igb: enp3s0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: RX
[   23.825957] IPv6: ADDRCONF(NETDEV_CHANGE): enp3s0: link becomes ready
[  125.294196] sof-audio-acpi 80860F28:01: pcm: open stream 1 dir 0
[  125.294202] sof-audio-acpi 80860F28:01: period min 192 max 262144 bytes
[  125.294205] sof-audio-acpi 80860F28:01: period count 2 max 32
[  125.294207] sof-audio-acpi 80860F28:01: buffer max 8388608 bytes
[  125.294404] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  125.294407] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  125.294412] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  125.294415] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  125.305698] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  125.305703] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  125.305713] sof-audio-acpi 80860F28:01: pcm: hw params stream 1 dir 0
[  125.305720] sof-audio-acpi 80860F28:01: generating page table for 00000000bc28ba37 size 0x7fe000 pages 2046
[  125.305744] sof-audio-acpi 80860F28:01: stream_tag 0
[  125.305754] sof-audio-acpi 80860F28:01: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  125.306179] sof-audio-acpi 80860F28:01: error: ipc error for 0x60010000 size 20
[  125.306187] sof-audio-acpi 80860F28:01: error: hw params ipc failed for stream 0
[  125.306190] sof-audio-acpi 80860F28:01: ASoC: 80860F28:01 hw params failed: -22
[  125.306194]  Media Playback 1: ASoC: hw_params FE failed -22
[  125.306202] sof-audio-acpi 80860F28:01: pcm: free stream 1 dir 0
[  125.306207] sof-audio-acpi 80860F28:01: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  125.306368] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  125.306483] sof-audio-acpi 80860F28:01: pcm: close stream 1 dir 0
[  125.343068] sof-audio-acpi 80860F28:01: ipc rx: 0x90020000: GLB_TRACE_MSG
[  125.343091] sof-audio-acpi 80860F28:01: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  158.074172] random: crng init done
[  158.074177] random: 7 urandom warning(s) missed due to ratelimiting
[  168.079201] rfkill: input handler disabled
[  187.329927] sof-audio-acpi 80860F28:01: pcm: open stream 0 dir 0
[  187.329932] sof-audio-acpi 80860F28:01: period min 192 max 16384 bytes
[  187.329935] sof-audio-acpi 80860F28:01: period count 2 max 16
[  187.329938] sof-audio-acpi 80860F28:01: buffer max 65536 bytes
[  187.333506] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  187.333511] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  187.333518] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  187.333520] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  187.333530] sof-audio-acpi 80860F28:01: rate_min: 48000 rate_max: 48000
[  187.333532] sof-audio-acpi 80860F28:01: channels_min: 2 channels_max: 2
[  187.336620] sof-audio-acpi 80860F28:01: pcm: hw params stream 0 dir 0
[  187.336642] sof-audio-acpi 80860F28:01: generating page table for 000000004dc19d72 size 0xff00 pages 16
[  187.336655] sof-audio-acpi 80860F28:01: stream_tag 0
[  187.336675] sof-audio-acpi 80860F28:01: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  187.337032] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  187.367977] sof-audio-acpi 80860F28:01: ipc rx: 0x90020000: GLB_TRACE_MSG
[  187.368000] sof-audio-acpi 80860F28:01: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  187.740825] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 1
[  187.740833] sof-audio-acpi 80860F28:01: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  187.740911] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  188.342128] sof-audio-acpi 80860F28:01: PCM: stream 0 dir 0 DMA position 0 DAI position 0
[  188.849832] sof-audio-acpi 80860F28:01: pcm: trigger stream 0 dir 0 cmd 0
[  188.849841] sof-audio-acpi 80860F28:01: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  188.851427] sof-audio-acpi 80860F28:01: error: ipc error for 0x60050000 size 12
[  188.851439]  Low Latency: ASoC: trigger FE failed -5
[  188.851459] sof-audio-acpi 80860F28:01: pcm: free stream 0 dir 0
[  188.851464] sof-audio-acpi 80860F28:01: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  188.851775] sof-audio-acpi 80860F28:01: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  188.851833] sof-audio-acpi 80860F28:01: pcm: close stream 0 dir 0

Sof-logger:

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          IPC         111617668.281250 111617672.000000    src/ipc/handler.c:296 	ipc: comp 21 parse descriptors failed -12
    0      1          DMA         111617681.875000        13.593750 src/drivers/dw/dma.c:442 	dw-dma: 1 invalid channel -1
    0      1          DMA         111617934.947917       253.072922 src/drivers/dw/dma.c:442 	dw-dma: 1 invalid channel -1
    0      1          DMA         174154314.322917  62536380.000000 src/drivers/dw/dma.c:807 	dw-dma: 0 channel 0 not enough elems for config with irq disabled
    0      1       BUFFER         174154324.843750        10.520833  src/lib/dma-trace.c:90  	trace_work() error: dma_copy_to_host_nowait() failed
    0      1          DMA         174654314.322917    499989.468750 src/drivers/dw/dma.c:807 	dw-dma: 0 channel 0 not enough elems for config with irq disabled
    0      1       BUFFER         174654324.843750        10.520833  src/lib/dma-trace.c:90  	trace_work() error: dma_copy_to_host_nowait() failed
    0      1         WAIT         175137506.562500    483181.718750       src/lib/wait.c:118 	ewt
    0      1          DMA         175137513.125000         6.562500 src/drivers/dw/dma.c:647 	dw-dma: 1 channel 0 timeout
    0      1          IPC         175137527.708333        14.583333 src/audio/pipeline.c:541 	pipeline_trigger() error: ret = -5, host->comp.id = 1, cmd = 0
    0      1          IPC         175137543.229167        15.520833    src/ipc/handler.c:498 	ipc: comp 1 trigger 0x50000 failed -5

Test env:
sof master: cd4633c
kernel sof-dev: 0ba314f
tplg: sof-byt-rt5651.tplg

Log:
dmesg.log
logger.log

[tlauda]

Please verify after applying following patches: #1136, #1159, #1160 and #1162.

[ranj063]

@tlauda this is not related to the noise issue. so the above PR's likely wont help

[ranj063]

@Jiangxinx it looks like the speaker-test failed in the first step. So obviously aplay after that will fail as well.
I am suspecting the kernel is not updated.

[ranj063]

I have verified this issue doesnt exist with these commits:
kernel commit: thesofproject/linux@2293bc7
fw commit: de46954

[tlauda]

@ranj063 I've suggested above PR's, because probably all of them are needed to make speaker test work. Error highlighted above is fixed by #1159.

[ranj063]

@tlauda all of the above PR's are merged to master now and the commit I included is the latest tip of master

[tlauda]

@Jiangxinx Any updates?

[Jiangxinx]

This issue can still be reproduced on daily test.
Test env:
sof master: 742f83b
kernel sof-dev: e29122d
tplg: sof-byt-rt5651.tplg

[juimonen]

For me the speaker test (so playing to hw 0,1) will fail despite of playing first to hw 0,0.

attached logs for playing to hp (hw 0,0) and to speaker (0,1), not sure these correspond to actual speaker and hp devices, but you can understand the difference.

so:

aplay -Dhw:0,0 -c2 -r48000 -fS16_LE test48.wav:
hp_test_dmesg.txt
hp_test_logger.txt

aplay -Dhw:0,1 -c2 -r48000 -fS16_LE test48.wav
speaker_test_dmesg.txt
speaker_test_logger.txt