[mythtv] extremly slow mythfilldatabase in 0.28

Torbjorn Jansson torbjorn.jansson at mbox200.swipnet.se
Sun Jul 17 17:08:44 UTC 2016


On 2016-07-17 13:57, Roger Siddons wrote:
> 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.
>
yes i forced a refresh of 7 days since the delay only happens when it 
actually updates days.


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

yes, that tends to happen as new data shows up.
and yes if i refresh all 20 days it takes over an hour to complete, much 
longer than in 0.27.

due to the graber having nearly 20 days of data and data far into the 
future is less reliable and tend to change, i sometimes have to run mfdb 
manually to refresh the next few days to avoid unexpected conflicts that 
isn't really a conflict at all.

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

computer is mostly idle with little or no disc access.
also i don't think the db is the source of the problems.
running just xmltv with same config file is very quick, so it is 
definitely not xmltvs fault it takes forever.


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

looks like it is doing just that.

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

new log attached, this time with:
--sourceid=1 --refresh 0 -v xmltv,channel,system
and as you can see there is loads of stuff about metadata and i suspect 
this is the cause of the slowness.

UPDATE:
apparently i was not allowed to attach the file in question and my first 
try at sending this mail got stuck pending moderator approval.
so this time i'm skipping the log file.
where do i put the logfile so you can look at it? it is 81.2Kb compressed.



More information about the mythtv-dev mailing list