[mythtv-users] Mythfilldatabase taking FOREVER

Larry Kennedy lunchtimelarry at gmail.com
Sun Jun 5 02:45:51 UTC 2022 

On Sat, Jun 4, 2022 at 10:27 PM Larry Kennedy <lunchtimelarry at gmail.com>
wrote:

>
>
> On Sat, Jun 4, 2022 at 10:21 PM Larry Kennedy <lunchtimelarry at gmail.com>
> wrote:
>
>>
>>
>> On Sat, Jun 4, 2022 at 9:33 PM Larry Kennedy <lunchtimelarry at gmail.com>
>> wrote:
>>
>>> Recently, I'm noticing that mythfilldtabase is taking something like 12
>>> hours to finish. I know we had some issues with SD and the backend
>>> maintenance, so not sure if that has been fully resolved.
>>>
>>> I'm on Ubuntu 18.04 and mythtv v30.0.  I use the sdjson_sqlite grabber
>>> v1.109 and xmltv v0.5.70.  I only have about 100 channels set as "selected"
>>> in the sqlite database.
>>>
>>> Mythfilldatabase sits forever on the message "pruning local database"
>>>
>>> I see very low CPU utilization on a four vCPU i7 VM with 8GB RAM.
>>>
>>> Any thoughts on why this is taking so long?
>>>
>>> Larry
>>>
>>
>> More log details:  With system,xmltv logging turned on, I see that it is
>> taking up to 20 seconds per program to insert:
>>
>> 2022-06-04 22:15:41.833789 I  Removing existing program:
>> 2022-06-17T00:00:00Z - 2022-06-17T00:51:00Z
>> I114759.json.schedulesdirect.org Dark Winds
>> 2022-06-04 22:15:42.257005 I  Inserting new program    :
>> 2022-06-17T00:00:00Z - 2022-06-17T00:51:00Z
>> I114759.json.schedulesdirect.org Dark Winds
>> 2022-06-04 22:15:47.151660 I  Removing existing program:
>> 2022-06-17T00:51:00Z - 2022-06-17T01:42:00Z
>> I114759.json.schedulesdirect.org Dark Winds
>> 2022-06-04 22:15:47.784472 I  Inserting new program    :
>> 2022-06-17T00:51:00Z - 2022-06-17T01:42:00Z
>> I114759.json.schedulesdirect.org Dark Winds
>> 2022-06-04 22:15:54.196309 I  Inserting new program    :
>> 2022-06-21T03:11:00Z - 2022-06-21T03:56:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:16:17.185399 I  Inserting new program    :
>> 2022-06-21T03:56:00Z - 2022-06-21T04:41:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:16:33.053704 I  Inserting new program    :
>> 2022-06-21T04:41:00Z - 2022-06-21T05:26:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:16:50.177901 I  Inserting new program    :
>> 2022-06-21T05:26:00Z - 2022-06-21T06:19:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:17:04.171445 I  Inserting new program    :
>> 2022-06-21T06:19:00Z - 2022-06-21T07:05:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:17:17.125686 I  Inserting new program    :
>> 2022-06-21T07:05:00Z - 2022-06-21T07:50:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:17:40.029102 I  Inserting new program    :
>> 2022-06-21T07:50:00Z - 2022-06-21T08:35:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:17:58.823123 I  Inserting new program    :
>> 2022-06-21T08:35:00Z - 2022-06-21T09:17:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:18:15.070319 I  Inserting new program    :
>> 2022-06-21T09:17:00Z - 2022-06-21T10:00:00Z
>> I114759.json.schedulesdirect.org Fear the Walking Dead
>> 2022-06-04 22:18:35.823610 I  Inserting new program    :
>> 2022-06-21T10:00:00Z - 2022-06-21T10:51:00Z
>> I114759.json.schedulesdirect.org The Walking Dead
>> 2022-06-04 22:18:59.061001 I  Inserting new program    :
>> 2022-06-21T10:51:00Z - 2022-06-21T11:40:00Z
>> I114759.json.schedulesdirect.org The Walking Dead
>> 2022-06-04 22:19:18.485766 I  Inserting new program    :
>> 2022-06-21T11:40:00Z - 2022-06-21T12:40:00Z
>> I114759.json.schedulesdirect.org The Walking Dead
>>
>> Does that seem right?
>>
>
> Sorry for the repeated messages, but here is more of the log leading up to
> the messages above:
>
> 2022-06-04 22:11:36.099986 N  Enabled verbose msgs:  general system xmltv
> 2022-06-04 22:11:36.099991 N  Setting Log Level to LOG_INFO
> 2022-06-04 22:11:36.110650 I  Setup Interrupt handler
> 2022-06-04 22:11:36.110657 I  Setup Terminated handler
> 2022-06-04 22:11:36.110661 I  Setup Segmentation fault handler
> 2022-06-04 22:11:36.110666 I  Setup Aborted handler
> 2022-06-04 22:11:36.110670 I  Setup Bus error handler
> 2022-06-04 22:11:36.110674 I  Setup Floating point exception handler
> 2022-06-04 22:11:36.110677 I  Setup Illegal instruction handler
> 2022-06-04 22:11:36.110683 I  Setup Real-time signal 0 handler
> 2022-06-04 22:11:36.110686 I  Setup Hangup handler
> 2022-06-04 22:11:36.110762 N  Using runtime prefix = /usr
> 2022-06-04 22:11:36.110764 N  Using configuration directory =
> /home/myuser/.mythtv
> 2022-06-04 22:11:36.110807 I  Assumed character encoding: en_US.UTF-8
> 2022-06-04 22:11:36.111004 I  Empty LocalHostName. This is typical.
> 2022-06-04 22:11:36.111008 I  Using a profile name of: 'myhost' (Usually
> the same as this host's name.)
> 2022-06-04 22:11:36.111043 I  Start up testing connections. DB localhost,
> BE , attempt 0, status dbAwake, Delay: 2000
> 2022-06-04 22:11:36.111663 I  Added logging to the console
> 2022-06-04 22:11:37.118747 N  Setting QT default locale to en_US
> 2022-06-04 22:11:37.118754 I  Current locale en_US
> 2022-06-04 22:11:37.118779 N  Reading locale defaults from
> /usr/share/mythtv//locales/en_us.xml
> 2022-06-04 22:11:37.121802 I  Loading en_us translation for module
> mythfrontend
> 2022-06-04 22:11:37.122930 I  Current MythTV Schema Version (DBSchemaVer):
> 1350
> 2022-06-04 22:11:37.124309 I  MythCoreContext::ConnectCommandSocket():
> Connecting to backend server: 192.168.1.200:6543 (try 1 of 1)
> 2022-06-04 22:11:37.125053 I  MythCoreContext::CheckProtoVersion(): Using
> protocol version 91 BuzzOff
> 2022-06-04 22:11:37.125480 I  Opening blocking connection to master backend
> 2022-06-04 22:11:37.191341 I  Updating source #2 (sd) with grabber
> tv_grab_zz_sdjson_sqlite
> 2022-06-04 22:11:37.191711 I  Found 1357 channels for source 2 which use
> grabber
> 2022-06-04 22:11:37.191899 I  Starting process manager
> 2022-06-04 22:11:37.192755 I  Starting IO manager (read)
> 2022-06-04 22:11:37.192886 I  Managed child (PID: 589) has started! *
> command=tv_grab_zz_sdjson_sqlite --capabilities, timeout=25
> 2022-06-04 22:11:37.193059 I  Starting process signal handler
> 2022-06-04 22:11:37.193097 I  Starting IO manager (write)
> 2022-06-04 22:11:37.594832 I  Managed child (PID: 589) has exited!
> command=tv_grab_zz_sdjson_sqlite --capabilities, status=0, result=0
> 2022-06-04 22:11:37.643913 I  Grabber has capabilities: baseline
> manualconfig preferredmethod lineups apiconfig
> 2022-06-04 22:11:37.644788 I  Managed child (PID: 591) has started! *
> command=tv_grab_zz_sdjson_sqlite --preferredmethod, timeout=15
> 2022-06-04 22:11:38.066778 I  Managed child (PID: 591) has exited!
> command=tv_grab_zz_sdjson_sqlite --preferredmethod, status=0, result=0
> 2022-06-04 22:11:38.094620 I  Grabber prefers method: allatonce
> 2022-06-04 22:11:38.095203 I  XMLTV config file is:
> /home/myuser/.mythtv/sd.xmltv
> 2022-06-04 22:11:39.365187 I  Grabber Command: nice
> tv_grab_zz_sdjson_sqlite --config-file '/home/myuser/.mythtv/sd.xmltv'
> --output /tmp/mythKBJFcR
> 2022-06-04 22:11:39.365192 I  ----------------- Start of XMLTV output
> -----------------
> 2022-06-04 22:11:39.366077 I  Managed child (PID: 593) has started! *
> command=nice tv_grab_zz_sdjson_sqlite --config-file
> '/home/myuser/.mythtv/sd.xmltv' --output /tmp/mythKBJFcR, timeout=0
> 2022-06-04 22:11:59.161162 I  Managed child (PID: 593) has exited!
> command=nice tv_grab_zz_sdjson_sqlite --config-file
> '/home/myuser/.mythtv/sd.xmltv' --output /tmp/mythKBJFcR, status=0, result=0
> 2022-06-04 22:11:59.182220 I  ------------------ End of XMLTV output
> ------------------
> 2022-06-04 22:12:04.736720 I  Managed child (PID: 595) has started! *
> command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, timeout=0
> 2022-06-04 22:12:04.777034 I  Managed child (PID: 595) has exited!
> command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, status=0, result=0
> 2022-06-04 22:12:04.798490 I  Managed child (PID: 597) has started! *
> command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, timeout=0
> 2022-06-04 22:12:04.939212 I  Managed child (PID: 597) has exited!
> command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, status=0,
> result=0
> 2022-06-04 22:12:10.832530 I  Cardutil: HDHomeRun Cablecard Present.
> 2022-06-04 22:12:10.851533 I  Cardutil: HDHomeRun Cablecard Present.
> 2022-06-04 22:12:10.870566 I  Cardutil: HDHomeRun Cablecard Present.
> 2022-06-04 22:12:10.873583 N  Match found for xmltvid
> I102337.json.schedulesdirect.org to channel QVC3 HD (20925)
> 2022-06-04 22:12:10.875195 N  Match found for xmltvid
> I104089.json.schedulesdirect.org to channel Olympic Channel (20822)
> 2022-06-04 22:12:10.876813 N  Match found for xmltvid
> I114759.json.schedulesdirect.org to channel AMC + (20892)
> 2022-06-04 22:12:10.878373 N  Match found for xmltvid
> I19578.json.schedulesdirect.org to channel WRCDT (WRC-DT) (20804)
> 2022-06-04 22:12:10.879904 N  Match found for xmltvid
> I19579.json.schedulesdirect.org to channel WJLADT (WJLA-DT) (20807)
> 2022-06-04 22:12:10.881558 N  Match found for xmltvid
> I19580.json.schedulesdirect.org to channel WUSADT (WUSA-DT) (20809)
> 2022-06-04 22:12:10.883091 N  Match found for xmltvid
> I19581.json.schedulesdirect.org to channel WETADT (WETA-DT) (20800)
> 2022-06-04 22:12:10.884677 N  Match found for xmltvid
> I20367.json.schedulesdirect.org to channel WTTGDT (WTTG-DT) (20805)
> 2022-06-04 22:12:10.886282 N  Match found for xmltvid
> I26195.json.schedulesdirect.org to channel WPXWDT (WPXW-DT) (20813)
> 2022-06-04 22:12:10.887903 N  Match found for xmltvid
> I31046.json.schedulesdirect.org to channel MOTORTREND HD (20870)
> 2022-06-04 22:12:10.889545 N  Match found for xmltvid
> I32537.json.schedulesdirect.org to channel NBC Sports Washington HD
> .....
>

Does it make sense that it is removing and then inserting the same
program?  This log entry suggests wasted effort, unless I'm missing
something:

2022-06-04 22:43:40.196509 I  Removing existing program:
2022-06-09T03:00:00Z - 2022-06-09T03:35:00Z I19580.json.schedulesdirect.org
WUSA 9 News at 11pm
2022-06-04 22:43:40.516899 I  Inserting new program    :
2022-06-09T03:00:00Z - 2022-06-09T03:35:00Z I19580.json.schedulesdirect.org
WUSA 9 News at 11pm
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20220604/23db9a52/attachment-0001.htm>

More information about the mythtv-users mailing list