up2: pulseaudio playback fails after suspend/resume

[kv2019i]

PCM playback to headset fails to recover after suspend/resume on UP2 board.

Commands:
sh1> /usr/bin/pulseaudio -vv
sh2> aplay -D default test.wav
sh3> sudo rtcwake -m mem -s 2

Notes:

• without pulseaudio, recovery from suspend/resume works
• @plbossart it seems at least the rewinds fails, this is probably what you referred to in a mail recently

Log:
I: [pulseaudio] protocol-native.c: Final latency 624.99 ms = 250.02 ms + 2124.99 ms + 124.99 ms
D: [alsa-sink-Port5 ()] alsa-sink.c: Latency set to 124.99ms
D: [alsa-sink-Port5 ()] alsa-sink.c: hwbuf_unused=41284
D: [alsa-sink-Port5 ()] alsa-sink.c: setting avail_min=15439
D: [alsa-sink-Port5 ()] alsa-sink.c: Requesting rewind due to latency change.
D: [alsa-sink-Port5 ()] alsa-sink.c: Requested to rewind 65280 bytes.
D: [alsa-sink-Port5 ()] alsa-sink.c: Limited to 44864 bytes.
D: [alsa-sink-Port5 ()] alsa-sink.c: before: 11216
D: [alsa-sink-Port5 ()] alsa-sink.c: after: 11216
D: [alsa-sink-Port5 ()] alsa-sink.c: Rewound 44864 bytes.
D: [alsa-sink-Port5 ()] sink.c: Processing rewind...
D: [alsa-sink-Port5 ()] sink-input.c: Have to rewind 44864 bytes on render memblockq.
D: [alsa-sink-Port5 ()] source.c: Processing rewind...
D: [alsa-sink-Port5 ()] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink-Port5 ()] alsa-sink.c: Requested to rewind 65280 bytes.
D: [alsa-sink-Port5 ()] alsa-sink.c: Limited to 23548 bytes.
D: [alsa-sink-Port5 ()] alsa-sink.c: before: 5887
D: [alsa-sink-Port5 ()] alsa-sink.c: after: 5887
D: [alsa-sink-Port5 ()] alsa-sink.c: Rewound 23548 bytes.
D: [alsa-sink-Port5 ()] sink.c: Processing rewind...
D: [alsa-sink-Port5 ()] sink-input.c: Have to rewind 23548 bytes on render memblockq.
D: [alsa-sink-Port5 ()] source.c: Processing rewind...
I: [alsa-sink-Port5 ()] alsa-sink.c: Scheduling delay of 464.48 ms > 18.38 ms, you might want to investigate this to improve latency...
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is SUSPENDED
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
I: [alsa-sink-Port5 ()] (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_START failed (-77)
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] ratelimit.c: 215 events suppressed
D: [alsa-sink-Port5 ()] alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: PCM state is RUNNING

[plbossart]

@kv2019i PulseAudio rewind issues, sounds like back to the future, huh :-)

[zhuyingjiang]

@kv2019i Could you provide the commit ID of the driver and the firmware? Did you test using PCM512X?

[zhuyingjiang]

I use :
linux: f3adfd6
sof: d7b36bf3e4db4
the result seems is different:
pulse.log
dmesg.log
@kv2019i
Could you confirm if it is the same thing you have got?

[kv2019i]

@zhuyingjiang
Hmm, I tested now with following
sof: cbd3e07
linux: f304b5c

Can you confirm suspend/resume works with your setup? I.e. run "aplay -D hw:0 foo.wav" and "sudo rtcwake -m mem -s 2" without pulseaudio. That should work ok?

The pulse log seems pretty similar -- there's a rewind attempt and then failed start:

A new log I took. Has the same two errors you have also (rewind due to end of underrun) and (Implicit underrun of "ALSA Playback").

I: [alsa-sink-Port5 (*)] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 (*)] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 (*)] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: PCM state is RUNNING
D: [alsa-sink-Port5 (*)] alsa-sink.c: Requested to rewind 47988 bytes.
D: [alsa-sink-Port5 (*)] alsa-sink.c: Mhmm, actually there is nothing to rewind.
I: [alsa-sink-Port5 (*)] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 (*)] alsa-util.c: PCM state is RUNNING
D: [alsa-sink-Port5 (*)] protocol-native.c: Implicit underrun of 'ALSA Playback'
I: [alsa-sink-Port5 (*)] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 (*)] alsa-util.c: Got POLLERR from ALSA

[kv2019i]

@kv2019i Could you provide the commit ID of the driver and the firmware? Did you test using PCM512X?

Commit-ids are above, and yes, as using PCM512X.

[zhuyingjiang]

I have test on Up2 with PCM512x, now some time the PCM playback can recover after suspend/resume. but still will have "underrun", not sure if it is caused by this fix.

I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING
I: [alsa-sink-Port5 ()] alsa-sink.c: Starting playback.
D: [alsa-sink-Port5 ()] alsa-sink.c: hwbuf_unused=0
D: [alsa-sink-Port5 ()] alsa-sink.c: setting avail_min=15487
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLERR from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: Got POLLOUT from ALSA
D: [alsa-sink-Port5 ()] alsa-util.c: PCM state is RUNNING