[vlc-devel] Endless buffer-way-too-late / audio resampling loop

[Chris Smowton]

Hi all,

I built VLC from git head today, and found an odd problem playing any 
kind of audio file: no audio is played, and the debug log shows an 
endless sequence of "buffer way too late" (originating from 
audio_output/input.c) plus an occasional "not synchronized, resampling" 
message (coming from audio_output/dec.c)

This happens for a variety of audio pipelines: I've tried using HTTP and 
file sources to eliminate the access stage, and using Vorbis and MP3 
(filter is called mpgatofixed32) to eliminate a codec bug. I've tried 
using the latest git head and a fairly arbitrary jump back to mid-March 
(git-1499-gd0590ad) to see if it's a recently introduced bug; it seems not.

The logs always start like:

main debug: using audio output module "alsa"
main debug: output 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: mixer 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: conversion pipeline completed
main debug: looking for audio mixer module: 2 candidates
main debug: using audio mixer module "float32_mixer"
main debug: input 'mpga' 44100 Hz Stereo frame=1152 samples/1053 bytes
main debug: looking for audio filter module: 1 candidate
scaletempo debug: format: 44100 rate, 2 nch, 4 bps, fl32
scaletempo debug: params: 30 stride, 0.200 overlap, 14 search
scaletempo debug: 1.000 scale, 1323.000 stride_in, 1323 stride_out, 1059 
standing, 264 overlap, 617 search, 2204 queue, fl32 mode
main debug: using audio filter module "scaletempo"
main debug: filter(s) 'mpga'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: looking for audio filter module: 13 candidates
mpgatofixed32 debug: mpga->f32l, bits per sample: 32
main debug: using audio filter module "mpgatofixed32"
main debug: conversion pipeline completed
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: conversion pipeline completed
main debug: filter(s) 'f32l'->'f32l' 48510 Hz->44100 Hz Stereo->Stereo
main debug: looking for audio filter module: 13 candidates
main debug: using audio filter module "samplerate"
main debug: conversion pipeline completed
main debug: End of audio preroll
main debug: Decoder buffering done in 58 ms
main warning: PTS is out of range (-9911), dropping buffer
main debug: connection succeeded (socket = 25)
main warning: PTS is out of range (-36003), dropping buffer
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
alsa debug: prepending 2595 zeroes

Except tfor the mention of libmad of course. Then once dropping starts, 
we see an interesting pattern in which the 'resampling' events seem to 
make the situation worse (specific numbers made up):

main warning: buffer way too late (241422), dropping buffer
main warning: buffer way too late (231422), dropping buffer
main warning: buffer way too late (221422), dropping buffer
[...]
main warning: buffer way too late (183422), dropping buffer

Then usually around the 180000us mark we get:

main warning: not synchronized (211280 us), resampling

The specific number here doesn't bear any apparent relation to the us 
offsets noted in the way-too-late messages: it's sometimes similar, 
sometimes less, sometimes more. But the interesting thing is that next 
we get:

main warning: buffer way too late (800000), dropping buffer

The sync problem has got worse! This then falls through repeated drops 
until it gets near 180000, then we get another 'not synchronized', 
making it worse again, and so on and so forth.

Given this interesting pattern, I tried commenting out the following 
lines from audio_output/dec.c:

msg_Warn (aout, "not synchronized (%"PRId64" us), resampling",
                   delta);
/*
         if (date_Get (&owner->sync.date) != VLC_TS_INVALID)
             date_Move (&owner->sync.date, delta);
*/

This indeed fixed playback! Now my logs look like this (real numbers 
this time -- I fabricated the ones earlier because I don't have the time 
to rebuild without my hack right now):

main debug: using audio output module "alsa"
main debug: output 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: mixer 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: conversion pipeline completed
main debug: looking for audio mixer module: 2 candidates
main debug: using audio mixer module "float32_mixer"
main debug: input 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: looking for audio filter module: 1 candidate
scaletempo debug: format: 44100 rate, 2 nch, 4 bps, fl32
scaletempo debug: params: 30 stride, 0.200 overlap, 14 search
scaletempo debug: 1.000 scale, 1323.000 stride_in, 1323 stride_out, 1059 
standing, 264 overlap, 617 search, 2204 queue, fl32 mode
main debug: using audio filter module "scaletempo"
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: conversion pipeline completed
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: conversion pipeline completed
main debug: filter(s) 'f32l'->'f32l' 48510 Hz->44100 Hz Stereo->Stereo
main debug: looking for audio filter module: 13 candidates
main debug: using audio filter module "samplerate"
main debug: conversion pipeline completed
main debug: End of audio preroll
main debug: Decoder buffering done in 59 ms
main warning: PTS is out of range (-9945), dropping buffer
main warning: PTS is out of range (-22964), dropping buffer
alsa debug: prepending 1907 zeroes
main warning: not synchronized (61098 us), resampling
ain warning: not synchronized (64260 us), resampling
ain warning: not synchronized (67611 us), resampling
main warning: not synchronized (183677 us), resampling
main warning: not synchronized (187172 us), resampling
main warning: not synchronized (190645 us), resampling
main warning: not synchronized (194059 us), resampling
main warning: not synchronized (196036 us), resampling
main warning: not synchronized (196662 us), resampling
main warning: not synchronized (197228 us), resampling
main warning: not synchronized (197532 us), resampling
main warning: not synchronized (197708 us), resampling
main warning: not synchronized (198294 us), resampling
main warning: not synchronized (198698 us), resampling
main warning: not synchronized (199445 us), resampling
main warning: not synchronized (199739 us), resampling
main warning: not synchronized (200347 us), resampling
main warning: not synchronized (200979 us), resampling
main warning: not synchronized (201878 us), resampling
main warning: not synchronized (202175 us), resampling
main warning: not synchronized (202346 us), resampling
main warning: not synchronized (202493 us), resampling
main warning: not synchronized (202635 us), resampling
main warning: not synchronized (202771 us), resampling
main warning: not synchronized (202910 us), resampling
main warning: not synchronized (203048 us), resampling
main warning: not synchronized (203607 us), resampling
main warning: not synchronized (205027 us), resampling
main warning: not synchronized (208160 us), resampling
main warning: not synchronized (210026 us), resampling
main warning: not synchronized (213178 us), resampling
main warning: not synchronized (214418 us), resampling
main warning: not synchronized (215399 us), resampling
main warning: not synchronized (215672 us), resampling
main warning: not synchronized (215841 us), resampling
main warning: not synchronized (216328 us), resampling
main warning: not synchronized (216834 us), resampling
main warning: not synchronized (217403 us), resampling
main warning: not synchronized (217690 us), resampling
main warning: not synchronized (498748 us), resampling
main warning: not synchronized (499545 us), resampling
main warning: not synchronized (500146 us), resampling
main warning: not synchronized (502174 us), resampling
main warning: not synchronized (505615 us), resampling
main warning: not synchronized (508969 us), resampling
main warning: not synchronized (512430 us), resampling
main warning: not synchronized (515865 us), resampling
main warning: not synchronized (519225 us), resampling
main warning: not synchronized (522652 us), resampling
main warning: not synchronized (526015 us), resampling
main warning: not synchronized (529395 us), resampling
main warning: not synchronized (532783 us), resampling
main warning: not synchronized (536231 us), resampling
main warning: not synchronized (539577 us), resampling
main warning: not synchronized (543000 us), resampling
main warning: not synchronized (801958 us), resampling
main warning: not synchronized (803811 us), resampling
main warning: not synchronized (804392 us), resampling
main warning: not synchronized (805030 us), resampling
main warning: not synchronized (805614 us), resampling
main warning: not synchronized (806129 us), resampling
main warning: not synchronized (806626 us), resampling
main warning: not synchronized (807146 us), resampling
main warning: not synchronized (807759 us), resampling
main warning: not synchronized (809838 us), resampling
main warning: not synchronized (813177 us), resampling
main warning: not synchronized (816525 us), resampling
main warning: not synchronized (820005 us), resampling
main warning: not synchronized (823345 us), resampling
main warning: not synchronized (826781 us), resampling
main warning: not synchronized (830141 us), resampling
main warning: not synchronized (833619 us), resampling
main warning: not synchronized (836994 us), resampling
main warning: not synchronized (840417 us), resampling
main warning: not synchronized (843719 us), resampling
main warning: not synchronized (847049 us), resampling
main warning: not synchronized (850349 us), resampling
main warning: not synchronized (1147942 us), resampling
main warning: not synchronized (1149015 us), resampling
main warning: not synchronized (1149574 us), resampling
main warning: not synchronized (1149765 us), resampling
main warning: not synchronized (1150143 us), resampling
main warning: not synchronized (1150338 us), resampling
main warning: not synchronized (1150490 us), resampling
main warning: not synchronized (1151067 us), resampling
main warning: not synchronized (1151611 us), resampling
main warning: not synchronized (1151808 us), resampling
main warning: not synchronized (1151966 us), resampling
main warning: not synchronized (1152926 us), resampling
main warning: not synchronized (1154000 us), resampling
main warning: not synchronized (1155599 us), resampling
main warning: not synchronized (1156884 us), resampling
main warning: not synchronized (1158148 us), resampling
main warning: not synchronized (1159377 us), resampling
main warning: not synchronized (1160614 us), resampling
main warning: not synchronized (1161643 us), resampling
main warning: not synchronized (1161938 us), resampling
main warning: not synchronized (1162176 us), resampling
main warning: not synchronized (1162470 us), resampling
main warning: not synchronized (1162759 us), resampling
main warning: not synchronized (1162964 us), resampling
main warning: not synchronized (1163237 us), resampling
main warning: not synchronized (1163444 us), resampling
main warning: not synchronized (1163712 us), resampling
main warning: not synchronized (1163995 us), resampling
main warning: not synchronized (1164833 us), resampling
main warning: not synchronized (1457707 us), resampling
main warning: not synchronized (1458944 us), resampling
main warning: not synchronized (1459916 us), resampling
main warning: not synchronized (1460839 us), resampling
main warning: not synchronized (1461763 us), resampling
main warning: not synchronized (1464842 us), resampling
main warning: not synchronized (1466073 us), resampling
main warning: not synchronized (1469168 us), resampling
main warning: not synchronized (1470387 us), resampling
main warning: not synchronized (1470494 us), resampling
main warning: not synchronized (1470501 us), resampling
main warning: not synchronized (1470496 us), resampling
main warning: not synchronized (1470498 us), resampling
main warning: not synchronized (1470496 us), resampling
main warning: not synchronized (1470487 us), resampling
main warning: not synchronized (1470487 us), resampling
main warning: not synchronized (1470496 us), resampling


After this point the complaint messages stay about stable at 1.5s error. 
The stabilisation figure varies for different access methods -- e.g. 
httplive access always stablises at around 0.8s, so I'd guess this 
figure it related to a sum of buffer lengths.


So, after all that, my question is pretty simple: what the heck is going 
on? I'm sure my simple hack has broken something else -- but what 
*should* that timeline tweak in dec.c be doing, and why is it causing 
trouble here?


Chris

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.videolan.org/pipermail/vlc-devel/attachments/20120528/fcd3d6e1/attachment.html>