[mythtv] extremly slow mythfilldatabase in 0.28

Sun Jul 17 11:57:18 UTC 2016

On 17/07/16 08:19, Mark Perkins wrote:
>>
>> 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.
>>

>> 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
>

Thanks for that.

OP is forcing a refresh of 7 days for both sources on each run. That's 
only necessary if the data changes. Maybe it does, but is unlikely IME.

MFD then updates day 15 because it's found new guide data.
And day 20 because it's found existing program data in the database. 
That could be from a previous source or garbage from an erroneous set-up 
that will disappear eventually.
Maybe the 2 hr run was when it found initially populated 2 weeks of data 
for both sources.

Regarding the delays, between:

" ------------------ End of XMLTV output ------------------"

and

"Match found for xmltvid animalplanet.se to channel Animal Planet HD"

MFD simply parses the XML file and matches xmltvids to the database
https://code.mythtv.org/trac/browser/mythtv/mythtv/programs/mythfilldatabase/filldata.cpp#L446

So no reason for delay other than a congested database, filesystem or 
CPU. Or a badly constructed XML file ?
OP mentioned it runs faster when run directly. Could backend activity 
(metadata grabbing ?) be causing MFD to run slowly - it is a "nice" 
activity.

The metagrabber shouldn't be run at all by MFD (AFAIK). Add the "-v 
system" log option to confirm it isn't being invoked.

Unfortunately there's no further debug logging here. One option is to 
add "-v database" logging to see exactly when the "channel" table is 
accessed after the "End of XMLTV". Before that is it's just XML parsing.
That will generate a big log. Minimize the work by just refreshing one 
day of one source.

mythfilldatabase --sourceid=1 --max-days=1 --config...
(Untested)