Transcoding with --start-time and --end-time results in incorrect duration

Hello,

I'm trying to transcode a part of mp4 into webm by using VLC with the following version string

VLC media player 2.2.1 Terry Pratchett (Weatherwax) (revision 2.2.1-0-ga425c42)

on a Debian/sid system using the following command line:

vlc "

{INPUT_FILE}" -vvvvv -I dummy --start-time 15 --stop-time 30 --sout "#transcode{vcodec=VP80,vb=800,scale=1,acodec=vorbis}:standard{dst="

{OUTPUT_FILE}",access=file,mux="ffmpeg{mux=webm}"}" vlc://quit

I expect the resulting output file to contain only 15 seconds of original video, and it does. The duration of the output video is set to some completely wrong value though. Note, how in the metadata dump below the input file has duration of 1 minute 24 seconds, but the output file's duration is reported as 3 hours and 40 minutes (!), even though it actually only contains 15 seconds of video (progress bar in various players shows the bogus duration). What's even more bizarre, if I rerun the same command, the output file actually gets a different (longer) duration every time, it appears that it depends on the current time somehow, which makes no sense at all.

Information about the input file according to mediainfo:

General Complete name : input.mp4 Format : MPEG-4 Format profile : Base Media / Version 2 Codec ID : mp42 File size : 3.66 MiB Duration : 1mn 24s Overall bit rate mode : Variable Overall bit rate : 365 Kbps Encoded date : UTC 2015-04-22 12:54:43 Tagged date : UTC 2015-04-22 12:54:43

Video ID : 1 Format : AVC Format/Info : Advanced Video Codec Format profile : Baseline@L1.3 Format settings, CABAC : No Format settings, ReFrames : 1 frame Format settings, GOP : M=1, N=60 Codec ID : avc1 Codec ID/Info : Advanced Video Coding Duration : 1mn 24s Bit rate : 291 Kbps Maximum bit rate : 427 Kbps Width : 352 pixels Height : 288 pixels Display aspect ratio : 1.222 Frame rate mode : Constant Frame rate : 19.000 fps Standard : PAL Color space : YUV Chroma subsampling : 4:2:0 Bit depth : 8 bits Scan type : Progressive Bits/(Pixel*Frame) : 0.151 Stream size : 2.92 MiB (80%) Tagged date : UTC 2015-04-22 12:54:44

Audio ID : 2 Format : AAC Format/Info : Advanced Audio Codec Format profile : LC Codec ID : 40 Duration : 1mn 24s Bit rate mode : Variable Bit rate : 72.0 Kbps Maximum bit rate : 76.4 Kbps Channel(s) : 1 channel Channel positions : Front: C Sampling rate : 44.1 KHz Compression mode : Lossy Stream size : 740 KiB (20%) Language : English Encoded date : UTC 2015-04-22 12:54:43 Tagged date : UTC 2015-04-22 12:54:44

Information about the generated output file, according to mediainfo:

General Complete name : output.webm Format : WebM Format version : Version 2 File size : 1.00 MiB Duration : 3h 40mn Overall bit rate mode : Variable Overall bit rate : 633 bps Writing application : Lavf56.1.0 Writing library : Lavf56.1.0

Video ID : 2 Format : VP8 Codec ID : V_VP8 Width : 352 pixels Height : 290 pixels Display aspect ratio : 1.214 Frame rate mode : Variable Compression mode : Lossy Default : No Forced : No

Audio ID : 1 Format : Vorbis Format settings, Floor : 1 Codec ID : A_VORBIS Duration : 3h 40mn Bit rate mode : Variable Bit rate : 96.0 Kbps Channel(s) : 1 channel Sampling rate : 44.1 KHz Compression mode : Lossy Delay relative to video : -358ms Stream size : 152 MiB Writing library : libVorbis (Turpakäräjiin) (20140122 (Turpakäräjiin)) Default : No Forced : No Writing application : VLC media player

I'm attaching a complete log of the VLC invocation which produced this file to the bug.

VLC invocation log

Added attachment:

• vlc_transcode.log.gz

added Component::Stream output: Muxers label

This is the most useful backtrace I was able to obtain so far:

[#0](https://code.videolan.org/videolan/vlc/-/issues/0)  date_Set (p_date=0x7fffd8c1cc28, i_new_date=40544759645) at misc/mtime.c:150
[#1](https://code.videolan.org/videolan/vlc/-/issues/1)  0x00007fffbf6970d0 in DecodeBlock (p_dec=0x7fffd8c04fe8, pp_block=0x970a7ef5d) at codec/faad.c:307
[#2](https://code.videolan.org/videolan/vlc/-/issues/2)  0x00007fffc3bf26f1 in transcode_audio_process (p_stream=0x7fffc8a2cfb8, id=id@entry=0x7fffd8004300, in=0x7fffc965b7e0, out=out@entry=0x7fffeffc3e20)
    at transcode/audio.c:222
[#3](https://code.videolan.org/videolan/vlc/-/issues/3)  0x00007fffc3bef41b in Send (p_stream=0x7fffc8a2cfb8, id=0x7fffd8004300, p_buffer=<optimized out>) at transcode/transcode.c:653
[#4](https://code.videolan.org/videolan/vlc/-/issues/4)  0x00007ffff71967a9 in sout_InputSendBuffer (p_input=0x7fffd8c23100, p_buffer=0x7fffc965b7e0) at stream_output/stream_output.c:233
[#5](https://code.videolan.org/videolan/vlc/-/issues/5)  0x00007ffff711ca01 in DecoderPlaySout (p_dec=0x7fffc96510c8, p_sout_block=0x7fffc965b7e0) at input/decoder.c:1501
[#6](https://code.videolan.org/videolan/vlc/-/issues/6)  0x00007ffff711cb7a in DecoderProcessSout (p_dec=0x7fffc96510c8, p_block=0x0) at input/decoder.c:1556
[#7](https://code.videolan.org/videolan/vlc/-/issues/7)  0x00007ffff711d273 in DecoderProcess (p_dec=0x7fffc96510c8, p_block=0x7fffc965b7e0) at input/decoder.c:1787
[#8](https://code.videolan.org/videolan/vlc/-/issues/8)  0x00007ffff711b48b in DecoderThread (p_data=0x7fffc96510c8) at input/decoder.c:909
[#9](https://code.videolan.org/videolan/vlc/-/issues/9)  0x00007ffff79a60a4 in start_thread (arg=0x7fffeffc4700) at pthread_create.c:309
[#10](https://code.videolan.org/videolan/vlc/-/issues/10) 0x00007ffff74d704d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

It shows how the bogus duration value (i_new_date=40544759645, which, I believe, is in microseconds) pops up in the audio decoding path.

The incorrect duration is clearly derived from mtime() which on my system comes from clock_gettime() and appears to be equal to the time since system boot.

I've noticed that the incorrect duration is written to output file metadata at the very end of transcoding process, and I was able to track down that it happens in this function (in libavformat):

int     av_write_trailer (AVFormatContext *s)

The AVFormatContext *s it receives as an argument is passed to mkv_write_trailer, and the problematic duration is a field in MatroskaMuxContent structure, which is accessed like this:

MatroskaMuxContext *mkv = s->priv_data;

Sample dump of the mkv:

(gdb) print *mkv
$3 = {class = 0x7fffe9425c40 <webm_class>, mode = 2, dyn_bc = 0x0, segment = {pos = 55, sizebytes = 8}, segment_offset = 55, cluster = {pos = 910230, sizebytes = 8}, 
  cluster_pos = 910218, cluster_pts = 28084105, duration_offset = 342, duration = 28086525, main_seekhead = 0x7fffd0067c00, cues = 0x7fffd0066380, 
  tracks = 0x7fffd0067b80, cur_audio_pkt = {buf = 0x7fffd00751e0, pts = 28086548, dts = 28086548, 
    data = 0x7fffd0075030 "\376v\034\371\237lre\224\004}\373\030M\033oǑ\377\311&WFIз\217ѴaY\032Y]~", size = 285, stream_index = 0, flags = 0, side_data = 0x0, 
    side_data_elems = 0, duration = 0, destruct = 0x7fffdef51901 <dummy_destruct_packet>, priv = 0x0, pos = -1, convergence_duration = 0}, have_attachments = 0, 
  reserve_cues_space = 0, cluster_size_limit = 5242880, cues_pos = 0, cluster_time_limit = 5000, wrote_chapters = 0}

In this case, duration is set to 7.8 hours.

On vlc side av_write_trailer is invoked in CloseMux:

/*****************************************************************************
 * Close
 *****************************************************************************/
void CloseMux( vlc_object_t *p_this )
{
    sout_mux_t *p_mux = (sout_mux_t*)p_this;
    sout_mux_sys_t *p_sys = p_mux->p_sys;

    if( !p_sys->b_write_header && !p_sys->b_error && av_write_trailer( p_sys->oc ) < 0 )
    {
        msg_Err( p_mux, "could not write trailer" );
    }
[...]
}

The problematic duration value is thus in p_mux->p_sys->oc->priv_data->duration.

The priv_data is first set to a non-trivial value here:

Hardware watchpoint 2: -location ((sout_mux_t *) p_this)->p_sys->oc->priv_data

Old value = (void *) 0x0
New value = (void *) 0x7fffd00954a0
init_muxer (s=0x7fffc802e780, options=0x0) at /home/jurij/tmp/libav-11.3/libavformat/mux.c:209
209         if (!s->priv_data) {
(gdb) bt
[#0](https://code.videolan.org/videolan/vlc/-/issues/0)  init_muxer (s=0x7fffc802e780, options=0x0) at /home/jurij/tmp/libav-11.3/libavformat/mux.c:209
[#1](https://code.videolan.org/videolan/vlc/-/issues/1)  0x00007fffe91609f1 in avformat_write_header (s=0x7fffc802e780, options=0x0) at /home/jurij/tmp/libav-11.3/libavformat/mux.c:242
[#2](https://code.videolan.org/videolan/vlc/-/issues/2)  0x00007fffe943d951 in Mux (p_mux=0x7fffc80033e8) at demux/avformat/mux.c:380
[#3](https://code.videolan.org/videolan/vlc/-/issues/3)  0x00007ffff71a0394 in sout_MuxSendBuffer (p_mux=0x7fffc80033e8, p_input=<optimized out>, p_buffer=<optimized out>) at stream_output/stream_output.c:542
[#4](https://code.videolan.org/videolan/vlc/-/issues/4)  0x00007fffc3063405 in sout_StreamIdSend (b=<optimized out>, id=<optimized out>, s=0x7fffc8001238) at ../../include/vlc_sout.h:212
[#5](https://code.videolan.org/videolan/vlc/-/issues/5)  Send (p_stream=<optimized out>, id=0x7fffd00008c0, p_buffer=<optimized out>) at transcode/transcode.c:692
[#6](https://code.videolan.org/videolan/vlc/-/issues/6)  0x00007ffff719f698 in sout_InputSendBuffer (p_input=0x7fffd0002cf0, p_buffer=p_buffer@entry=0x7fffc965aaf0) at stream_output/stream_output.c:233
[#7](https://code.videolan.org/videolan/vlc/-/issues/7)  0x00007ffff712d024 in DecoderPlaySout (p_sout_block=0x7fffc965aaf0, p_dec=0x7fffc9652898) at input/decoder.c:1502
[#8](https://code.videolan.org/videolan/vlc/-/issues/8)  DecoderProcessSout (p_block=0x0, p_dec=<optimized out>) at input/decoder.c:1557
[#9](https://code.videolan.org/videolan/vlc/-/issues/9)  DecoderProcess (p_block=<optimized out>, p_dec=<optimized out>) at input/decoder.c:1788
[#10](https://code.videolan.org/videolan/vlc/-/issues/10) DecoderThread (p_data=0x7fffc9652898) at input/decoder.c:909
[#11](https://code.videolan.org/videolan/vlc/-/issues/11) 0x00007ffff79a60a4 in start_thread (arg=0x7ffff0047700) at pthread_create.c:309
[#12](https://code.videolan.org/videolan/vlc/-/issues/12) 0x00007ffff74d704d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

This is where duration is getting set to an incorrect value:

Hardware watchpoint 3: -location ((MatroskaMuxContext *)(s->priv_data))->duration

Old value = 0
New value = 29065223
mkv_write_packet_internal (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/matroskaenc.c:1498
1498        return 0;
(gdb) bt
[#0](https://code.videolan.org/videolan/vlc/-/issues/0)  mkv_write_packet_internal (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/matroskaenc.c:1498
[#1](https://code.videolan.org/videolan/vlc/-/issues/1)  0x00007fffe912c51c in mkv_write_packet (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/matroskaenc.c:1564
[#2](https://code.videolan.org/videolan/vlc/-/issues/2)  0x00007fffe912c63a in mkv_write_flush_packet (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/matroskaenc.c:1589
[#3](https://code.videolan.org/videolan/vlc/-/issues/3)  0x00007fffe9160f86 in write_packet (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/mux.c:334
[#4](https://code.videolan.org/videolan/vlc/-/issues/4)  0x00007fffe9161160 in av_write_frame (s=0x7fffc802e780, pkt=0x7ffff0046d30) at /home/jurij/tmp/libav-11.3/libavformat/mux.c:380
[#5](https://code.videolan.org/videolan/vlc/-/issues/5)  0x00007fffe943d75e in MuxBlock (p_input=<optimized out>, p_input=<optimized out>, p_mux=<optimized out>) at demux/avformat/mux.c:348
[#6](https://code.videolan.org/videolan/vlc/-/issues/6)  Mux (p_mux=0x7fffc80033e8) at demux/avformat/mux.c:407
[#7](https://code.videolan.org/videolan/vlc/-/issues/7)  0x00007ffff71a0394 in sout_MuxSendBuffer (p_mux=0x7fffc80033e8, p_input=<optimized out>, p_buffer=<optimized out>) at stream_output/stream_output.c:542
[#8](https://code.videolan.org/videolan/vlc/-/issues/8)  0x00007fffc3063405 in sout_StreamIdSend (b=<optimized out>, id=<optimized out>, s=0x7fffc8001238) at ../../include/vlc_sout.h:212
[#9](https://code.videolan.org/videolan/vlc/-/issues/9)  Send (p_stream=<optimized out>, id=0x7fffd00008c0, p_buffer=<optimized out>) at transcode/transcode.c:692
[#10](https://code.videolan.org/videolan/vlc/-/issues/10) 0x00007ffff719f698 in sout_InputSendBuffer (p_input=0x7fffd0002cf0, p_buffer=p_buffer@entry=0x7fffc965aaf0) at stream_output/stream_output.c:233
[#11](https://code.videolan.org/videolan/vlc/-/issues/11) 0x00007ffff712d024 in DecoderPlaySout (p_sout_block=0x7fffc965aaf0, p_dec=0x7fffc9652898) at input/decoder.c:1502
[#12](https://code.videolan.org/videolan/vlc/-/issues/12) DecoderProcessSout (p_block=0x0, p_dec=<optimized out>) at input/decoder.c:1557
[#13](https://code.videolan.org/videolan/vlc/-/issues/13) DecoderProcess (p_block=<optimized out>, p_dec=<optimized out>) at input/decoder.c:1788
[#14](https://code.videolan.org/videolan/vlc/-/issues/14) DecoderThread (p_data=0x7fffc9652898) at input/decoder.c:909
[#15](https://code.videolan.org/videolan/vlc/-/issues/15) 0x00007ffff79a60a4 in start_thread (arg=0x7ffff0047700) at pthread_create.c:309
[#16](https://code.videolan.org/videolan/vlc/-/issues/16) 0x00007ffff74d704d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Relevant code from mkv_write_packet_internal concerned with duration manipulation:

int duration            = pkt->duration;

int64_t ts = mkv->tracks[pkt->stream_index].write_dts ? pkt->dts : pkt->pts;

ts += mkv->tracks[pkt->stream_index].ts_offset;

mkv->duration = FFMAX(mkv->duration, ts + duration);

I was able to confirm that the abnormally large value ends up in ts, and it gets there from pkt->pts.

Dump of a sample pkt structure:

(gdb) print *pkt
$27 = {buf = 0x0, pts = 29065170, dts = 29065170, data = 0x7fffcc4bfd80 "\360\020\001\235\001*`\001 \001", size = 13876, stream_index = 1, flags = 1, side_data = 0x0, 
  side_data_elems = 0, duration = 53, destruct = 0x0, priv = 0x0, pos = -1, convergence_duration = 0}

Judging by the code, pts is never intended to be used as a duration, as it's just a monotonically increasing value. Looking at the code from mkv_write_packet_internal included above, it appears that the only reasonable way for this to produce a realistic duration is to have a large negative value in mkv->tracks[pkt->stream_index].ts_offset. That does not happen though, and I did not succeed so far in tracking down where this value is populated.

Likely linked to #12713 (closed) and fixed by !3409 (merged).

closed

added Status::fixed label

changed milestone to %4.0