VLC 2.0.1 drops packets during MP3 decoding

[GregoryPOIRIER]

Hi,

I just migrate from VLC 1.0.5 to VLC 2.0.2 and I am not able to read mp3 anymore (same issues on videos). I have extracted the message and it seems that a module is responding too slowly=> VLC trashes some data packets. Any idea?

Best regards,

Gregory

main debug: processing request item: 05 Auf Achse, node: Liste de lecture, skip: 0
main debug: resyncing on 05 Auf Achse
main debug: 05 Auf Achse is at 0
main debug: starting playback of the new playlist item
main debug: creating new input thread
main debug: Creating an input for '05 Auf Achse'
main debug: using timeshift granularity of 50 MiB, in path 'C:\DOCUME~1\gpoirier\LOCALS~1\Temp'
main debug: `file:///D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3' gives access `file' demux `' path `/D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3'
main debug: creating demux: access='file' demux='' location='/D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3' file='D:\private\mp3\Franz Ferdinand - Franz Ferdinand\05 Auf Achse.mp3'
main debug: looking for access_demux module: 3 candidates
main debug: no access_demux module matching "file" could be loaded
main debug: TIMER module_need() : 0.649 ms - Total 0.649 ms / 1 intvls (Avg 0.649 ms)
main debug: creating access 'file' location='/D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3', path='D:\private\mp3\Franz Ferdinand - Franz Ferdinand\05 Auf Achse.mp3'
main debug: looking for access module: 3 candidates
filesystem debug: opening file `D:\private\mp3\Franz Ferdinand - Franz Ferdinand\05 Auf Achse.mp3'
main debug: using access module "filesystem"
main debug: TIMER module_need() : 0.447 ms - Total 0.447 ms / 1 intvls (Avg 0.447 ms)
main debug: Using stream method for AStream*
main debug: starting pre-buffering
main debug: received first data after 0 ms
main debug: pre-buffering done 1024 bytes in 0s - 13157 KiB/s
main debug: looking for stream_filter module: 4 candidates
main debug: no stream_filter module matching "any" could be loaded
main debug: TIMER module_need() : 1.234 ms - Total 1.234 ms / 1 intvls (Avg 1.234 ms)
main debug: looking for stream_filter module: 1 candidate
main debug: using stream_filter module "stream_filter_record"
main debug: TIMER module_need() : 0.246 ms - Total 0.246 ms / 1 intvls (Avg 0.246 ms)
main debug: creating demux: access='file' demux='' location='/D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3' file='D:\private\mp3\Franz Ferdinand - Franz Ferdinand\05 Auf Achse.mp3'
main debug: ID3v2.4 revision 0 tag found, skipping 2103 bytes
main debug: looking for demux module: 55 candidates
es debug: detected format mpga
main debug: looking for packetizer module: 21 candidates
main debug: using packetizer module "mpeg_audio"
main debug: TIMER module_need() : 0.237 ms - Total 0.237 ms / 1 intvls (Avg 0.237 ms)
mpeg_audio debug: MPGA channels:2 samplerate:44100 bitrate:192
main debug: selecting program id=0
qt4 debug: IM: Setting an input
main debug: using demux module "es"
main debug: TIMER module_need() : 1.972 ms - Total 1.972 ms / 1 intvls (Avg 1.972 ms)
main debug: looking for a subtitle file in D:\private\mp3\Franz Ferdinand - Franz Ferdinand
main debug: looking for decoder module: 31 candidates
main debug: using decoder module "mpeg_audio"
main debug: TIMER module_need() : 0.830 ms - Total 0.830 ms / 1 intvls (Avg 0.830 ms)
main debug: looking for meta reader module: 2 candidates
main debug: using meta reader module "taglib"
main debug: TIMER module_need() : 1.579 ms - Total 1.579 ms / 1 intvls (Avg 1.579 ms)
main debug: removing module "taglib"
main debug: `file:///D:/private/mp3/Franz%20Ferdinand%20-%20Franz%20Ferdinand/05%20Auf%20Achse.mp3' successfully opened
main debug: Buffering 0%
main debug: Buffering 8%
main debug: Buffering 17%
mpeg_audio debug: MPGA channels:2 samplerate:44100 bitrate:192
main debug: recycling audio output
main debug: Buffering 26%
main debug: Buffering 34%
main debug: Buffering 43%
main debug: Buffering 52%
main debug: looking for audio output module: 2 candidates
aout_directx debug: Opening DirectSound Audio Output
main debug: Buffering 60%
main debug: Buffering 69%
main debug: Buffering 78%
main debug: Buffering 87%
main debug: Buffering 95%
aout_directx debug: found device: Primary Sound Driver
aout_directx debug: found device: SoundMAX HD Audio
aout_directx debug: using device: SoundMAX HD Audio
aout_directx debug: found device: HD Audio digital out
main debug: Stream buffering done (313 ms in 0 ms)
aout_directx debug: device supports 2 channels (DEFAULT!)
aout_directx debug: device supports 1 channel
aout_directx debug: Windows says your SpeakerConfig is stereo
aout_directx debug: creating DirectSoundThread
main debug: using audio output module "aout_directx"
main debug: TIMER module_need() : 30.544 ms - Total 30.544 ms / 1 intvls (Avg 30.544 ms)
aout_directx debug: DirectSoundThread ready
main debug: output 's16l' 44100 Hz Stereo frame=1 samples/4 bytes
main debug: mixer 'f32l' 44100 Hz Stereo frame=1 samples/8 bytes
main debug: filter(s) 'f32l'->'s16l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: looking for audio filter module: 14 candidates
audio_format debug: f32l->s16l, bits per sample: 32->16
main debug: using audio filter module "audio_format"
main debug: TIMER module_need() : 0.332 ms - Total 0.332 ms / 1 intvls (Avg 0.332 ms)
main debug: conversion pipeline completed
main debug: looking for audio mixer module: 2 candidates
main debug: using audio mixer module "float32_mixer"
main debug: TIMER module_need() : 0.229 ms - Total 0.229 ms / 1 intvls (Avg 0.229 ms)
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: TIMER module_need() : 0.377 ms - Total 0.377 ms / 1 intvls (Avg 0.377 ms)
main debug: filter(s) 'mpga'->'f32l' 44100 Hz->44100 Hz Stereo->Stereo
main debug: looking for audio filter module: 14 candidates
mpgatofixed32 debug: mpga->f32l, bits per sample: 32
main debug: using audio filter module "mpgatofixed32"
main debug: TIMER module_need() : 0.297 ms - Total 0.297 ms / 1 intvls (Avg 0.297 ms)
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: 14 candidates
main debug: using audio filter module "samplerate"
main debug: TIMER module_need() : 0.328 ms - Total 0.328 ms / 1 intvls (Avg 0.328 ms)
main debug: conversion pipeline completed
main debug: End of audio preroll
main debug: Decoder buffering done in 27 ms
main warning: PTS is out of range (-9982), dropping buffer
main warning: PTS is out of range (-36067), dropping buffer
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
main debug: audio output is starving (-52442), playing silence
main warning: audio output out of sync, adjusting dates (224966 us)
main warning: not synchronized (224967 us), resampling
main warning: buffer way too late (224513), dropping buffer
main warning: buffer way too late (198390), dropping buffer
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
main warning: buffer too late (172268), up-sampling
main warning: audio output out of sync, adjusting dates (67840 us)
main warning: not synchronized (67842 us), resampling
main warning: buffer way too late (240042), dropping buffer
main warning: buffer way too late (213920), dropping buffer
main warning: buffer way too late (187797), dropping buffer
main warning: audio output out of sync, adjusting dates (-44123 us)
main warning: not synchronized (-44121 us), resampling
main debug: audio output is starving (-157127), playing silence
main warning: audio output out of sync, adjusting dates (188240 us)
main warning: not synchronized (188242 us), resampling
main warning: buffer way too late (305523), dropping buffer
main warning: buffer way too late (279400), dropping buffer
main warning: buffer way too late (253278), dropping buffer
main warning: buffer way too late (227155), dropping buffer
main warning: buffer way too late (201033), dropping buffer
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
main debug: audio output is starving (-114112), playing silence
main debug: audio output is too slow (348512 us): trashing 50000 us
main debug: audio output is too slow (298512 us): trashing 50000 us
main debug: audio output is too slow (248512 us): trashing 50000 us
main debug: audio output is too slow (198512 us): trashing 50000 us
main debug: audio output is too slow (148512 us): trashing 50000 us
main debug: audio output is too slow (98512 us): trashing 50000 us
main debug: audio output is too slow (48512 us): trashing 50000 us
main warning: audio output out of sync, adjusting dates (169070 us)
main warning: not synchronized (169071 us), resampling
main warning: buffer way too late (342826), dropping buffer
main warning: buffer way too late (316703), dropping buffer
main warning: buffer way too late (290581), dropping buffer
main warning: buffer way too late (264459), dropping buffer
main warning: buffer way too late (238336), dropping buffer
main warning: buffer way too late (212214), dropping buffer
main warning: audio output out of sync, adjusting dates (161721 us)
main warning: buffer way too late (186091), dropping buffer
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
main warning: not synchronized (161723 us), resampling
main warning: buffer way too late (321623), dropping buffer
main warning: buffer way too late (295501), dropping buffer
main warning: buffer way too late (269378), dropping buffer
main warning: buffer way too late (243256), dropping buffer
main warning: buffer way too late (217133), dropping buffer
main warning: buffer way too late (191011), dropping buffer
main warning: audio output out of sync, adjusting dates (119947 us)
main warning: not synchronized (119948 us), resampling
main warning: buffer way too late (284791), dropping buffer
main warning: buffer way too late (258669), dropping buffer
main warning: buffer way too late (232546), dropping buffer
main warning: buffer way too late (206424), dropping buffer
main warning: buffer way too late (180301), dropping buffer
main debug: audio output is starving (-79436), playing silence
mpgatofixed32 debug: libmad error: bad main_data_begin pointer
main debug: incoming request - stopping current input
main debug: dying input
main debug: control: stopping input
main debug: dying input
main debug: removing module "mpeg_audio"
main debug: killing decoder fourcc `mpga', 0 PES in FIFO
main debug: removing module "mpgatofixed32"
main debug: removing module "scaletempo"
main debug: removing module "samplerate"
main debug: removing module "aout_directx"
aout_directx debug: closing audio device
aout_directx debug: DirectSoundThread exiting
main debug: removing module "audio_format"
main debug: removing module "float32_mixer"
main debug: releasing audio output
main debug: removing module "es"
main debug: removing module "mpeg_audio"
main debug: removing module "stream_filter_record"
main debug: removing module "filesystem"
main debug: Program doesn't contain anymore ES
main debug: dead input
qt4 debug: IM: Deleting the input
main debug: TIMER input launching for '05 Auf Achse' : 10.287 ms - Total 10.287 ms / 1 intvls (Avg 10.287 ms)

[GregoryPOIRIER]

It's working with version 1.1.9 but not 2.x.x versions

[VLC_help]

What kind of computer you have?

[blistovmhz]

Same issue here.
Q6600@3GHz, 4GB RAM. blah blah blah. Any other player can deal with whatever I throw at it. Upgraded from 1.1.9 to 2.0.1 today and can no longer play any audio smoothly. Same messages in logs as posted by OP.
Sound is stuttering, video playback (with audio) is choppy and drops out of sync.

[ianp0]

Is your CPU overclocked?

[ianp0]

My system was overclocked using the Auto AI feature in BIOS.

I've switched it off and the problem is gone!

[blistovmhz]

Interesting. Yes, was using live OC. I have Auto-AI on the machine I first noticed this issue. Was testing with another machine (which also uses a live OC (I7 cpu)) and had the same issue. Wish I had more time to test this right now as I suspect the solution is not far off and it'll be something simple like the default audio buffer time being precisely as long as it takes some CPU's to switch frequencies, and perhaps 2.0.1 automatically sets CPU affinity to a single core?

[VLC_help]

perhaps 2.0.1 automatically sets CPU affinity to a single core?

Nope. VLC 2.0.x is more multithreaded than earlier versions. And that seems to cause problems with certain setups. But with some users setting affinity to single core helps.