[mythtv-users] mythbackend hanging with busy disk

[Stephen Worthington]

On Wed, 6 Apr 2016 19:30:10 +0200, you wrote:

>My mythbackend hangs from time to time with a busy disk.
>
>It is not reproducible, but happens every couple of days.
>
>When it happens, I cannot log in via ssh, and mythweb is also
>unresponsive. The one time I happened to be already logged in via ssh,
>htop showed that it was not CPU-bound.
>
>Therefore, I don't have any other option but to pull the plug, count
>to ten, and reboot. Afterwards, looking at /var/log/syslog and the
>list of recorded programs, I see a 0-length recording and:
>
>Apr  6 15:53:32 pan mythbackend: message repeated 102622 times: [
>mythbackend[2403]: N Scheduler scheduler.cpp:2771 (HandleIdleShutdown)
>Blocking shutdown because a recording is due to start soon.]
>Apr  6 15:53:37 pan mythbackend: message repeated 11096 times: [
>mythbackend[2403]: N Scheduler scheduler.cpp:2771 (HandleIdleShutdown)
>Blocking shutdown because a recording is due to start soon.]
>Apr  6 15:53:45 pan mythbackend: message repeated 20943 times: [
>mythbackend[2403]: N Scheduler scheduler.cpp:2771 (HandleIdleShutdown)
>Blocking shutdown because a recording is due to start soon.]
>Apr  6 15:54:37 pan mythbackend: message repeated 120254 times: [
>mythbackend[2403]: N Scheduler scheduler.cpp:2771 (HandleIdleShutdown)
>Blocking shutdown because a recording is due to start soon.]
>
>This may be a red herring, but why would the message be repeated so many times?
>
>In /var/log/mythtv/mythbackend.log, I see messages like:
>
>Apr  6 15:53:32 pan mythbackend: mythbackend[2403]: W TVRecEvent
>recorders/dvbchannel.cpp:386 (CheckOptions)
>DVBChan[7](/dev/dvb/adapter0/fr
>ontend0): Selected fec_inner parameter unsupported by this driver.
>Apr  6 15:53:37 pan mythbackend: mythbackend[2403]: E TVRecEvent
>recorders/dvbchannel.cpp:1107 (GetUncorrectedBlockCount)
>DVBChan[7](/dev/dvb/adapter0/frontend0): Getting Frontend uncorrected
>block count failed.#012#011#011#011eno: Operation not supported (95)
>Apr  6 15:53:37 pan mythbackend: mythbackend[2403]: W TVRecEvent
>recorders/dvbsignalmonitor.cpp:97 (DVBSignalMonitor)
>DVBSigMon[7](/dev/dvb/adapter0/frontend0): Cannot count Uncorrected
>Blocks#012#011#011#011eno: Operation not supported (95)
>Apr  6 15:53:45 pan mythbackend: mythbackend[2403]: N DVBRead
>recorders/dtvsignalmonitor.cpp:367 (HandlePMT)
>DTVSigMon[7](/dev/dvb/adapter0/frontend0): PMT says program 4326 is
>encrypted
>Apr  6 15:54:37 pan mythbackend: mythbackend[2403]: I DVBRead
>mpeg/mpegstreamdata.cpp:1979 (ProcessEncryptedPacket)
>MPEGStream[7](0x7f0000130f18): PID 0x28c status: Encrypted
>
>Does this mean that it tried to record an encrypted program, and it
>hit the disk until I pulled the plug two hours later? The channel it
>should have recorded then is not encrypted.
>
>What does "program 4326" mean?
>
>Concerned that I had some old channel info in the database, yesterday
>I deleted the transport and channel tables with:
>
>mysql -umythtv -pxxxxxxxx -e"DELETE from mythconverg.channelscan_dtv_multiplex;"
>mysql -umythtv -pxxxxxxxx -e"DELETE from mythconverg.channel;"
>
>and then rescanned for channels.
>
>Any ideas?
>
>Regards
>
>Jeff

My experiences with a "busy disk" (continuous disk activity but unable
to get the box to do anything, or it taking many minutes to do
something that normally is instant) have all been one of two things:

1) Disk thrashing - where there are two or more sources of ultra-heavy
disk activity, each causing so much activity that the other can not
make any progress.  If you have mythcommflag running on multiple
recordings (started at the end of the recording) and a database backup
happening at the same time, you will likely get disk thrashing (unless
it is an SSD).

2) Disk full.  This is usually caused by log files filling up the
disk, due to some problem that does not properly control the resulting
log messages, or say a DDNS attack on a router causing massive traffic
from it.  But I have also had a MythTV backup to the same disk as the
database causing it to go full.  My database is always growing and is
now huge, so the backup process, which creates an ASCII SQL dump of
the database first, then compresses it with gzip, was overflowing the
disk, either in the first stage of creating the dump, or when it
needed to create new file to compress that dump into.  So check where
your backups are going and the relative size of your database versus
the free space.  The database is normally in
/var/lib/mysql/mythconverg and backups default to going to
/var/lib/mythtv/db_backups.

The "PMT says program xxxx is encrypted" messages may or may not be a
problem.  The PMT is a Program Map Table in the MPEG2 transport
stream.  See here for basic information about how MPEG2 transport
streams work:

https://en.wikipedia.org/wiki/MPEG_transport_stream

A transport stream normally contains multiple interleaved data
streams, several for each channel being broadcast on a multiplex.  A
PMT packet is sent regularly for each channel to give the service ID
number for that channel and identify the various streams that make it
up (eg video, audio, subtitles).  It also specifies if (and possibly
how) a stream is encrypted.  Without looking at the mythbackend code,
I do not know if you will get messages about encrypted channels if
mythbackend simply sees an encryption flag in any PMT, or whether that
message will appear only if it sees an encryption flag in a PMT it
needs to use for the a channel it is trying to record.  I do know what
happens if it is unable to decrypt the packets for a channel.  It just
keeps on trying forever, and finally only stops trying when the end of
the scheduled recording time for the program comes along.