http://bugs.winehq.org/show_bug.cgi?id=28723
--- Comment #60 from Alexey Loukianov mooroon2@mail.ru 2011-11-30 08:00:35 CST --- Found another gotcha for GetPosition implementation from latest patchset. Suppose an APP had finished pumping out data and waiting some time for audio engine to finish actual playback. Here is what happens with proposed Wine GetPosition implementation:
... Event loop finished, waiting 20.0ms for playback to finish... T: 2005.3ms S: 87318f P: 0f DP: 86881 dDP: 437 dDPNZ: 437 T: 2006.4ms S: 87318f P: 0f DP: 86930 dDP: 388 dDPNZ: 388 T: 2007.6ms S: 87318f P: 0f DP: 86983 dDP: 335 dDPNZ: 335 T: 2008.7ms S: 87318f P: 0f DP: 87033 dDP: 285 dDPNZ: 285 T: 2009.8ms S: 87318f P: 0f DP: 87081 dDP: 237 dDPNZ: 237 T: 2010.9ms S: 87318f P: 0f DP: 87130 dDP: 188 dDPNZ: 188 T: 2012.1ms S: 87318f P: 0f DP: 87180 dDP: 138 dDPNZ: 138 T: 2013.2ms S: 87318f P: 0f DP: 87228 dDP: 90 dDPNZ: 90 T: 2014.3ms S: 87318f P: 0f DP: 87278 dDP: 40 dDPNZ: 40 WARNING: devpos backwards jump, prev = 87278, cur = 85963 T: 2015.4ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2016.6ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2017.7ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2018.8ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2019.9ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2021.1ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2022.2ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2023.3ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2024.5ms S: 87318f P: 0f DP: 85963 dDP:1355 dDPNZ:1355 T: 2025.8ms S: 87318f P: 0f DP: 87318 dDP: 0 dDPNZ:1355
We can see device position (DP) returned by IAudioClock_GetPosition() to steadily increase towards the value of samples_sent (S). Then we hit expected xrun and devpos experiences immediate backwards jump. The cause can be easily guessed from WINEDEBUG logs:
... 0025:trace:alsa:AudioClock_GetPosition written_frames: 0x1535d, held_frames: 0, delay_frames: 88, avail_frames: 1186, pad_frames: 137 0025:trace:alsa:AudioClock_GetPosition written_frames: 0x1535d, held_frames: 0, delay_frames: 38, avail_frames: 1235, pad_frames: 88 0025:warn:alsa:AudioClock_GetPosition snd_pcm_delay failed: -32 (Обрыв канала) 0025:trace:alsa:AudioClock_GetPosition written_frames: 0x1535d, held_frames: 0, delay_frames: 0, avail_frames: -32, pad_frames: 1355 0028:warn:alsa:alsa_write_data snd_pcm_delay failed: -32 (Обрыв канала) 0025:trace:alsa:AudioClock_GetPosition written_frames: 0x1535d, held_frames: 0, delay_frames: 0, avail_frames: 1323, pad_frames: 0 0025:trace:alsa:AudioClock_GetPosition written_frames: 0x1535d, held_frames: 0, delay_frames: 0, avail_frames: 1323, pad_frames: 0 ...
It's obvious that when we get avail_frames == -32 it doesn't mean that pad_frames = 1355. To fix it we should add check for XRUN state to the GetPosition right after the "avail_frames = snd_pcm_avail_update(This->pcm_handle);" line:
+ if(snd_pcm_state(This->pcm_handle) == SND_PCM_STATE_XRUN || + avail_frames > This->alsa_bufsize_frames || + avail_frames < 0){ + TRACE("XRun state detected\n"); + avail_frames = This->alsa_bufsize_frames; + }