Improving speed of EPG retrieval from MythTV backend

[andrewgreenwood]

Is there any way to possibly make the MythTV PVR add-on retrieve EPG data from the backend faster? I tend to set it to only load a couple of days of EPG data but on start-up it seems to take a minute or so to load.

I see that Kodi's PVR interface seems to request this by making calls to GetEPGForChannel, specifying a channel and start/end time. However MythTV's GetProgramGuide API looks like it is capable of requesting information for multiple channels in one call.

This is really only an issue when Kodi is starting up (for some reason it never seems to store the EPG database regardless of whether I tell it to or not). If there's some way to check how many days of EPG Kodi wants, on startup the add-on could request all of the EPG data for all channels for that time period (so, basically pre-fetch it for Kodi's individual calls to GetEPGForChannel). Once Kodi has retrieved all the initial EPG data it wants (unsure how this would be determined - a period of EPG request inactivity?), just go back to the current behaviour.

It's a minor issue, just with the frequency which I have to restart Kodi (or it restarts itself), it can be quite frustrating to wait for it to finish populating the guide on start-up. I could remove some channels of course. I'd also like to have more days of EPG so loading it faster would be great.

I might try and have a look into how to do this once I get more familiar with how everything works.

There seems to be a side-effect of the slow EPG loading: Obviously, with debugging enabled (like I have now) it takes even longer (a couple of minutes perhaps?) so I've reduced the amount of data loaded to 1 day. However, on startup, Kodi restarts itself about 70% through loading the EPG data, repeatedly. I can prevent this by playing/stopping a channel every 20-25% until it finishes.

Whenever the restart happens I get a crash log showing an assertion relating to a mutex:

Thread 1 (Thread 0x60064370 (LWP 7816)):
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x74e46184 in __GI_abort () at abort.c:79
#2 0x74e532c8 in __assert_fail_base (fmt=0x74f4a298 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x76f72ef0 "INTERNAL_SYSCALL_ERRNO (e, __err) != EDEADLK || (kind != PTHREAD_MUTEX_ERRORCHECK_NP && kind != PTHREAD_MUTEX_RECURSI
VE_NP)", assertion@entry=0x60064370 "\001", file=0x76f73130 "pthread_mutex_lock.c", file@entry=0x76f73028 <PRETTY_FUNCTION.12300> "__pthread_mutex_lock_full", line=422, line@entry=1995911472, function=function@entry=0x76f73028 <PRE
TTY_FUNCTION.12300> "__pthread_mutex_lock_full") at assert.c:92
#3 0x74e53378 in __GI___assert_fail (assertion=0x60064370 "\001", file=0x76f73028 <PRETTY_FUNCTION.12300> "__pthread_mutex_lock_full", line=1995911472, line@entry=422, function=0x76f73028 <PRETTY_FUNCTION.12300> "__pthread_mutex
_lock_full") at assert.c:101
#4 0x76f67b6c in __pthread_mutex_lock_full (mutex=0x60064370) at pthread_mutex_lock.c:420
#5 0x009aa728 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
############# END STACK TRACE ###############

Of course, the above could just be Kodi not liking something else, but it doesn't happen once the EPG has finished loading so I wondered if it's timing out waiting for something and then deciding something's wrong so it needs to restart.

[janbar]

• First point: how long get the full processing of the API call "GetProgramList" (cppmyth::GetProgramGuide) for one channel ?
  I ran my testing tool for libcppmyth on my mediacenter connected to the backend (ethernet 100Mb), and really it is short about 1 second to retrieve 1 channel for 10 days. See the log below:

    processing guide TF1: 1542534503
    processing completed: 1542534503
  
    processing guide France 2: 1542534503
    processing completed: 1542534504
  
    processing guide F3 Paris Ile-de-Fran: 1542534504
    processing completed: 1542534505
  
    processing guide M6: 1542534507
    processing completed: 1542534507
  
    processing guide Arte: 1542534507
    processing completed: 1542534508
  
    processing guide TFX: 1542534509
    processing completed: 1542534510
    ....
  

Retrieving EPG for 10 days of my 32 channels gets 21 seconds.
And retrieving for 3 days gets 8 seconds.
And retrieving for 1 days gets 3 seconds.
The response time seems to be linear regarding the number of rows selected. In this case the round-trip time is (3*10-21)/10 = 0.9 seconds by call.

[janbar]

I tested the time consumed by Kodi to retrieve my EPG (32 channels / 10 days):

• Disabling cache in local database, it lasted 22 seconds
• Enabling cache in local database, it lasted 26 seconds

So nothing bad here.

[andrewgreenwood]

Thanks very much for testing this so soon and in this much detail.

Which version of MythTV are you using? I'm on 0.28 still.

I've just measured times (using my desktop PC). We have quite a few channels here in the UK, I'm intending on removing a few of these as certain ones were auto-detected but have no content, and others aren't interesting, but basically at the moment MythTV has 127 channels.

1 day of EPG: 21 seconds to load
2 days of EPG: 67 seconds to load
3 days of EPG: 88 seconds to load
7 days of EPG: 199 seconds to load

This is all with the cache disabled. For some reason I've never got the cache to work on the Raspberry Pi (it always wants to do a full load) - that said, I haven't tried it on Leia yet.

One thing that is likely different with my setup is I have my MythTV database on a separate system (since I'm using the backend diskless, it seemed more reasonable to have DB requests go over the network rather than filesystem accesses where possible). It's a gbit network so bandwidth shouldn't be an issue. I do see that the CPU usage for the DB process does go quite high when pulling down the EPG though.

I'll see if I can get the cache working - that may be the simple answer. It seems any delays are likely to be on the MythTV backend or database side though.

Thanks again for checking this.

[janbar]

Interesting: You get 4 times more channels than my benchmark, and you get 11 times more time !

• 88 / 8 / (127/32) = 2.75 slower than my setup.

My setup uses low cpu power consumption, and DD for storage are low-end.
Mediacenter:

• Board QC5000M-ITX / CPU AMD A4-5000 APU with Radeon(TM) HD Graphics (~15 watts)
• RAM 8GB
• SSD 40GB
• Ubuntu server 16.04 / X11 / aewm / Kodi 18-938146c9

Backend: (Also used to store/share my files: tax receipt ;-) , photos, music, videos ...)

• Board C2750D4I / CPU Intel(R) Atom(TM) CPU C2750 @ 2.40GHz (~20 watts)
• RAM 16GB
• root is SSD 40GB
• storage for files and db: logical raid-5 (md): 5 x DD2.5" 1TB
  All DD for the storage are low-end and recovered from low cost usb boxes.
• OpenSuse 42.3 / mythbackend 30-e50d9c7d / mysql 5.6.42

I use mythtv 30, but 0.28 or 29 perform the same. That's just to keep ahead.

Internally the libcppmyth does more api calls than you could imagine: I configured a fetch size limit. Actually is 100. but for EPG I could increase to 500 to avoid round-trip. We have to make some benchmark with your setup...

[janbar]

To increase the fetch size you can apply the diff on the source file lib/cppmyth/src/mythwsapi.cpp as below:

--- a/lib/cppmyth/src/mythwsapi.cpp
+++ b/lib/cppmyth/src/mythwsapi.cpp
@@ -32,7 +32,7 @@
 #include "private/uriparser.h"
 
 #define BOOLSTR(a)  ((a) ? "true" : "false")
-#define FETCHSIZE   100
+#define FETCHSIZE   500

Testing this change with my setup, I get 20% better on 10 days (17 sec), and 0% on 3 days.

[andrewgreenwood]

Using mostly a low-power setup here too :)

I'm using 2 Pi's as media centres (main one with Leia, other one in a different room with Krypton). One is powered by a PoE adapter, both boot up over TFTP/NFS so run without microSD cards.

My MythTV backend is a system attached to the wall in the attic so it's quite close to the antenna:
Board: Supermicro X7SPE-H (I think?) with Atom D510 CPU
RAM: 2GB (seems enough, very little swap happens)
Disk: None (PXE boot, everything is stored on NFS including root and swap)
OS: Debian 8

The recordings are stored on my main server which runs several virtual machines (Xen) - one for file storage, one for database, one for network booting, various unrelated things... This system is using a C2750D4I board (the same as you are using) with 32GB RAM (different amounts per VM). Disks on the VM host are 4x 4TB in raid10 configuration (md) with a few older disks attached for backups etc. (I think I have 8 in total?) These are mainly WD Red drives - I wanted low CPU power but good I/O speed. Host and VMs are running a mixture of Debian 8 and 9. Power usage for that server plus a OPNsense-based embedded system and PoE-enabled network switch comes to about 100w.

I'll try the suggested change later on and see if it helps. I do wonder if the backend is stressing the DB somehow though.

[andrewgreenwood]

Haven't yet tried with your diff (been busy with other things and still getting familiar with how to build things with LibreELEC's build system), but just wanted to note some additional findings.

The standard Kodi "Guide" option "Don't cache in local database" was enabled on my Pi. Personally I think this option should be reversed ("Cache" instead of "Don't cache") but that's obviously something I'd have to raise against Kodi since it's nothing to do with your add-on :)

Anyway I turned off that option so that it enabled the cache. Loading the guide became MUCH faster, however it triggered the mutex issue I described earlier upon every restart, so I've had to disable the option again. So now I'm wondering if that is also a Kodi issue. I've re-built the entire LibreELEC with debugging options turned on to try and gain some more info.

I'm tempted to just remove most of the channels we don't watch to work around this, but I think it's important to fix it. Would deleting the channels from Kodi work or do I have to do this from the MythTV backend? I'd like to poke at this with a dedicated Pi with all channels available, while having my "production" ones being free of the issue.

[janbar]

I added a branch where the addon grabs guide in bulk mode. Ouahhh go fast. It takes 1/3 of time.

[janbar]

But I meet an issue with the MythTV api: we can't limit the number of channel selected as I expected. So all channels are gathered. It could cause a memory issue in a setup with hundreds channels. To be tested...

Also the api request time cannot be too long and any network timeout will cause a failure. Maybe adding an advanced setting to enable it for expert user.

[andrewgreenwood]

That sounds great - I'll give it a try a little later. The guide data shouldn't be too big - it's just text data I think? Maybe useful to log the overall size when receiving in bulk. I doubt it will be more than a couple of MB.

I built the latest LibreELEC yesterday and am running that now. The mutex issue seems to be gone - so, without the cache it was just taking some time to load the EPG, and with the cache it is really fast. It's a bit frustrating that I couldn't pinpoint what exactly was causing that problem and I can't find a specific issue or commit that fixes it.

[janbar]

You could try the branch https://github.com/janbar/pvr.mythtv/tree/opt_guide , which contains patches to enable bulk loading for EPG. To enable the feature, you have to check the option "Enable bulk load for EPG" in advanced settings of the addon.
The addon will adjust the bulk fetch size according to the range of data requested to avoid any http timeout.

[andrewgreenwood]

I've just got round to testing this and the results are the opposite of what I'd expected, strangely - in my case it actually seems much slower! After a few minutes it is less than 5% done. After disabling the "bulk load" option, it went back to loading the guide at the original speed.

I'm wondering if this might require a newer backend to support it fully? I'm using MythTV 0.28 (I have been trying to set up MythTV 29 for the past 2 days or so and have had a lot of problems setting it up).

[janbar]

I pushed a commit to show more log. Please can you retry with it ?
That's really strange because the api 0.28 is same as 29 for the guide service.

A sample of the log output:

23:07:36.831` T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: Start BULK loading for period [2018-11-26T23:07:36,2018-12-07T23:07:36]
23:07:36.832 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: request index(0) count(25)
23:07:43.477 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: content parsed
23:07:43.672 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: received count(25)
23:07:43.675 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: request index(25) count(25)
23:07:45.295 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: content parsed
23:07:45.346 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: received count(7)
23:07:45.347 T:123145344192512  NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: End loading (32,6522)

It is normal that the progress stop on first channel until it load all epg data in a bulk, then the progress will go very fast because it will load data already cached in memory.

[andrewgreenwood]

I'm seeing a lot of socket timeouts (each timeout is after 10 seconds). Here's an example:

23:03:23.956 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: Start BULK loading for period [2018-11-27T22:58:55,2018-11-30T22:58:55]
23:03:23.956 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: request index(0) count(50)
23:03:34.062 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)ReceiveData: socket(0x5cee5fd4) timed out (0)
23:03:40.790 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: content parsed
23:03:40.949 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: received count(50)
23:03:40.951 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: request index(50) count(50)
23:03:50.955 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)ReceiveData: socket(0x5cea5d0c) timed out (0)
23:03:57.359 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: content parsed
23:03:57.516 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: received count(50)
23:03:57.519 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: request index(100) count(50)
23:04:02.701 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: content parsed
23:04:02.748 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: (CPPMyth)GetProgramGuide2_2: received count(14)
23:04:02.750 T:1553806192  NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: End loading (114,9379)

I'm also seeing it look up guide data from 2017:

23:04:02.796 T:1633010544 NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: Start BULK loading for period [2017-09-24T19:58:00,2017-09-24T21:02:00]

23:04:03.268 T:1633010544 NOTICE: AddOnLog: MythTV PVR Client: GetProgramGuide: Start BULK loading for period [2017-09-29T12:13:00,2017-09-29T13:02:00]

I've noticed this before when I was first investigating the EPG loading speed and figured it might be something to do with recordings that I still have. Looking in my recordings directory, I do have recordings from those dates so that's probably what those are.

[janbar]

That improves your epg loading too: 39 seconds. Without the patches you took 88 seconds. But you found an other issue. It seems kodi uses epg call to retreive program info for recordings. Maybe some others backend don't provide the program data with the recording. This behavior breaks my expectations and finally we can't bulk load epg data using the existing pvr api call GetEPGForChannel.

[andrewgreenwood]

That was just one example part of the log to show the timeout :) I let it run for several minutes. It seemed to be increasing the time period it was collecting data for - sometimes it would succeed but there were several timeouts.

I can send you a full log if you need me to.

Maybe it could only do bulk EPG query when the time is greater or equal to the start date in the guide settings (i.e. how many previous days to get EPG for)?

Without this change, enabling the cache does now make it really fast for me anyway as Kodi Leia no longer restarts during cache load. So it may not be essential to have this change after all.

Thanks very much for looking into this possibility anyway!