Created attachment 61893 [details]
vlc -vvv console output

Also the same on my system. For your information, both VLC 2.0.1 stable package and VLC git 20120520 build show the error. I am using Arch Linux with kernel 3.3.6-1-ARCH and PulseAudio package version 2.0.1. My laptop has the Intel 6 series/C200 series chipset family high definition audio controller and the bug occurs with both the analog and IEC958 S/PDIF outputs.

I'm also getting the same error with pulseaudio 2.0-1. I'm using kernel 3.3.6-1-ARCH.

Audio device: Intel Corporation 82801H (ICH8 Family) HD Audio Controller

Created attachment 63123 [details]
VLC console log

I am also having this problem on debian. I have not noticed a delay but it causes my audio to crackle which is very annoying.

Versions:

VLC media player 2.0.1 Twoflower (revision 2.0.1-0-gf432547)
VLC version 2.0.1 Twoflower (2.0.1-0-gf432547)
Compiled by pbuilder on www.marillat.net (May 29 2012 16:35:24)
Compiler: gcc version 4.7.0 (Debian 4.7.0-10)

pulseaudio 2.0

Here is where someone posted the bug to vlc's bug tracker: https://trac.videolan.org/vlc/ticket/6853. It has been marked as notvlc so I presume this is a pulseaudio issue.

I've attached my vlc log.

It seems the problem is intermittent and present at the start for me. For example at the start I see this and eventually it gets to 44100hz.

[0xe7f978] pulse audio output warning: too late by 63581 us
[0xe7f978] pulse audio output debug: changed sample rate to 44343 Hz
[0xe7f978] pulse audio output warning: too late by 63074 us
[0xe7f978] pulse audio output debug: changed sample rate to 44381 Hz
[0xe7f978] pulse audio output warning: too late by 62122 us
[0xe7f978] pulse audio output debug: changed sample rate to 44413 Hz
[0xe7f978] pulse audio output warning: too late by 60691 us
[0xe7f978] pulse audio output debug: changed sample rate to 44439 Hz
[0xe7f978] pulse audio output debug: changed sample rate to 44353 Hz
[0xe7f978] pulse audio output debug: changed sample rate to 44267 Hz
[0xe7f978] pulse audio output debug: changed sample rate to 44181 Hz
[0xe7f978] pulse audio output debug: changed sample rate to 44100 Hz

While the too late by x ms is happening other sounds in my system distort or crackle. Will test further on request.

Opening /etc/pulse/default.pa and disabling timerbased scheduling by replacing 
load-module module-udev-detect 
with 
load-module module-udev-detect tsched=0
solves the problem here after a reboot.

Same here.  Really annoying for VLC user.

I'm not familar with pa so I cannot say whether this patch is has something wrong or not.  !!!!!!!But this commit broken the userspace!!!!!!!   Should it be reverted?

It's 7 month after this bug has been reported.  Should the developer say something to show that this bug is not totally ignored?

(In reply to comment #7)
> Same here.  Really annoying for VLC user.
> 
> I'm not familar with pa so I cannot say whether this patch is has something
> wrong or not.  !!!!!!!But this commit broken the userspace!!!!!!!   Should
> it be reverted?
> 
> It's 7 month after this bug has been reported.  Should the developer say
> something to show that this bug is not totally ignored?

Sure, I can say something. The problematic commit implements a useful feature, so it probably won't be simply reverted. A better fix is needed (patches very welcome). There have been fixes related to the sample rate updating since pulseaudio 2.0, so it's worth retrying with pulseaudio 3.0, but I don't remember that those fixes would have been timing related, so don't expect too much.

(In reply to comment #8)
> (In reply to comment #7)
> > Same here.  Really annoying for VLC user.
> > 
> > I'm not familar with pa so I cannot say whether this patch is has something
> > wrong or not.  !!!!!!!But this commit broken the userspace!!!!!!!   Should
> > it be reverted?
> > 
> > It's 7 month after this bug has been reported.  Should the developer say
> > something to show that this bug is not totally ignored?
> 
> Sure, I can say something. The problematic commit implements a useful
> feature, so it probably won't be simply reverted. A better fix is needed
> (patches very welcome). There have been fixes related to the sample rate
> updating since pulseaudio 2.0, so it's worth retrying with pulseaudio 3.0,
> but I don't remember that those fixes would have been timing related, so
> don't expect too much.

Thinking a bit more, reverting the patch (or maybe commenting out the code would be better) is maybe the right approach after all, if nobody submits a better fix. Removing the code that was added that patch shouldn't really break anything, the only effect should be that there's sometimes unnecessary resampling, which is better than breaking the timing of applications.

Before removing any functionality, this must be reproducible by a pulseaudio developer, though. Otherwise there's no way to know when it's safe to add the functionality back. I can't reproduce this with vlc version 2.0.3 and pulseaudio's current development version. I'll try installing vlc 2.0.1 and pulseaudio 2.0 later today.

This affects all VLC versions (however please avoid VLC version 2.0.4, which has an audio latency bug of its own), with PulseAudio 2.x.

Any further hints for reproducing? I have pulseaudio 2.0 installed, and since vlc version shouldn't matter, I still have vlc 2.0.3, not 2.0.1 that the original reporter used. A/V sync is just fine for me, with both pulseaudio and alsa (through pulseaudio) backends of vlc.

For me, the bug strikes when all of the following conditions are met:
- The sink (Intel HDA) is inactive.
- The new sink input is created with the _same_ sample rate as the last sink input that was previous connected to the sink.
- Alternate rate is enabled (44100 and 48000).
Correlation/Reproducibility is 100%.

Then there is approximately 2 seconds delay between VLC "trigger"ing its sink input and PulseAudio actually starting playback. (Note that VLC uses manual trigger.)

The bug does NOT strike when alternating sample rate.
The bug does NOT strike when alternate rate are disabled in the configuration.
That is very confusing.

I was now able to reproduce this. For me this doesn't seem to happen 100% of the time (I test by running "vlc ~/misc/sync_test.mp4", observing the A/V sync, closing vlc, waiting for the sink to suspend, and trying again). The small hardware buffer size that I have (371 ms) might make noticing the delay harder, if the delay is variable, but if it's always one full hw buffer size in length, then I should be able to reliably notice it... I'll build a custom kernel next with a bigger audio buffer, and see if that changes anything.

Btw, Remi, you said that "this affects all VLC versions [...] with PulseAudio 2.x." Do you mean that this doesn't affect 3.0?

Did not try PA 3.x, so far not landed in Debian unstable.

With bigger hw buffer I was able to reproduce the problem 100% of time on pulseaudio 2.0. With the current development version I can't reproduce the problem. Thus, resolving the bug as fixed.