[mythtv] extremly slow mythfilldatabase in 0.28

Sun Jul 17 07:19:56 UTC 2016

> 
> see attached compressed log file.
> it was created with: --refresh 0-7 -v xmltv,channel it took "only" 30
minutes
> to complete the run of mfdb but still much longer than it used to be.
> 
> i still have the -v all file if anyone is interested but i doubt i will be
able to
> send it to the mailing list since even compressed it is about 3.12mb
> 
> anyway, in the attached file you can see a long delay between end of xmltv
> output and the first line after.
> usually about a minute and i bet this is when it does all of those
ttvdb.py calls.

I don't have any answers, sorry, but will make a couple of observations in
case it helps someone else with a suggestion. 

First observation is same as you, about 80-110sec delay between the line
"End of XMLTV output" and the next line where it starts matching xmltvid's.
There are 19 xmltv grabs so that accounts for just about nearly all the
total time. But I don't see why it would be running ttvdb.py calls in those
intervals, my understanding is that metadata should / would only be pulled
once a recording was started (assuming metadata lookup is configured /
enabled etc). 

Second observation is that despite using --refresh 0-7 it seemed to be check
up to 20days worth of time, albeit with some gaps.
cat mythfilldatabase.20160717051154.27529.log | grep "\-\-config\-file"
> 2016-07-17 07:12:01.371714 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/myth4hszoT --days 1 --offset 0
> 2016-07-17 07:14:01.476704 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythlEgt33 --days 1 --offset 1
> 2016-07-17 07:16:01.237414 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythPyHrg0 --days 1 --offset 2
> 2016-07-17 07:18:02.141973 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythpGnX1L --days 1 --offset 3
> 2016-07-17 07:20:00.788347 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/myth6X9vrf --days 1 --offset 4
> 2016-07-17 07:21:59.500557 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythRvhjJq --days 1 --offset 5
> 2016-07-17 07:23:50.110846 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythHPPOvR --days 1 --offset 6
> 2016-07-17 07:25:31.063099 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythvS09WZ --days 1 --offset 7
> 2016-07-17 07:27:18.254595 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythJ7nyUb --days 1 --offset 15
> 2016-07-17 07:28:58.805120 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DVB.xmltv' --output /tmp/mythmXKA73 --days 1 --offset 20
> 2016-07-17 07:29:03.609020 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/myth3OjV9c --days 1 --offset 0
> 2016-07-17 07:30:34.272580 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythHujzOt --days 1 --offset 1
> 2016-07-17 07:32:13.473504 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythiamGZl --days 1 --offset 2
> 2016-07-17 07:33:51.117033 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythek11eK --days 1 --offset 3
> 2016-07-17 07:35:27.510229 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythEvx1aA --days 1 --offset 4
> 2016-07-17 07:37:04.496072 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythlFxpST --days 1 --offset 5
> 2016-07-17 07:38:37.676264 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythyMWx0t --days 1 --offset 6
> 2016-07-17 07:39:59.480612 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythjKfDIG --days 1 --offset 7
> 2016-07-17 07:41:27.334188 I [27529/27529] CoreContext filldata.cpp:410
(GrabData) - Grabber Command: nice tv_grab_se_tvzon --config-file
'/root/.mythtv/DBOX.xmltv' --output /tmp/mythhy8acR --days 1 --offset 20

Third observation is that you have 2 sources, the first with 61 channels the
second with 43 channels. The first source is numbered 1, the second source
is numbered 8. I am guessing maybe you have tried adding / deleting sources
at different times to try get things working. Have you tried clearing out
all sources with a 'delete all sources on all hosts' and starting the source
config from scratch?
cat mythfilldatabase.20160717051154.27529.log | grep -A 2 " Updating source"
> 2016-07-17 07:11:59.698048 I [27529/27529] CoreContext filldata.cpp:569
(Run) - Updating source #1 (DVB) with grabber tv_grab_se_tvzon
> 2016-07-17 07:11:59.698583 I [27529/27529] CoreContext filldata.cpp:583
(Run) - Found 61 channels for source 1 which use grabber
> 2016-07-17 07:11:59.707874 I [27529/27539] SystemManager
mythsystemunix.cpp:276 (run) - Starting process manager
> --
> 2016-07-17 07:29:03.300771 I [27529/27529] CoreContext filldata.cpp:569
(Run) - Updating source #8 (DBOX) with grabber tv_grab_se_tvzon
> 2016-07-17 07:29:03.301336 I [27529/27529] CoreContext filldata.cpp:583
(Run) - Found 43 channels for source 8 which use grabber
> 2016-07-17 07:29:03.607192 I [27529/27529] CoreContext filldata.cpp:641
(Run) - Grabber has capabilities: baseline manualconfig tkconfig apiconfig
cache

Fourth observation, looks like you're running the backend as the root user,
was this intentional or have you had other issues that running the BE as
root got around?

Have you tried running top or iotop during a mythfilldatabase run to see if
that gives any extra clues about what is going on. Is your system thrashing
the cpu or mem swapping or anything? Otherwise I don't know. Could always
pastebin the -v all log file in case someone gets super excited and decides
to try and trawl through it.