Log storm from bad h264 decoded video

[Robin Gilks <g8ecj@…>]

Unrelated to #7982, error messages swamp the nfs network connection which cause error messages that swamp the nfs network connection which cause......

Averaging 8 messages per millisecond to the log. Currently running with no '-v' options at all (i.e. mythfrontend > /home/mythtv/mythfrontend.log 2>&1)

2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.440 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one
2010-04-19 08:14:39.441 [h264 @ 0x7f301f5da500]number of reference frames exceeds max (probably corrupt input), discarding one

$ mythfrontend --version
Please include all output in bug reports.
MythTV Version   : 23907
MythTV Branch    : branches/release-0-23-fixes
Network Protocol : 56
Library API      : 0.23.20100314-1
QT Version       : 4.6.2
Options compiled in:
 linux release using_oss using_alsa using_jack using_backend using_dvb using_firewire using_frontend using_hdhomerun using_hdpvr using_iptv using_ivtv using_joystick_menu using_lirc using_mheg using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld using_xvmcw using_bindings_perl using_bindings_python using_opengl using_vdpau using_ffmpeg_threads using_libavc_5_3 using_live using_mheg

[sphery]

dup of #6729 . See ​http://svn.mythtv.org/trac/ticket/6729#comment:16

[kevin.wells@…]

Count repeated log messages instead of logging them individually

[kevin.wells@…]

Please see #6729 details about the "log_count_repeats_24221.patch". I added the patch to #8367 instead of #6729 accidentally.

[kevin.wells@…]

#6729 is locked so I can't submit changes there! So I'll add them here instead.

High frequency log messages were a big problem for me in 0.22. Messages were logged so frequently that it prevented MythTV working reliably. My system was spending most of its time flushing to disk (presumably a flush for each line written to the log file).

After a short time my mythbackend.log file was 143MiB and 1,183,981 out of 1,161,018 lines contained errors like this:

        2009-12-31 00:32:53.547 [h264 @ 0x7fa3038b7820]number of reference \
                frames exceeds max (probably corrupt input), discarding one

In my opinion if the same message is repeated many times it should be logged like this:

        2009-12-31 00:32:53.547 [h264 @ 0x7fa3038b7820]number of reference \
                frames exceeds max (probably corrupt input), discarding one
        2009-12-31 00:32:57.530 last message repeated 152 times

This means the error is still logged, but when the frequency of logging is very high the system will not lock up as a result.

There is code in av_log_default_callback to handle repeated messages, but no code in myth_av_log or my_av_print`. The log_count_repeats_24221.patch above adds support for counting of repeated messages to myth_av_log and my_av_print.

Warning - I have been using this code without any problems since Dec 2009 (against revision 23245 and Ubuntu mythtv-0.22.0+fixes22594). Today I modified the patch to work on Trunk as at revision 24221, tested that it compiled, and submitted it. I have not run the code built from Trunk because of VDPAU related linking problems.

Future work - There is code to handle repeated log messages in libs/libavutil/log.c, libs/libmyth/mythcontext.cpp, libs/libmythtv/avformatdecoder.cpp, and programs/mythtranscode/mpeg2fix.cpp. Perhaps this could should be re-factored into a single function.

[Janne Grunau]

(In [24235]) H264: respect ref_frame_count when adding short term refs after a frame num gap

this silences the "number of reference frames exceeds max (probably corrupt input), discarding one" message in the uninteresting cases, i.e. after seeking, playback start Refs #6729 Refs #8367