[mythtv-users] Mythcommflag hanging at midnight
K Stanton
stantonx at comcast.net
Sat May 5 14:27:30 UTC 2018
I'm running Mythtv 29.0-71 on mythbuntu/Ubuntu 16.04. Combination
FE/BE. 6 core processor. Nvidia GT630. System is on SSD. Recordings
are on HDD "media" drives in RAID.
I have a recent issue where mythcommflag jobs hang on late-night shows.
The job statuses show that they're "running", but they're frozen at a %
complete, and a certain frame rate. Those numbers won't change for
days, and the queue will keep stacking up. Here's the tail of a recent
mythcommflag.log:
...
May 4 21:56:06 mythbox mythcommflag: mythcommflag[17874]: I CoreContext
ClassicCommDetector.cpp:570 (go) 90% Completed @ 38.4722 fps.
May 4 22:02:30 mythbox mythcommflag: mythcommflag[17874]: I CoreContext
ClassicCommDetector.cpp:570 (go) 100% Completed @ 37.4117 fps.
May 4 22:03:41 mythbox mythcommflag: mythcommflag[17874]: E Decoder
avformatdecoder.cpp:4936 (GetFrame) decoding error#012#011#011#011eno:
Unknown error 541478725 (541478725)
May 4 22:03:42 mythbox mythcommflag: mythcommflag[17874]: N CoreContext
main.cpp:932 (FlagCommercials) Finished, 7 break(s) found.
May 4 22:03:42 mythbox mythcommflag: mythcommflag[17874]: I CoreContext
mythcontext.cpp:1610 (~MythContext) Waiting for threads to exit.
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: C
thread_unknown mythcommandlineparser.cpp:2619 (ConfigureLogging)
mythcommflag version: fixes/29 [v29.0-71-g339b08e] www.mythtv.org
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: C
thread_unknown mythcommandlineparser.cpp:2621 (ConfigureLogging) Qt
version: compile: 5.5.1, runtime: 5.5.1
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: N
thread_unknown mythcommandlineparser.cpp:2623 (ConfigureLogging) Enabled
verbose msgs: general
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: N
thread_unknown logging.cpp:927 (logStart) Setting Log Level to LOG_INFO
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I Logger
logging.cpp:313 (run) Added logging to the console
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Interrupt handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Terminated handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Segmentation fault handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Aborted
handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Bus
error handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Floating
point exception handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Illegal
instruction handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Real-time signal 0 handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Hangup
handler
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: N
thread_unknown mythdirs.cpp:195 (InitializeMythDirs) Using runtime
prefix = /usr
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: N
thread_unknown mythdirs.cpp:197 (InitializeMythDirs) Using configuration
directory = /home/mythtv/.mythtv
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcorecontext.cpp:271 (Init) Assumed character encoding: en_US.UTF-8
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: N CoreContext
mythcontext.cpp:599 (LoadDatabaseSettings) Empty LocalHostName.
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcontext.cpp:607 (LoadDatabaseSettings) Using localhost value of mythbox
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcontext.cpp:852 (TestDBconnection) Start up testing connections. DB
192.168.1.152, BE , attempt 0, status dbAwake
May 4 23:33:34 mythbox mythcommflag: mythcommflag[18887]: I LogForward
loggingserver.cpp:302 (SyslogLogger) Added syslogging
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: N CoreContext
mythcorecontext.cpp:1768 (InitLocale) Setting QT default locale to en_US
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcorecontext.cpp:1801 (SaveLocaleDefaults) Current locale en_US
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: N CoreContext
mythlocale.cpp:123 (LoadDefaultsFromXML) Reading locale defaults from
/usr/share/mythtv//locales/en_us.xml
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythtranslation.cpp:73 (load) Loading en_us translation for module
mythfrontend
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcorecontext.cpp:448 (ConnectCommandSocket)
MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
192.168.1.152:6543 (try 1 of 1)
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcorecontext.cpp:1665 (CheckProtoVersion)
MythCoreContext::CheckProtoVersion(): Using protocol version 91 BuzzOff
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
avformatdecoder.cpp:2081 (ScanStreams) AFD: codec AC3 has 6 channels
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x26d2b40,
id(AC3) type(Audio)
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
avformatdecoder.cpp:2081 (ScanStreams) AFD: codec AC3 has 2 channels
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x26d3bc0,
id(AC3) type(Audio)
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x26d4dc0,
id(MPEG2VIDEO) type(Video)
May 4 23:33:35 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
mythcorecontext.cpp:448 (ConnectCommandSocket)
MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
192.168.1.152:6543 (try 1 of 1)
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: C
thread_unknown mythcommandlineparser.cpp:2619 (ConfigureLogging)
mythcommflag version: fixes/29 [v29.0-71-g339b08e] www.mythtv.org
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: C
thread_unknown mythcommandlineparser.cpp:2621 (ConfigureLogging) Qt
version: compile: 5.5.1, runtime: 5.5.1
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: N
thread_unknown mythcommandlineparser.cpp:2623 (ConfigureLogging) Enabled
verbose msgs: general
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: N
thread_unknown logging.cpp:927 (logStart) Setting Log Level to LOG_INFO
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I Logger
logging.cpp:313 (run) Added logging to the console
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Interrupt handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Terminated handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Segmentation fault handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Aborted
handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Bus
error handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Floating
point exception handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Illegal
instruction handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup
Real-time signal 0 handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I
thread_unknown signalhandling.cpp:194 (SetHandlerPrivate) Setup Hangup
handler
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: N
thread_unknown mythdirs.cpp:195 (InitializeMythDirs) Using runtime
prefix = /usr
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: N
thread_unknown mythdirs.cpp:197 (InitializeMythDirs) Using configuration
directory = /home/mythtv/.mythtv
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcorecontext.cpp:271 (Init) Assumed character encoding: en_US.UTF-8
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: N CoreContext
mythcontext.cpp:599 (LoadDatabaseSettings) Empty LocalHostName.
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcontext.cpp:607 (LoadDatabaseSettings) Using localhost value of mythbox
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcontext.cpp:852 (TestDBconnection) Start up testing connections. DB
192.168.1.152, BE , attempt 0, status dbAwake
May 4 23:34:44 mythbox mythcommflag: mythcommflag[18969]: I LogForward
loggingserver.cpp:302 (SyslogLogger) Added syslogging
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: N CoreContext
mythcorecontext.cpp:1768 (InitLocale) Setting QT default locale to en_US
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcorecontext.cpp:1801 (SaveLocaleDefaults) Current locale en_US
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: N CoreContext
mythlocale.cpp:123 (LoadDefaultsFromXML) Reading locale defaults from
/usr/share/mythtv//locales/en_us.xml
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythtranslation.cpp:73 (load) Loading en_us translation for module
mythfrontend
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcorecontext.cpp:448 (ConnectCommandSocket)
MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
192.168.1.152:6543 (try 1 of 1)
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcorecontext.cpp:1665 (CheckProtoVersion)
MythCoreContext::CheckProtoVersion(): Using protocol version 91 BuzzOff
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
avformatdecoder.cpp:2081 (ScanStreams) AFD: codec AC3 has 6 channels
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x2021fc0,
id(AC3) type(Audio)
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
avformatdecoder.cpp:2081 (ScanStreams) AFD: codec AC3 has 1 channels
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x20231c0,
id(AC3) type(Audio)
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
avformatdecoder.cpp:2590 (OpenAVCodec) AFD: Opened codec 0x2020ea0,
id(MPEG2VIDEO) type(Video)
May 4 23:34:45 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
mythcorecontext.cpp:448 (ConnectCommandSocket)
MythCoreContext::ConnectCommandSocket(): Connecting to backend server:
192.168.1.152:6543 (try 1 of 1)
May 4 23:44:56 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
ClassicCommDetector.cpp:392 (go) Finding Logo
May 4 23:45:42 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
ClassicCommDetector.cpp:570 (go) 0% Completed @ 143.266 fps.
May 4 23:45:54 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:392 (go) Finding Logo
May 4 23:47:04 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:570 (go) 0% Completed @ 131.926 fps.
May 4 23:47:26 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
ClassicCommDetector.cpp:570 (go) 10% Completed @ 115.092 fps.
May 4 23:48:46 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:570 (go) 10% Completed @ 114.95 fps.
May 4 23:49:10 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
ClassicCommDetector.cpp:570 (go) 20% Completed @ 115.027 fps.
May 4 23:50:30 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:570 (go) 20% Completed @ 114.857 fps.
May 4 23:52:59 mythbox mythcommflag: mythcommflag[18887]: I CoreContext
ClassicCommDetector.cpp:570 (go) 30% Completed @ 82.5289 fps.
May 4 23:53:20 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:570 (go) 30% Completed @ 94.5966 fps.
May 4 23:59:54 mythbox mythcommflag: mythcommflag[18969]: I CoreContext
ClassicCommDetector.cpp:570 (go) 40% Completed @ 61.5977 fps.
May 5 00:00:25 mythbox mythcommflag: mythcommflag[18887]: E Decoder
mythplayer.cpp:3503 (DecoderGetFrame) Player(0): Decoder timed out
waiting for free video buffers.
May 5 00:00:25 mythbox mythcommflag: mythcommflag[18969]: E Decoder
mythplayer.cpp:3503 (DecoderGetFrame) Player(0): Decoder timed out
waiting for free video buffers.
So, every day, at 24 or 25 seconds after midnight, this will happen.
And there will be no more logging until I do something.
If I kill the two jobs - in this case 18887 and 18969 - the current
(hung) jobs are marked as failed, and mythcommflag happily and
successfully goes on to the backlog of queued jobs. I will then
re-queue the hung jobs, and they complete successfully.
On a related note, just based on the final error in that log (Decoder
timed out waiting for free video buffers); I had been using vdpau for
video playback, and mythfrontend would often randomly freeze, and
mythfrontend.log would show that same error. I recently changed to
OpenGL/ffmpeg, and the mythfrontend freezing stopped. That might be
about the time this mythcommflag issue started. Could the playback
decoder affect mythcommflag? In the log, it's obviously mythplayer.cpp
showing the error.
I allow 2 simultaneous jobs. Mythcommflag never goes over 35% of the
processing capability. So, could this not necessarily be a mythcommflag
problem, but something possibly hogging io resources at midnight? I do
have a system backup which runs at midnight, but I don't see it in the
chron lists, so don't know how to play with that to troubleshoot. Is
there perhaps an "io" log capability? Is it possible to ionice either a
backup script or mythcommflagging? Running top or iotop during
mythcommflagging while watching recordings show low usage of processors
and io, but maybe whatever is happening at midnight is just too much.
So, I think I have a couple directions I could go to diagnose this, but
I'm thinking someone will have some good insight in where to start!
Thanks.
More information about the mythtv-users
mailing list