x11grab does not handle missed frames properly

[Levi]

If x11grab misses some frames, there is no indication that this occurred, and it does not correctly duplicate frames to make up for the missing ones.

How to reproduce: (Using ffmpeg 1.0.7 from deb-multimedia)

/usr/bin/ffmpeg -an -loglevel debug -f x11grab -s 720x576 -r 25 -i :0 -vsync cfr -f rawvideo -y -r 25 - 2>out.txt | cat >/dev/null &
PID=$! ; sleep 10 ; kill -SIGSTOP $PID ; sleep 30 ; kill -SIGCONT $PID ; sleep 30 ; kill $PID

(ie wait 10 seconds, then cause ffmpeg to block trying to write to output for 30 seconds then restart for another 30 seconds)

Output:

ffmpeg version 1.0.7 Copyright (c) 2000-2013 the FFmpeg developers
  built on Jul 19 2013 07:14:44 with gcc 4.7 (Debian 4.7.2-5)
  configuration: --prefix=/usr --extra-cflags='-g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security ' --extra-ldflags='-Wl,-z,relro' --cc='ccache cc' --enable-shared --enable-libmp3lame --enable-gpl --enable-nonfree --enable-libvorbis --enable-pthreads --enable-libfaac --enable-libxvid --enable-postproc --enable-x11grab --enable-libgsm --enable-libtheora --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libx264 --enable-libspeex --enable-nonfree --disable-stripping --enable-libvpx --enable-libschroedinger --disable-encoder=libschroedinger --enable-version3 --enable-libopenjpeg --enable-librtmp --enable-avfilter --enable-libfreetype --enable-libvo-aacenc --disable-decoder=amrnb --enable-libvo-amrwbenc --enable-libaacplus --libdir=/usr/lib/x86_64-linux-gnu --disable-vda --enable-libbluray --enable-libcdio --enable-gnutls --enable-frei0r --enable-openssl --enable-libass --enable-libopus --enable-fontconfig --enable-libfdk-aac --enable-libdc1394 --disable-altivec --dis  libavutil      51. 73.101 / 51. 73.101
  libavcodec     54. 59.100 / 54. 59.100
  libavformat    54. 29.104 / 54. 29.104
  libavdevice    54.  2.101 / 54.  2.101
  libavfilter     3. 17.100 /  3. 17.100
  libswscale      2.  1.101 /  2.  1.101
  libswresample   0. 15.100 /  0. 15.100
  libpostproc    52.  0.100 / 52.  0.100
[x11grab @ 0x946e60] device: :0 -> display: :0 x: 0 y: 0 width: 720 height: 576
[x11grab @ 0x946e60] shared memory extension found
[x11grab @ 0x946e60] All info found
[x11grab @ 0x946e60] Estimating duration from bitrate, this may be inaccurate
Input #0, x11grab, from ':0':
  Duration: N/A, start: 1381462811.123713, bitrate: 331776 kb/s
    Stream #0:0, 1, 1/1000000: Video: rawvideo (BGR[0] / 0x524742), bgr0, 720x576, 1/25, 331776 kb/s, 25 tbr, 1000k tbn, 25 tbc
[buffer @ 0x92b780] Setting entry with key 'video_size' to value '720x576'
[buffer @ 0x92b780] Setting entry with key 'pix_fmt' to value '298'
[buffer @ 0x92b780] Setting entry with key 'time_base' to value '1/25'
[buffer @ 0x92b780] Setting entry with key 'pixel_aspect' to value '0/1'
[buffer @ 0x92b780] Setting entry with key 'sws_param' to value 'flags=2'
[buffer @ 0x92b780] Setting entry with key 'frame_rate' to value '25/1'
[graph 0 input from stream 0:0 @ 0x92bc00] w:720 h:576 pixfmt:bgr0 tb:1/25 fr:25/1 sar:0/1 sws_param:flags=2
[graph 0 input from stream 0:0 @ 0x92bc00] TB:0.040000 FRAME_RATE:25.000000 SAMPLE_RATE:nan
Output #0, rawvideo, to 'pipe:':
  Metadata:
    encoder         : Lavf54.29.104
    Stream #0:0, 0, 1/90000: Video: rawvideo (BGR[0] / 0x524742), bgr0, 720x576, 1/25, q=2-31, 200 kb/s, 90k tbn, 25 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo -> rawvideo)
Press [q] to stop, [?] for help
frame=   15 fps=0.0 q=0.0 size=   24300kB time=00:00:00.60 bitrate=331776.0kbits/s
frame=   28 fps= 27 q=0.0 size=   45360kB time=00:00:01.12 bitrate=331776.0kbits/s
frame=   41 fps= 26 q=0.0 size=   66420kB time=00:00:01.64 bitrate=331776.0kbits/s
...
frame=  262 fps= 25 q=0.0 size=  424440kB time=00:00:10.48 bitrate=331776.0kbits/s
frame=  275 fps= 25 q=0.0 size=  445500kB time=00:00:11.00 bitrate=331776.0kbits/s

(Output blocks for 30 seconds and then restarts)

frame=  279 fps=6.8 q=0.0 size=  451980kB time=00:00:11.16 bitrate=331776.0kbits/s
frame=  512 fps= 12 q=0.0 size=  829440kB time=00:00:20.48 bitrate=331776.0kbits/s
frame=  670 fps= 16 q=0.0 size= 1085400kB time=00:00:26.80 bitrate=331776.0kbits/s
frame=  683 fps= 16 q=0.0 size= 1106460kB time=00:00:27.32 bitrate=331776.0kbits/s
frame=  696 fps= 16 q=0.0 size= 1127520kB time=00:00:27.84 bitrate=331776.0kbits/s
...
frame= 1346 fps= 19 q=0.0 size= 2180520kB time=00:00:53.84 bitrate=331776.0kbits/s
frame= 1359 fps= 20 q=0.0 size= 2201580kB time=00:00:54.36 bitrate=331776.0kbits/s
frame= 1372 fps= 20 q=0.0 size= 2222640kB time=00:00:54.88 bitrate=331776.0kbits/s
frame= 1385 fps= 20 q=0.0 size= 2243700kB time=00:00:55.40 bitrate=331776.0kbits/s

During the stall, strace output shows that it is indeed blocking on output:

strace -p 3891
Process 3891 attached - interrupt to quit
write(1, "hJ\26\25|\340\4\345\r)\300\221\32\203u\241\234U\340!\206\2610n7(>\372\2\v-\4"..., 6081

Frame count does not match elapsed time
At least 70 seconds real time have elapsed, but ffmpeg only gave 55 seconds worth of output. It *is* making up for some of the time since it would have only had 40 seconds worth of output otherwise, but 50% of the time spent blocked is not accounted for. The frame count indicated does match the actual amount of data outputted.

No indication of missed frames
It is not possible to identify whether the frame grabber missed any frames and inserted dups. As a comparison, libav 0.8 identifies that there are frames missing with dup/drop on the status line if using mpeg2video output (but strangely shows nothing when using rawvideo -- presumably rawvideo has no timestamps?).

Example of libav output:

frame=  495 fps= 25 q=31.0 size=    1035kB time=19.76 bitrate= 429.1kbits/s
frame= 1126 fps= 25 q=31.0 size=    1948kB time=45.00 bitrate= 354.7kbits/s dup=461 drop=216

From my cursory look, x11grab_read_packet() seems to be doing the right thing (reporting the result from av_gettime() in the AVPacket) so I presume this is something that happens at a higher level. ffmpeg.c appears to contain code to print dup/drop but it doesn't actually print anything.

Alternate Demonstration

A slightly different demonstration. Instead of blocking on output, we can try SIGSTOP/SIGCONT on ffmpeg directly:

usr/bin/ffmpeg -an -loglevel 99 -f x11grab -s 720x576 -r 25 -vsync 1 -i :0 -vsync 1 -f rawvideo -pix_fmt yuv420p -y -r 25 - 2> out.txt > /dev/null

And while that's running, in another terminal:

PID=6519 ; kill -SIGSTOP $PID ; sleep 40 ; kill -SIGCONT $PID ; sleep 10 ; kill $PID

ffmpeg output:

...
frame=  795 fps= 25 q=0.0 size=  482962kB time=00:00:31.80 bitrate=124416.0kbits/s
frame=  808 fps= 25 q=0.0 size=  490860kB time=00:00:32.32 bitrate=124416.0kbits/s
frame=  821 fps= 25 q=0.0 size=  498758kB time=00:00:32.84 bitrate=124416.0kbits/s

(pause)

frame=  825 fps= 11 q=0.0 size=  501188kB time=00:00:33.00 bitrate=124416.0kbits/s
frame=  997 fps= 14 q=0.0 size=  605678kB time=00:00:39.88 bitrate=124416.0kbits/s
frame= 1186 fps= 16 q=0.0 size=  720495kB time=00:00:47.44 bitrate=124416.0kbits/s
...
frame= 1540 fps= 19 q=0.0 size=  935550kB time=00:01:01.60 bitrate=124416.0kbits/s
frame= 1553 fps= 19 q=0.0 size=  943448kB time=00:01:02.12 bitrate=124416.0kbits/s
frame= 1556 fps= 19 q=0.0 size=  945270kB time=00:01:02.24 bitrate=124416.0kbits/s

video:945270kB audio:0kB subtitle:0 global headers:0kB muxing overhead 0.000000%
Received signal 15: terminating.

The timestamp before the first stop was 32.84 so the timestamp at the last kill should have been +10 seconds (if the timer was being paused) or +50 seconds later (if it noticed the 40 seconds of missing time). Instead the missing 40 seconds somehow turned into 20 seconds. The fact that 40 seconds worth of input frames were missing is not indicated anywhere.

It may just be coincidence but in both situations, 'missing' time seems to be made up at almost exactly a 50% rate.

[Carl Eugen Hoyos]

Please test current git head.

[Levi]

Is still broken in head.

The commit that broke the behaviour was c9cc76290f8139a012a12efe7e581276b8bd8dff (activating the setpts filter).

That commit was from qatar/master repository which seemed to be one of the libav devs (was imported into ffmpeg master in commit 16e25ef34b375dbc6789b6b0da7d077c1dcefe88) so I also lodged a bug report with libav ​https://bugzilla.libav.org/show_bug.cgi?id=574 (not sure how this works with the two projects, apologies in advance if this is not the way you'd prefer to handle it).

[Carl Eugen Hoyos]

Could you confirm that the problem you see is not reproducible with b0387edd (but with 16e25ef3)?

[Carl Eugen Hoyos]

Please read ​http://blog.pkh.me/p/13-the-ffmpeg-libav-situation.html for more information about qatar/avconv.

[Levi]

Replying to cehoyos:

Could you confirm that the problem you see is not reproducible with b0387edd (but with 16e25ef3)?

Confirmed:

16e25ef34b375dbc6789b6b0da7d077c1dcefe88: Failed
c9cc76290f8139a012a12efe7e581276b8bd8dff: Failed
4f81a5072a59798e22ffacb091b4dd6b865b9a80: Succeeded
b0387edd5e766b1032f946d6cdb35b765bb45435: Succeeded

[Michael Niedermayer]

"-framerate 25" instead of "-r 25" should work, -r 25 overrides the input timestamps that is with -r 25 before the input you tell ffmpeg that the input IS constant 25fps with no missing or duplicate frames

[Jeff Marion]

Using -framerate instead of -r doesn't actually fix the issue. It's easy to reproduce with an excessively high frame rate and corresponding high dropped frame count. In my environment using ffmpeg 2.6.2 trying to capture 3 seconds of 1920x1080 at 100fps only manages to capture 47 frames which results in a duration of 0.47 seconds rather than the correct 3 seconds.

[Jeff Marion]

Never mind my mistake, -framerate before -i doesn't work but after it works as you say.