[BUG] Cherrytrail DMA fails occasionally

[cujomalainey]

Describe the bug
Cherrytrail playback fails, reboots sometimes gets system to a good state which allows playback but occasionally this will appear in the logs

    0      2          DMA          32400464.635417         1.979167   src/drivers/dw/dma.c:442    dw_dma_stop(): dma 1 channel 0 stop
    0      1         WAIT          32401809.166667      1344.531250   src/lib/wait.c:96     ewt
    0      1          DMA          32401815.989583         6.822917   src/drivers/dw/dma.c:460    dw_dma_stop() error: dma 1 channel 0

or

    0      2          SSP          51489200.677083         2.708333 intel/baytrail/ssp.c:572    ssp_trigger()                                                                                                                                                                              
    0      2          SSP          51489203.385417         2.708333 intel/baytrail/ssp.c:521    ssp_start()                                                                                                                                                                                
    0      1          DMA          51490154.375000       950.989563 src/drivers/dw/dma.c:275    dw_dma_start() error: dma 2 channel 1 not ready ena 0x0 status 0x5                                                                                                                         
    0      1         HOST 1.1      51490166.093750        11.718750     src/audio/host.c:796    host_copy() error: dma_copy() failed, ret = 4294967280                                                                                                                                     
    0      1         PIPE          51490174.687500         8.593750 src/audio/pipeline.c:801    pipeline_copy() error: ret = -16, start->comp.id = 3, dir = 1                                                                                                                              
    0      1         PIPE 1.10     51490184.843750        10.156250 src/audio/pipeline.c:977    pipeline_task(): xrun recover failed! pipeline will be stopped!

To Reproduce
Load cyan with SOF Tot and attempt to run a speaker test

Reproduction Rate
4 out of 5 reboots approximately

Expected behavior
system is stable

Impact
blocker for kerneluprev for bsw

Environment

1. Branch name and commit hash
   • SOF 460c41a (master) (with topology: sof-cht-max98090 move DAI definition above media pipeline #1846 and topology: cht-max98090 add missing virtual widgets #1842)
   • Kernel 6fc7eb3 (topic/sof-dev)
2. Name of the topology file
   • sof-cht-max98090.tplg
3. Name of the platform(s) on which the bug is observed
   • Cherrytrail

Screenshots or console output

localhost ~ # speaker-test -D hw:1,0 -c 2                                                                                                                                                                                                                                                  

speaker-test 1.1.6

Playback device is hw:1,0
Stream parameters are 48000Hz, S16_LE, 2 channels                                                                                                                                                                                                                                          
Using 16 octaves of pink noise                                                                                                                                                                                                                                                             
Rate set to 48000Hz (requested 48000Hz)                                                                                                                                                                                                                                                    
Buffer size range from 96 to 16368                                                                                                                                                                                                                                                         
Period size range from 48 to 4080                                                                                                                                                                                                                                                          
Using max buffer size 16368                                                                                                                                                                                                                                                                
Periods = 4                                                                                                                                                                                                                                                                                
was set period_size = 3312
was set buffer_size = 16368                                                                                                                                                                                                                                                                
 0 - Front Left                                                                                                                                                                                                                                                                            
Write error: -5,Input/output error                                                                                                                                                                                                                                                         
xrun_recovery failed: -5,Input/output error
Transfer failed: Input/output error

Relevant dmesg logs

[   51.864104] sof-audio-acpi 808622A8:00: pcm: open stream 0 dir 0
[   51.864110] sof-audio-acpi 808622A8:00: period min 192 max 16384 bytes
[   51.864113] sof-audio-acpi 808622A8:00: period count 2 max 16
[   51.864116] sof-audio-acpi 808622A8:00: buffer max 65536 bytes
[   51.864511] sof-audio-acpi 808622A8:00: rate_min: 48000 rate_max: 48000
[   51.864515] sof-audio-acpi 808622A8:00: channels_min: 2 channels_max: 2
[   51.866616] sof-audio-acpi 808622A8:00: rate_min: 48000 rate_max: 48000
[   51.866634] sof-audio-acpi 808622A8:00: channels_min: 2 channels_max: 2
[   51.866965] sof-audio-acpi 808622A8:00: rate_min: 48000 rate_max: 48000
[   51.866969] sof-audio-acpi 808622A8:00: channels_min: 2 channels_max: 2
[   51.866984] sof-audio-acpi 808622A8:00: pcm: hw params stream 0 dir 0
[   51.866992] sof-audio-acpi 808622A8:00: generating page table for 00000000ab5ef320 size 0xffc0 pages 16
[   51.866998] sof-audio-acpi 808622A8:00: stream_tag 0
[   51.867012] sof-audio-acpi 808622A8:00: ipc tx: 0x60010000
[   51.867824] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60010000
[   51.867850] sof-audio-acpi 808622A8:00: pcm: stream dir 0, posn mailbox offset is 1329664
[   51.871161] sof-audio-acpi 808622A8:00: pcm: trigger stream 0 dir 0 cmd 1
[   51.871172] sof-audio-acpi 808622A8:00: ipc tx: 0x60040000
[   51.871357] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60040000
[   52.375426] sof-audio-acpi 808622A8:00: PCM: stream 0 dir 0 DMA position 0 DAI position 0
[   52.879599] sof-audio-acpi 808622A8:00: pcm: trigger stream 0 dir 0 cmd 0
[   52.879625] sof-audio-acpi 808622A8:00: ipc tx: 0x60050000
[   52.880581] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60050000
[   52.880608] sof-audio-acpi 808622A8:00: ipc tx: 0x60030000
[   52.880854] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60030000
[   52.881092] sof-audio-acpi 808622A8:00: pcm: free stream 0 dir 0
[   52.881589] sof-audio-acpi 808622A8:00: pcm: close stream 0 dir 0

[cujomalainey]

Possibly interesting line that might be causing the DMA to crash, does it really have 65k channels?

    0      2          DMA         192612458.802083        18.229166 src/drivers/dw/dma.c:187    dw_dma_channel_get(): dma 2 request channel 65535

[paulstelian97]

Looks like some sort of weird issue, like casting -1 to a uint16_t? I noticed the pattern of using negative channel numbers in dma_get() as called from host. Can you show a few lines before that interesting one?

Relevant code, from src/audio/host.c (function host_params):

dev->params.stream_tag -= 1;
/* get DMA channel from DMAC
 * note: stream_tag is ignored by dw-dma
 */
hd->chan = dma_channel_get(hd->dma, dev->params.stream_tag);
if (!hd->chan) {
        trace_host_error_with_ids(dev, "host_params() error: "
                                  "hd->chan is NULL");
        return -ENODEV;
}

If it's the call from dai.c though there must be a bug (platform data being wrong or not used correctly). But that should cause a permanent, not occasional issue.

[paulstelian97]

Found the relevant code for the real issue (line numbers are wrong), the channel stop seems to fail waiting for FIFOs to be empty (function dw_dma_stop, only with CONFIG_DMA_SUSPEND_DRAIN -- which is enabled on CHT and BYT).

Someone who's actually working on that platform?

[tlauda]

Please try to increase the timeout. It might be that ocassionally FIFO is not emptied on time. Disabling the channel with FIFO not empty is causing DMA hang and that's why you cannot restart it.

[cujomalainey]

Doubling the DMA timeout (for baytrail) did not change the behaviour. It seems to consistently fail on master but on 005-cml-drop it flakes and I was able to get audio working a couple times

[cujomalainey]

@paulstelian97 yes I noticed this morning I forgot to update the ldc between builds which caused incorrect line numbers

[cujomalainey]

changing all the cherrytrail only dmac configs in src/platform/baytrail/lib/dma.c to #if 0 allows cherrytrail to work. I am going to look closer at the last controllers config

[lgirdwood]

@cujomalainey that's a good find and interesting, these values are internal DMAC channel priority configurations. They are intended to allow the DMAC to give bandwidth and FIFO priority to some channels over other ones. We do not use these currently in SOF so it should be safe to comment on CHT platform.

[cujomalainey]

Continuing DMA failure discussion from #1862

@lgirdwood I logged the SSP state post start and pre stop

    0      1          SSP          21673968.750000  21673968.000000 intel/baytrail/ssp.c:590    SSITR: 0
    0      1          SSP          21673976.770833         8.020833 intel/baytrail/ssp.c:591    SSDR: 0
    0      1          SSP          21673984.791667         8.020833 intel/baytrail/ssp.c:592    SSTO: 0
    0      1          SSP          21673992.812500         8.020833 intel/baytrail/ssp.c:593    SSTSS: 0
    0      1          SSP          21674000.833333         8.020833 intel/baytrail/ssp.c:594    SFIFOL: 30000
    0      1          SSP         321949477.447917 300275488.000000 intel/baytrail/ssp.c:551    ssp_start(): post-write dump
    0      1          SSP         321949484.270833         6.822917 intel/baytrail/ssp.c:552    SSCR0: c009bf
    0      1          SSP         321949492.291667         8.020833 intel/baytrail/ssp.c:553    SSCR1: 1200cc0
    0      1          SSP         321949500.312500         8.020833 intel/baytrail/ssp.c:554    SSCR2: 801
    0      1          SSP         321949508.385417         8.072917 intel/baytrail/ssp.c:555    SSCR3: 30607
    0      1          SSP         321949516.510417         8.125000 intel/baytrail/ssp.c:556    SSCR4: 1400
    0      1          SSP         321949524.531250         8.020833 intel/baytrail/ssp.c:557    SSCR5: 26
    0      1          SSP         321949532.552083         8.020833 intel/baytrail/ssp.c:558    SSPSP: 14008c
    0      1          SSP         321949540.625000         8.072917 intel/baytrail/ssp.c:559    SFIFOTT: 30003
    0      1          SSP         321949548.645833         8.020833 intel/baytrail/ssp.c:560    SSTSA: 3
    0      1          SSP         321949556.770833         8.125000 intel/baytrail/ssp.c:561    SSRSA: 3
    0      1          SSP         321949564.895833         8.125000 intel/baytrail/ssp.c:562    SSSR: f024
    0      1          SSP         321949572.916667         8.020833 intel/baytrail/ssp.c:563    SSITR: 0
    0      1          SSP         321949580.937500         8.020833 intel/baytrail/ssp.c:564    SSDR: 0
    0      1          SSP         321949588.958333         8.020833 intel/baytrail/ssp.c:565    SSTO: 0
    0      1          SSP         321949596.979167         8.020833 intel/baytrail/ssp.c:566    SSTSS: 0
    0      1          SSP         321949605.000000         8.020833 intel/baytrail/ssp.c:567    SFIFOL: 1f0000
    0      1          SSP          21320256.666667              nan intel/baytrail/ssp.c:557    SSCR5: 26
    0      1          SSP          21320264.687500         8.020833 intel/baytrail/ssp.c:558    SSPSP: 14008c
    0      1          SSP          21320272.916667         8.229167 intel/baytrail/ssp.c:559    SFIFOTT: 30003
    0      1          SSP          21320281.197917         8.281250 intel/baytrail/ssp.c:560    SSTSA: 3
    0      1          SSP          21320289.427083         8.229167 intel/baytrail/ssp.c:561    SSRSA: 3
    0      1          SSP          21320297.708333         8.281250 intel/baytrail/ssp.c:562    SSSR: 20f034
    0      1          SSP          21320305.989583         8.281250 intel/baytrail/ssp.c:563    SSITR: 0
    0      1          SSP          21320314.218750         8.229167 intel/baytrail/ssp.c:564    SSDR: 0
    0      1          SSP          21320322.500000         8.281250 intel/baytrail/ssp.c:565    SSTO: 0
    0      1          SSP          21320330.729167         8.229167 intel/baytrail/ssp.c:566    SSTSS: 80000001
    0      1          SSP          21320339.010417         8.281250 intel/baytrail/ssp.c:567    SFIFOL: 0
    0      1          SSP          21673873.697917    353534.687500 intel/baytrail/ssp.c:578    ssp_stop(): pre-write dump
    0      1          SSP          21673880.520833         6.822917 intel/baytrail/ssp.c:579    SSCR0: c009bf
    0      1          SSP          21673888.541667         8.020833 intel/baytrail/ssp.c:580    SSCR1: 1100cc0
    0      1          SSP          21673896.562500         8.020833 intel/baytrail/ssp.c:581    SSCR2: 801
    0      1          SSP          21673904.583333         8.020833 intel/baytrail/ssp.c:582    SSCR3: 30607
    0      1          SSP          21673912.604167         8.020833 intel/baytrail/ssp.c:583    SSCR4: 1400
    0      1          SSP          21673920.625000         8.020833 intel/baytrail/ssp.c:584    SSCR5: 26
    0      1          SSP          21673928.645833         8.020833 intel/baytrail/ssp.c:585    SSPSP: 14008c
    0      1          SSP          21673936.666667         8.020833 intel/baytrail/ssp.c:586    SFIFOTT: 30003
    0      1          SSP          21673944.687500         8.020833 intel/baytrail/ssp.c:587    SSTSA: 3
    0      1          SSP          21673952.708333         8.020833 intel/baytrail/ssp.c:588    SSRSA: 3

See attached for full dump of initial states from set config
bad_after_set_config.txt
good_after_set_config.txt
good_before_set_config.txt
bad_before_set_config.txt

I tried writing the default back to SSSR before set_config with no change in behaviour. I am trying to understand how to determine the DMA alignment from the doc to see if that is the issue. The document is a bit daunting so if can give me some pointers that would be great.