[BUG] [BDW] aplay failed on bdw

[xiulipan]

Describe the bug
aplay will got aplay: pcm_write:2011: write error: Input/output error error
To Reproduce
aplay -Dhw:0,0 -f dat /dev/zero -vvv

Reproduction Rate
10/10

Expected behavior
aplay can work

Impact
bdw playback is broken again

Environment
last kernel (98b6f21) with nocodec
and fw with 3d44dea

Screenshots or console output

$ aplay -Dhw:0,1 -f dat /dev/zero -vvv
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Hardware PCM card 0 'sof-broadwell-rt286' device 1 subdevice 0
Max peak (12000 samples): 0x00000000 #                    0%
Max peak (12000 samples): 0x00000000 #                    0%
Max peak (12000 samples): 0x00000000 #                    0%
Max peak (12000 samples): 0x00000000 #                    0%
aplay: pcm_write:2011: write error: Input/output error

error trace:

$ sudo sof-logger -l /etc/sof/sof-bdw.ldc
 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1           SA         13891601120.572918              nan      src/lib/agent.c:55   validate(), ll drift detected, delta = 358652

dma trace:

    0      2          IPC         13976164179.479168  76163264.000000    src/ipc/handler.c:228  ipc: comp 12 -> params
    0      2          DMA         13976164235.000000        55.520832 src/drivers/dw/dma.c:137  dw_dma_channel_get(): dma 1 request channel 0
    0      2          DMA         13976167215.156250      2980.156250 src/drivers/dw/dma.c:196  dw_dma_channel_put(): dma 1 channel 3 put
    0      2         PIPE 2.17    13976167448.072918       232.916672 src/audio/pipeline.c:385  pipeline_params()
    0      2         HOST 2.12    13976167499.427084        51.354168     src/audio/host.c:467  host_params()
    0      2       BUFFER         13976167548.958334        49.531250   src/audio/buffer.c:25   buffer_alloc()
    0      2          DMA         13976167889.583334       340.625000 src/drivers/dw/dma.c:137  dw_dma_channel_get(): dma 1 request channel 65535
    0      2       VOLUME 2.13    13976168045.677084       156.093750 udio/volume/volume.c:267  volume_params()
    0      2          DAI 2.16    13976168102.343750        56.666668      src/audio/dai.c:352  dai_params()
    0      2       BUFFER         13976168150.677084        48.333332   src/audio/buffer.c:25   buffer_alloc()
    0      2          DAI 2.16    13976168575.989584       425.312500      src/audio/dai.c:313  dai_capture_params() src_dev = 2 stream_id = 0 src_width = 4 dest_width = 4
    0      2          DAI 2.16    13976168611.302084        35.312500      src/audio/dai.c:320  dai_capture_params() fifo FFFFC010
    0      2         PIPE 2.17    13976168700.416668        89.114586 src/audio/pipeline.c:492  pipeline_prepare()
    0      2         HOST 2.12    13976168824.166668       123.750000     src/audio/host.c:618  host_prepare()
    0      2       VOLUME 2.13    13976169151.250000       327.083344 udio/volume/volume.c:621  volume_prepare()
    0      2          DAI 2.16    13976169484.843750       333.593750      src/audio/dai.c:450  dai_prepare()
    0      2          IPC         13976180275.208334     10790.364258    src/ipc/handler.c:457  ipc: comp 12 -> trigger cmd 0x40000
    0      2         PIPE 2.17    13976180325.729168        50.520832 src/audio/pipeline.c:711  pipeline_trigger()
    0      2         HOST 2.12    13976180363.645834        37.916668     src/audio/host.c:299  host_trigger()
    0      2       VOLUME 2.13    13976180464.895834       101.250000 udio/volume/volume.c:563  volume_trigger()
    0      2          DAI 2.16    13976180510.520834        45.625000      src/audio/dai.c:536  dai_comp_trigger(), command = 1
    0      2          DAI 2.16    13976180589.322918        78.802086      src/audio/dai.c:552  dai_comp_trigger(), START
    0      2          SSP         13976180624.114584        34.791668 /intel/haswell/ssp.c:481  ssp_trigger()
    0      2          SSP         13976180660.364584        36.250000 /intel/haswell/ssp.c:417  ssp_start()
    0      2  SCHEDULE_LL         13976180745.000000        84.635414 _multi_chan_domain.c:109  dma_multi_chan_domain_register()
    0      2  SCHEDULE_LL         13976180788.333334        43.333332 _multi_chan_domain.c:70   dma_multi_chan_domain_irq_register()
    0      2          IPC         14003126495.781250  26945708.000000    src/ipc/handler.c:457  ipc: comp 12 -> trigger cmd 0x50000
    0      2         PIPE 2.17    14003126546.250000        50.468750 src/audio/pipeline.c:711  pipeline_trigger()
    0      2         HOST 2.12    14003126584.166668        37.916668     src/audio/host.c:299  host_trigger()
    0      2       VOLUME 2.13    14003126692.708334       108.541664 udio/volume/volume.c:563  volume_trigger()
    0      2          DAI 2.16    14003126738.125000        45.416668      src/audio/dai.c:536  dai_comp_trigger(), command = 0
    0      2          DAI 2.16    14003126835.989584        97.864586      src/audio/dai.c:600  dai_comp_trigger(), PAUSE/STOP
    0      2          DMA         14003126870.729168        34.739582 src/drivers/dw/dma.c:366  dw_dma_stop(): dma 1 channel 2 stop
    0      2          SSP         14003126908.125000        37.395832 /intel/haswell/ssp.c:481  ssp_trigger()
    0      2          SSP         14003126949.895834        41.770832 /intel/haswell/ssp.c:453  ssp_stop(), RX stop
    0      2          SSP         14003126986.354168        36.458332 /intel/haswell/ssp.c:471  ssp_stop(), SSP port disabled
    0      2  SCHEDULE_LL         14003127039.375000        53.020832 _multi_chan_domain.c:197  dma_multi_chan_domain_unregister()
    0      2  SCHEDULE_LL         14003127092.187500        52.812500 _multi_chan_domain.c:173  dma_multi_chan_domain_irq_unregister()
    0      2          IPC         14003131274.739584      4182.552246    src/ipc/handler.c:346  ipc: comp 12 -> free
    0      2         PIPE 2.17    14003131324.635418        49.895832 src/audio/pipeline.c:786  pipeline_reset()
    0      2         HOST 2.12    14003131361.302084        36.666668     src/audio/host.c:661  host_reset()
    0      2          DMA         14003131396.145834        34.843750 src/drivers/dw/dma.c:196  dw_dma_channel_put(): dma 1 channel 3 put
    0      2       BUFFER         14003131573.489584       177.343750   src/audio/buffer.c:115  buffer_free()
    0      2       VOLUME 2.13    14003131698.385418       124.895836 udio/volume/volume.c:671  volume_reset()
    0      2          DAI 2.16    14003131742.968750        44.583332      src/audio/dai.c:498  dai_reset()
    0      2       BUFFER         14003131796.197918        53.229168   src/audio/buffer.c:115  buffer_free()
    0      2          IPC         25234628831.979168              nan    src/ipc/handler.c:228  ipc: comp 18 -> params
    0      2          DMA         25234628895.052086        63.072918 src/drivers/dw/dma.c:137  dw_dma_channel_get(): dma 1 request channel 0
    0      2          DMA         25234631877.447918      2982.395752 src/drivers/dw/dma.c:196  dw_dma_channel_put(): dma 1 channel 3 put
    0      2         PIPE 3.24    25234632162.812500       285.364594 src/audio/pipeline.c:385  pipeline_params()
    0      2         HOST 3.18    25234632214.479168        51.666668     src/audio/host.c:467  host_params()
    0      2       BUFFER         25234632264.427086        49.947918   src/audio/buffer.c:25   buffer_alloc()
    0      2          DMA         25234632904.270836       639.843750 src/drivers/dw/dma.c:137  dw_dma_channel_get(): dma 1 request channel 65535
    0      2       VOLUME 3.19    25234633062.916668       158.645828 udio/volume/volume.c:267  volume_params()
    0      2          SRC 3.20    25234633126.927086        64.010414  src/audio/src/src.c:545  src_params()
    0      2          SRC         25234633160.416668        33.489582  src/audio/src/src.c:555  src_params(): src->source_rate: 0
    0      2          SRC         25234633193.645836        33.229168  src/audio/src/src.c:556  src_params(): src->sink_rate: 48000
    0      2          SRC 3.20    25234633232.552086        38.906250  src/audio/src/src.c:582  src_params(), source_rate = 48000, sink_rate = 48000
    0      2          SRC 3.20    25234633265.625000        33.072918  src/audio/src/src.c:585  src_params(), sourceb->channels = 2, sinkb->channels = 2, dev->frames = 96
    0      2          SRC 3.20    25234633310.625000        45.000000  src/audio/src/src.c:595  src_params(), blk_in = 0, blk_out = 0
    0      2        MIXER 1.4     25234633434.843750       124.218750    src/audio/mixer.c:179  mixer_params()
    0      2       VOLUME 1.3     25234633503.281250        68.437500 udio/volume/volume.c:267  volume_params()
    0      2          DAI 1.9     25234633560.625000        57.343750      src/audio/dai.c:352  dai_params()
    0      2       BUFFER         25234633609.062500        48.437500   src/audio/buffer.c:25   buffer_alloc()
    0      2          DAI 1.9     25234634031.666668       422.604156      src/audio/dai.c:249  dai_playback_params() dest_dev = 3 stream_id = 0 src_width = 4 dest_width = 4
    0      2          DAI 1.9     25234634067.135418        35.468750      src/audio/dai.c:256  dai_playback_params() fifo FFFFC010
    0      2         PIPE 3.24    25234634167.083336        99.947914 src/audio/pipeline.c:492  pipeline_prepare()
    0      2         HOST 3.18    25234634204.114586        37.031250     src/audio/host.c:618  host_prepare()
    0      2       VOLUME 3.19    25234636491.041668      2286.927002 udio/volume/volume.c:621  volume_prepare()
    0      2          SRC 3.20    25234638784.479168      2293.437500  src/audio/src/src.c:792  src_prepare()
    0      2        MIXER 1.4     25234641079.583336      2295.104248    src/audio/mixer.c:367  mixer_prepare()
    0      2       VOLUME 1.3     25234641410.625000       331.041656 udio/volume/volume.c:621  volume_prepare()
    0      2          DAI 1.9     25234641744.739586       334.114594      src/audio/dai.c:450  dai_prepare()
    0      2          IPC         25234657535.208336     15790.468750    src/ipc/handler.c:457  ipc: comp 18 -> trigger cmd 0x40000
    0      2         PIPE 3.24    25234657593.281250        58.072918 src/audio/pipeline.c:711  pipeline_trigger()
    0      2         HOST 3.18    25234657631.197918        37.916668     src/audio/host.c:299  host_trigger()
    0      2       VOLUME 3.19    25234657734.479168       103.281250 udio/volume/volume.c:563  volume_trigger()
    0      2          SRC 3.20    25234657780.104168        45.625000  src/audio/src/src.c:679  src_trigger()
    0      2  SCHEDULE_LL         25234657829.322918        49.218750 _multi_chan_domain.c:109  dma_multi_chan_domain_register()
    0      2        MIXER 1.4     25234657904.687500        75.364586    src/audio/mixer.c:232  mixer_trigger()
    0      2       VOLUME 1.3     25234657951.145836        46.458332 udio/volume/volume.c:563  volume_trigger()
    0      2          DAI 1.9     25234657996.302086        45.156250      src/audio/dai.c:536  dai_comp_trigger(), command = 1
    0      2          DAI 1.9     25234658097.187500       100.885414      src/audio/dai.c:552  dai_comp_trigger(), START
    0      2          SSP         25234658131.979168        34.791668 /intel/haswell/ssp.c:481  ssp_trigger()
    0      2          SSP         25234658168.229168        36.250000 /intel/haswell/ssp.c:417  ssp_start()
    0      2  SCHEDULE_LL         25234658254.427086        86.197914 _multi_chan_domain.c:109  dma_multi_chan_domain_register()
    0      2  SCHEDULE_LL         25234658296.875000        42.447918 _multi_chan_domain.c:70   dma_multi_chan_domain_irq_register()

bisect to be caused by c89d916@#1950

arecord is not influenced by this case.

[paulstelian97]

Related to #2214 (related bisect, same manifestation, different platform). In my case, once aplay fails I cannot start it again and arecord also fails with IPC timeout.

[xiulipan]

@paulstelian97 update with some debug finding:
Add trace here and find there is no such caller to dma chan in the notify->list

sof/src/lib/notifier.c

Lines 118 to 122 in 3d44dea

	list_for_item_safe(wlist, tlist, &notify->list[type]) {
	handle = container_of(wlist, struct callback_handle, list);
	if (!caller || !handle->caller || handle->caller == caller)
	handle->cb(handle->receiver, type, data);
	}

Then add log to

sof/src/lib/notifier.c

Line 69 in 3d44dea

void notifier_unregister(void *receiver, void *caller, enum notify_id type)

the chan was unregistered from

sof/src/lib/notifier.c

Line 100 in 3d44dea

void notifier_unregister_all(void *receiver, void *caller)

Then find it was called in

sof/src/drivers/dw/dma.c

Line 178 in 3d44dea

notifier_unregister_all(NULL, channel);

sof/src/drivers/dw/dma.c

Line 191 in 3d44dea

static void dw_dma_channel_put(struct dma_chan_data *channel)

Not sure why the chan is freed before we are trying to use the notifier register with them. @tlauda @akloniex @jajanusz could you help to keep track the issue?

[paulstelian97]

@xiulipan Can you actually point out to where the notifier_register would happen after a dw_dma_channel_put happened? Also, would XRUN recovery have anything to do with that situation?

[lgirdwood]

@xiulipan, @fredoh9 what's ETA for BDW on CI ?

[ranj063]

@xiulipan How could this happen within the last 2 days? When we merged #2188, wasnt aplay working? Should be easy to bisect no?