<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=ISO-8859-1">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi all,<br>
<br>
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)<br>
<br>
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.<br>
<br>
The logs always start like:<br>
<br>
main debug: using audio output module "alsa"<br>
main debug: output 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes<br>
main debug: mixer 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes<br>
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: conversion pipeline completed<br>
main debug: looking for audio mixer module: 2 candidates<br>
main debug: using audio mixer module "float32_mixer"<br>
main debug: input 'mpga' 44100 Hz Stereo frame=1152 samples/1053
bytes<br>
main debug: looking for audio filter module: 1 candidate<br>
scaletempo debug: format: 44100 rate, 2 nch, 4 bps, fl32<br>
scaletempo debug: params: 30 stride, 0.200 overlap, 14 search<br>
scaletempo debug: 1.000 scale, 1323.000 stride_in, 1323 stride_out,
1059 standing, 264 overlap, 617 search, 2204 queue, fl32 mode<br>
main debug: using audio filter module "scaletempo"<br>
main debug: filter(s) 'mpga'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: looking for audio filter module: 13 candidates<br>
mpgatofixed32 debug: mpga->f32l, bits per sample: 32<br>
main debug: using audio filter module "mpgatofixed32"<br>
main debug: conversion pipeline completed<br>
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: conversion pipeline completed<br>
main debug: filter(s) 'f32l'->'f32l' 48510 Hz->44100 Hz
Stereo->Stereo<br>
main debug: looking for audio filter module: 13 candidates<br>
main debug: using audio filter module "samplerate"<br>
main debug: conversion pipeline completed<br>
main debug: End of audio preroll<br>
main debug: Decoder buffering done in 58 ms<br>
main warning: PTS is out of range (-9911), dropping buffer<br>
main debug: connection succeeded (socket = 25)<br>
main warning: PTS is out of range (-36003), dropping buffer<br>
mpgatofixed32 debug: libmad error: bad main_data_begin pointer<br>
alsa debug: prepending 2595 zeroes<br>
<br>
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):<br>
<br>
main warning: buffer way too late (241422), dropping buffer<br>
main warning: buffer way too late (231422), dropping buffer<br>
main warning: buffer way too late (221422), dropping buffer<br>
[...]<br>
main warning: buffer way too late (183422), dropping buffer<br>
<br>
Then usually around the 180000us mark we get:<br>
<br>
main warning: not synchronized (211280 us), resampling<br>
<br>
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:<br>
<meta name="qrichtext" content="1">
<br>
main warning: buffer way too late (800000), dropping buffer<br>
<br>
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.<br>
<br>
Given this interesting pattern, I tried commenting out the following
lines from audio_output/dec.c:<br>
<br>
msg_Warn (aout, "not synchronized (%"PRId64" us), resampling",<br>
delta);<br>
/*<br>
if (date_Get (&owner->sync.date) != VLC_TS_INVALID)<br>
date_Move (&owner->sync.date, delta);<br>
*/<br>
<br>
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):<br>
<br>
<meta name="qrichtext" content="1">
<p style="margin: 0px; text-indent: 0px;"><!--StartFragment--><span
style=" font-style:italic; color:#00008b;"></span>main debug:
using audio output module "alsa"<br>
main debug: output 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes<br>
main debug: mixer 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes<br>
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: conversion pipeline completed<br>
main debug: looking for audio mixer module: 2 candidates<br>
main debug: using audio mixer module "float32_mixer"<br>
main debug: input 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes<br>
main debug: looking for audio filter module: 1 candidate<br>
scaletempo debug: format: 44100 rate, 2 nch, 4 bps, fl32<br>
scaletempo debug: params: 30 stride, 0.200 overlap, 14 search<br>
scaletempo debug: 1.000 scale, 1323.000 stride_in, 1323
stride_out, 1059 standing, 264 overlap, 617 search, 2204 queue,
fl32 mode<br>
main debug: using audio filter module "scaletempo"<br>
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: conversion pipeline completed<br>
main debug: filter(s) 'f32l'->'f32l' 44100 Hz->44100 Hz
Stereo->Stereo<br>
main debug: conversion pipeline completed<br>
main debug: filter(s) 'f32l'->'f32l' 48510 Hz->44100 Hz
Stereo->Stereo<br>
main debug: looking for audio filter module: 13 candidates<br>
main debug: using audio filter module "samplerate"<br>
main debug: conversion pipeline completed<br>
main debug: End of audio preroll<br>
main debug: Decoder buffering done in 59 ms<br>
main warning: PTS is out of range (-9945), dropping buffer<br>
main warning: PTS is out of range (-22964), dropping buffer<br>
alsa debug: prepending 1907 zeroes<br>
main warning: not synchronized (61098 us), resampling<br>
ain warning: not synchronized (64260 us), resampling<br>
ain warning: not synchronized (67611 us), resampling<br>
main warning: not synchronized (183677 us), resampling<br>
main warning: not synchronized (187172 us), resampling<br>
main warning: not synchronized (190645 us), resampling<br>
main warning: not synchronized (194059 us), resampling<br>
main warning: not synchronized (196036 us), resampling<br>
main warning: not synchronized (196662 us), resampling<br>
main warning: not synchronized (197228 us), resampling<br>
main warning: not synchronized (197532 us), resampling<br>
main warning: not synchronized (197708 us), resampling<br>
main warning: not synchronized (198294 us), resampling<br>
main warning: not synchronized (198698 us), resampling<br>
main warning: not synchronized (199445 us), resampling<br>
main warning: not synchronized (199739 us), resampling<br>
main warning: not synchronized (200347 us), resampling<br>
main warning: not synchronized (200979 us), resampling<br>
main warning: not synchronized (201878 us), resampling<br>
main warning: not synchronized (202175 us), resampling<br>
main warning: not synchronized (202346 us), resampling<br>
main warning: not synchronized (202493 us), resampling<br>
main warning: not synchronized (202635 us), resampling<br>
main warning: not synchronized (202771 us), resampling<br>
main warning: not synchronized (202910 us), resampling<br>
main warning: not synchronized (203048 us), resampling<br>
main warning: not synchronized (203607 us), resampling<br>
main warning: not synchronized (205027 us), resampling<br>
main warning: not synchronized (208160 us), resampling<br>
main warning: not synchronized (210026 us), resampling<br>
main warning: not synchronized (213178 us), resampling<br>
main warning: not synchronized (214418 us), resampling<br>
main warning: not synchronized (215399 us), resampling<br>
main warning: not synchronized (215672 us), resampling<br>
main warning: not synchronized (215841 us), resampling<br>
main warning: not synchronized (216328 us), resampling<br>
main warning: not synchronized (216834 us), resampling<br>
main warning: not synchronized (217403 us), resampling<br>
main warning: not synchronized (217690 us), resampling<br>
main warning: not synchronized (498748 us), resampling<br>
main warning: not synchronized (499545 us), resampling<br>
main warning: not synchronized (500146 us), resampling<br>
main warning: not synchronized (502174 us), resampling<br>
main warning: not synchronized (505615 us), resampling<br>
main warning: not synchronized (508969 us), resampling<br>
main warning: not synchronized (512430 us), resampling<br>
main warning: not synchronized (515865 us), resampling<br>
main warning: not synchronized (519225 us), resampling<br>
main warning: not synchronized (522652 us), resampling<br>
main warning: not synchronized (526015 us), resampling<br>
main warning: not synchronized (529395 us), resampling<br>
main warning: not synchronized (532783 us), resampling<br>
main warning: not synchronized (536231 us), resampling<br>
main warning: not synchronized (539577 us), resampling<br>
main warning: not synchronized (543000 us), resampling<br>
main warning: not synchronized (801958 us), resampling<br>
main warning: not synchronized (803811 us), resampling<br>
main warning: not synchronized (804392 us), resampling<br>
main warning: not synchronized (805030 us), resampling<br>
main warning: not synchronized (805614 us), resampling<br>
main warning: not synchronized (806129 us), resampling<br>
main warning: not synchronized (806626 us), resampling<br>
main warning: not synchronized (807146 us), resampling<br>
main warning: not synchronized (807759 us), resampling<br>
main warning: not synchronized (809838 us), resampling<br>
main warning: not synchronized (813177 us), resampling<br>
main warning: not synchronized (816525 us), resampling<br>
main warning: not synchronized (820005 us), resampling<br>
main warning: not synchronized (823345 us), resampling<br>
main warning: not synchronized (826781 us), resampling<br>
main warning: not synchronized (830141 us), resampling<br>
main warning: not synchronized (833619 us), resampling<br>
main warning: not synchronized (836994 us), resampling<br>
main warning: not synchronized (840417 us), resampling<br>
main warning: not synchronized (843719 us), resampling<br>
main warning: not synchronized (847049 us), resampling<br>
main warning: not synchronized (850349 us), resampling<br>
main warning: not synchronized (1147942 us), resampling<br>
main warning: not synchronized (1149015 us), resampling<br>
main warning: not synchronized (1149574 us), resampling<br>
main warning: not synchronized (1149765 us), resampling<br>
main warning: not synchronized (1150143 us), resampling<br>
main warning: not synchronized (1150338 us), resampling<br>
main warning: not synchronized (1150490 us), resampling<br>
main warning: not synchronized (1151067 us), resampling<br>
main warning: not synchronized (1151611 us), resampling<br>
main warning: not synchronized (1151808 us), resampling<br>
main warning: not synchronized (1151966 us), resampling<br>
main warning: not synchronized (1152926 us), resampling<br>
main warning: not synchronized (1154000 us), resampling<br>
main warning: not synchronized (1155599 us), resampling<br>
main warning: not synchronized (1156884 us), resampling<br>
main warning: not synchronized (1158148 us), resampling<br>
main warning: not synchronized (1159377 us), resampling<br>
main warning: not synchronized (1160614 us), resampling<br>
main warning: not synchronized (1161643 us), resampling<br>
main warning: not synchronized (1161938 us), resampling<br>
main warning: not synchronized (1162176 us), resampling<br>
main warning: not synchronized (1162470 us), resampling<br>
main warning: not synchronized (1162759 us), resampling<br>
main warning: not synchronized (1162964 us), resampling<br>
main warning: not synchronized (1163237 us), resampling<br>
main warning: not synchronized (1163444 us), resampling<br>
main warning: not synchronized (1163712 us), resampling<br>
main warning: not synchronized (1163995 us), resampling<br>
main warning: not synchronized (1164833 us), resampling<br>
main warning: not synchronized (1457707 us), resampling<br>
main warning: not synchronized (1458944 us), resampling<br>
main warning: not synchronized (1459916 us), resampling<br>
main warning: not synchronized (1460839 us), resampling<br>
main warning: not synchronized (1461763 us), resampling<br>
main warning: not synchronized (1464842 us), resampling<br>
main warning: not synchronized (1466073 us), resampling<br>
main warning: not synchronized (1469168 us), resampling<br>
main warning: not synchronized (1470387 us), resampling<br>
main warning: not synchronized (1470494 us), resampling<br>
main warning: not synchronized (1470501 us), resampling<br>
main warning: not synchronized (1470496 us), resampling<br>
main warning: not synchronized (1470498 us), resampling<br>
main warning: not synchronized (1470496 us), resampling<br>
main warning: not synchronized (1470487 us), resampling<br>
main warning: not synchronized (1470487 us), resampling<br>
main warning: not synchronized (1470496 us), resampling<br>
</p>
<p style="margin: 0px; text-indent: 0px;"><br>
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.<br>
</p>
<p style="margin: 0px; text-indent: 0px;"><br>
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?<br>
</p>
<p style="margin: 0px; text-indent: 0px;"><br>
Chris<br>
</p>
<span style=" color:#000000;"></span><!--EndFragment-->
<meta http-equiv="Content-Type" content="text/html;
charset=ISO-8859-1">
<style type="text/css">
p, li { white-space: pre-wrap; }
</style>
</body>
</html>