[metaron]

My normal set-up is mythtv-0.27.4_p20141018 on a gentoo box (Core2/4GB) and Openelec 4.2.1 on raspberry Pi as two frontends. Default 'confluence' skin. I don't use local Kodi files storage, everything is mythtv on the server.
I have a large mythtv database ~1000 recordings split into 9 recording groups:
Default - 196, Enterprise - 96, Films - 190, LiveTV - 12,
Murder Mystery - 86, Nature - 135, Star Trek - 86, Stargete-SG1 - 252, Strictly - 2.
Mythtv looks up extra metadata for me automatically.

Accessing the recordings list was never fast, but this combination was usable: 2-5 seconds to open the initial list, a similar time to open each group and quicker for the title folders. I generally avoid the 'All Recordings' folders due to large number of files, but also much longer load times.

Today I tried Openelec 5RC1 which uses the new plugin (1.9.27)

It took so long to open the recordings list that for the 1st two attempts I thought Kodi had crashed (no 'Working' dialog appeared, the remote did nothing) and I gave up and power cycled the Pi. Eventually after sshing into the box and confirming with top that kodi was 'busy' I left it long enough to finish, and the recordings list came up and could be browsed - slowly.

I can think of five things which might be the culprit / making it worse:
1) OpenElec 4.2.1 has a ulimit on files of 1024, 4.97.1 added "set LimitNOFILE to 16384": Icons for each recording are now loading successfully and the poor Pi simply can't cope with the data (I always wondered why some icons didn't load before!) - this might be considered a 'skin' issue.
2) I've chosen a sub-optimal 'Group recordings by title' option in the client settings - probably 'Only for series' is what I want.
3) There is a conflict/performance bottleneck with this particular combination of backend/pvr.mythtv client (I've seen this with the old client in the past)
4) The new backend API this plugin is using is simply slower/more buggy than the old API (maybe this will be improved in 0.28?) - an issue for the mythtv forum probably.
5) The new pvr.mythtv plugin isn't as optimized as the old one for lots of recordings / long lists.

Unfortunately at the moment this combination is unusably slow so it's back to 4.2.1 for now. I will investigate different settings/combinations and post back if I find something that works (it may be next weekend before I do), but was wondering if the users on this forum have had similar problems and hopefully some success at resolving them!

Even better would be if something could be done in the new client to reduce initial load time before the list appears/becomes browsable. There isn't much/any metadata displayed at the Recordings and Group levels and the recordings list loads into memory at startup so it ought to be feasible. (You can probably tell I know nothing about the underlying data structures).

[metaron]

Some more quick tests (pvr.mythtv version = 1.9.27):
With 'Group recordings by title' set to 'Only for series' takes 65 seconds to enter the 'Recordings' screen (no 'waiting' prompt, just the blue background) the first time after powering up the Pi. (This Pi is powered up with the TV, so once per session)
Subsequent entry to the group folders takes <1 second. Subsequent entry into the individual series folders is quick, but menu navigation while metadata loads from the server is sluggish. Once the metadata is cached locally seems to be much more responsive, although when background fan-art applies navigating up and down the list is sluggish (Similar to 4.2.1/Gotham but slightly slower).
2-5 second delay with a 'black' screen after stopping video playback before the recordings list returns to the screen. (Similar to OpenElec 4.2.1 / Gotham, maybe slightly slower)
Returning to the home screen and then entering the 'Recordings' screen a second time in a power-up sequence is almost instantanious :-).
More tests (without re-booting the Pi):
Settings->Addins->PVR Addins->MythTv->Configure->Advanced->Group recordings by title->Allways
Back to home screen, TV->Recordings - takes 65 seconds
Back to home screen, TV->Recordings - instantanious
Settings->...->Only for series
Back to home screen, TV->Recordings - takes 65 seconds
Back to home screen, TV->Recordings - instantanious
->Films, browse up and down list (page at a time). While metadata loading - Kodi 'hangs' showing 1/2 the folder icon, 1/2 the icon for back to the future III. Eventually the list recovers. On re-entering the Film folder, metadata has now been loaded for the items on that page.

[janbar]

Hi,

My config is: Intel® Atom™ CPU D525 @ 1.80GHz

I have ~200 recordings (1/5 of yours) and entering in Recordings screen get less than 1 sec for the first time ! I could think you should wait 1~2 secondes, no more for ~1000 items. Where do you get patience to wait 65 sec ?
Also this time (65 sec for you) is consumed to transfer data from addon to pvr manager, not to get data from backend ! All recordings data have been collected from backend at startup before you could have any hands.
Really there is something obvious there. Please let me know if you catch the root cause.

EDIT: Root cause could be your local storage too slow. During data transfer to pvr manager, kodi re-cache artworks. What kind of local storage have you ?

Note: My local storage is a flash drive 64GB to store OS with /home. Last generation of SDram are very fast too.

[janbar]

To really compare my old version (called cmyth) to my new version you should use same XBMC.
So you can checkout compiled version of new addon for RPI-arm XBMC-13 from my cloud: https://www.canneasucre.org/owncloud/pub...=%2Fgotham

[metaron]

Thanks Janbar.
I tried your gotham pi addon on my 4.2.1 Openelec build.
It takes about 5 seconds to open the recordings window, so it seems that the biggest part of the problem is related to Helix.
Experimented a bit more and managed to watch 1 hour of x264 1080 encoded video without problems, which is very encouraging.
Generally navigating the recordings menus is a bit slower than the cmyth addin, with the 'progress' spinner coming up quite a bit so it's back to the cmyth addon for now on Gotham.
I'm a big fan of 'only for series' though as it removes the extra layer from my 'Films' directory. The new addon also seems to make a far better job of getting all the icons - cmyth shows 'missing icon' icons for lots of my recordings.

I tried OpenElec 4.97.2 which is Helix RC3 based this weekend and it still takes 65 seconds for the recordings window to show the 1st time around. I had a go with the debug log running.
On selecting 'Recordings' the debug readout froze. Once the recording window arrived it started jumping about the screen and updating %CPU again. Repeated a couple of times. Similar 65 seconds before the screen appears, although the log entries show things happening sooner than this, so maybe it is just the display that is lagging behind. 2nd time entering the recordings window is almost immediate as before.

Here's a pastebin example: My Log File
I re-started the PI before starting the tail. The sequence of events is:
Selecting 'Recordings'
23:20:15 214.711975 T:3042615296 DEBUG: OnKey: 11 (0x0b) pressed, action is Select
Several of these appear in the log:
23:20:19 218.275681 T:2813924416 DEBUG: AddOnLog: MythTV PVR Client: Process: File is empty: type: 2, local: /storage/.kodi/userdata/addon_data/pvr.mythtv/cache/coverart/8940_1396113900_000
23:20:19 218.276047 T:2813924416 DEBUG: AddOnLog: MythTV PVR Client: Process: Delayed recache file: type: 2, local: /storage/.kodi/userdata/addon_data/pvr.mythtv/cache/coverart/8940_1396113900_0002
As soon as recordings screen appears, select 'back'
23:21:18 278.123779 T:3042615296 DEBUG: OnKey: menu (0xd8) pressed, action is Back
As soon as Home screen appears, select down, and Recordings
23:21:20 279.655304 T:3042615296 DEBUG: OnKey: 167 (0xa7) pressed, action is Down
23:21:21 280.349579 T:3042615296 DEBUG: OnKey: 11 (0x0b) pressed, action is Select
As soon as recordings screen appears, select 'back'
23:21:23 282.756927 T:3042615296 DEBUG: OnKey: menu (0xd8) pressed, action is Back

I'm using a 2GB SanDisk Class 2 SD card by the way, although I doubt this would explain the 65 seconds!

Any suggestions what / where I should try next?

[metaron]

OK janbar, some updates:

• Tried deleting the 'empty files' to see if that would change anything, both on the mythtv server and the local SD card. It didn't.
  
  
• Tried your new addon (1.10.1) and disabled the icons (thanks). Faster scrolling down lists with icons disabled, but it still takes the same time to load the recordings screen 1st time.
  
  
• Deleted some recordings (now 800 ish) - no obvous change.
  
  
• Tried moving the storage directory onto a 4GB Cruzer USB stick: 'loading EPG from database' is a little faster, but it still takes a similar time to load the recordings screen the 1st time.
  
  
• Tried your 1.9.22-28 addon on OE 4.2.1 again. Compared to the old cmyth addon it is noticeably slower, especially when loading the 'films' directory for the 1st time. The standard cmyth version which comes with OE 4.2.1 is much more snappy. 1.10.0 / 1.10.1 is much faster on helix (once the recordings screen has been loaded).
  

I suspect whatever 4.97.2 (helix) does in one go on 1st entry to the recordings screen is done in smaller chunks on 4.2.1 (gotham) when lower level menus are presented. (Shame it can't do it at the end of the PVR startup sequence. 65 seconds then wouldn't be anywhere near as bad)

Does anyone have experience using 1.10.1 with a raspberry pi helix build other than OE 4.97.2 or 4.97.1?
(I tried raspbmc briefly, but it installed Gotham by default and the OE 4.2.1 compiled addon couldn't find one of the dlls it needed - will try again over Christmas)

Can anyone suggest something I could try next?

[MikeB2013]

OK janbar, some updates:

• Tried deleting the 'empty files' to see if that would change anything, both on the mythtv server and the local SD card. It didn't.
  
  
• Tried your new addon (1.10.1) and disabled the icons (thanks). Faster scrolling down lists with icons disabled, but it still takes the same time to load the recordings screen 1st time.
  
  
• Deleted some recordings (now 800 ish) - no obvous change.
  
  
• Tried moving the storage directory onto a 4GB Cruzer USB stick: 'loading EPG from database' is a little faster, but it still takes a similar time to load the recordings screen the 1st time.
  
  
• Tried your 1.9.22-28 addon on OE 4.2.1 again. Compared to the old cmyth addon it is noticeably slower, especially when loading the 'films' directory for the 1st time. The standard cmyth version which comes with OE 4.2.1 is much more snappy. 1.10.0 / 1.10.1 is much faster on helix (once the recordings screen has been loaded).
  

I suspect whatever 4.97.2 (helix) does in one go on 1st entry to the recordings screen is done in smaller chunks on 4.2.1 (gotham) when lower level menus are presented. (Shame it can't do it at the end of the PVR startup sequence. 65 seconds then wouldn't be anywhere near as bad)

Does anyone have experience using 1.10.1 with a raspberry pi helix build other than OE 4.97.2 or 4.97.1?
(I tried raspbmc briefly, but it installed Gotham by default and the OE 4.2.1 compiled addon couldn't find one of the dlls it needed - will try again over Christmas)

Can anyone suggest something I could try next?

Just to confirm the long delay pause:

I am seeing a similar effect, although in my case the delay is just under 30 seconds on my pi running Raspbmc Kodi (14.0-RC3 Git:2014-12-16-5b03e6f-dirty) with mythtv pvr 1.10..1 (built from source) with 581 recordings.

Kodi build for Raspbmc from Post #1731 http://forum.kodi.tv/showthread.php?tid=176043&page=116

The debug logs don't show anything, apart from the usual pvr.mythtv Housekeeping task running many times in the "pause", about once per second.

Mike

[metaron]

Some more data points with 840 recordings:

• Std Rasbmc O/Clock setting: arm_freq=850; core_freq=375; force_turbo=1 - takes 36 seconds
  
• Std OpenElec no O/Clock i.e. arm_freq=700; core_freq=250; force_turbo=0 - takes 51 seconds
  

Tried twice to make sure. As nothing else changed, it looks looks like we're CPU limited...
My money is on an inefficient sort algorithm somewhere (won't show up on something with more horsepower).

[metaron]

I've managed to compile OpenELEC and the mythtv addon from source.
I tried adding some log statements to 'GetRecordings' in 'pvrclient-mythtv.cpp' as that looked hopeful but it seems to run when the recordings are loaded at the start, rather than when the menu is 1st presented.

I thought it would be worth attacking the problem from the other end so to speak, but I'm not famailiar with kodi internals and my cpp is poor to non-existent, so it's a bit like looking for a needle in a haystack.

There isn't someone out there who could point me in the right direction is there? (I'm currently fumbling around in 'kodi-14-xxxxx/xbmc/pvr/windows/GUIWindowPVRRecordings.cpp')

[frank.grant]

Hi, I have the same problem after I updated to Kodi.
I have a Raspberry Pi model B.
It is running Raspbian Raspbmc Kodi compiled Dec 24 Kernel 3.12.31
I have 759 recordings in default

The old XBMC cmyth addon worked fine. This new MythTV addon is very slow when going to recordings.

[metaron]

OK after some rummaging around in the code and adding log statements, it wasn't a sort order thing in the GUI section as I had feared. The same line of code in function CPVRDirectory::GetDirectory in the file "xbmc/filesystem/PVRDirectory.cpp" calls:
"return g_PVRRecordings->GetDirectory(pathToUrl, items);"

In slow cases (1st entry): CGUIMediaWindow::GetDirectory: Loading took 38675 ms
In fast cases (2nd and subsequent): CGUIMediaWindow::GetDirectory: Loading took 67 ms

CGUIMediaWindow::GetDirectory doesn't cache the list although it takes more than 1000 ms - probably in case the content has changed.

Extract from xbmc/pvr/PVRManager.h:
#define g_PVRManager CPVRManager::Get()
#define g_PVRRecordings g_PVRManager.Recordings()

I'm continuing investigations in PVRManager.cpp, but I suspect the breadcrumbs are going to lead back into the pvr.mythv addon code somewhere...

[metaron]

Tracked to CPVRRecordings::GetSubDirectories in xbmc/pvr/recordings/PVRRecordings.cpp:

Applied timings to the for loop to narrow down the culprit:
CPVRRecordings - GetSubDirectories - pt1: 143, pt2: 35603, pt3: 34, pt4: 4, total: 35797
CGUIMediaWindow::GetDirectory: Loading took 35815 ms

Code:

pt1 += (XbmcThreads::SystemClockMillis() - time);
time = XbmcThreads::SystemClockMillis();

CFileItemPtr pFileItem;
current->UpdateMetadata();

pt2 += (XbmcThreads::SystemClockMillis() - time);
time = XbmcThreads::SystemClockMillis();

Enough for this evening.

[metaron]

I have a solution!

Tracked the slowness to CPVRRecording::Update Metadata in xbmc/pvr/recordings/PVRRecording.cpp
Each time CPVRRecording::Update is called by CPVRRecordings::GetSubDirectories, it loads and closes the CVideoDatabase, which was taking ~ 45ms (and 850 recordings * 45ms = 38250ms or 38 seconds...)

Basically:

• * declare a CVideoDatabase in CPVRRecordings::GetSubDirectories,
  * create an overloaded CPVRRecording::Update which only loads the database once if required
  * close the database in CPVRRecordings::GetSubDirectories after the loop
  

Example timings now:
CPVRRecordings - GetSubDirectories - pt1: 81, pt2: 1279, pt3: 21, pt4: 4, total: 1394

Much more usable!

PVRRecording.h:

Code:

#include "video/VideoDatabase.h" //Metaron added

// Update Metadata without re-loading the database (slow system i.e. raspberry pi optimisation)
bool UpdateMetadata(CVideoDatabase &db, bool isAlreadyLoaded);

PVRRecording.cpp:

Code:

bool CPVRRecording::UpdateMetadata(CVideoDatabase &db, bool dbLoaded){
  if (m_bGotMetaData)
    return false;

  bool supportsPlayCount  = g_PVRClients->SupportsRecordingPlayCount(m_iClientId);
  bool supportsLastPlayed = g_PVRClients->SupportsLastPlayedPosition(m_iClientId);

  if (!supportsPlayCount || !supportsLastPlayed)
  {
    if (!dbLoaded)
      dbLoaded = db.Open();
    if (dbLoaded)
    {
      if (!supportsPlayCount)
      {
         CFileItem pFileItem(*this);
         m_playCount = db.GetPlayCount(pFileItem);
      }
      if (!supportsLastPlayed)
        db.GetResumeBookMark(m_strFileNameAndPath, m_resumePoint);
    }
    else
      CLog::Log(LOGDEBUG, "CPVRRecording - %s - unable to load video database", __FUNCTION__);
  }
  m_bGotMetaData = true;
  return dbLoaded;
}

PVRRecordings.cpp:

Code:

void CPVRRecordings::GetSubDirectories(const std::string &strBase, CFileItemList *results)
{
  CLog::Log(LOGDEBUG, "CPVRRecordings - %s - start", __FUNCTION__);
  std::string strUseBase = TrimSlashes(strBase);
  std::set<CFileItemPtr> unwatchedFolders;

  unsigned int time = XbmcThreads::SystemClockMillis();
  unsigned int start = time;
  unsigned int pt1 = 0;
  unsigned int pt2 = 0;
  unsigned int pt3 = 0;
  unsigned int pt4 = 0;

  CVideoDatabase db; //Metaron Mod
  bool myVideoDBLoaded = false;

  for (PVR_RECORDINGMAP_CITR it = m_recordings.begin(); it != m_recordings.end(); it++)
  {
    CPVRRecordingPtr current = it->second;
    const std::string strCurrent = GetDirectoryFromPath(current->m_strDirectory, strUseBase);
    if (strCurrent.empty())
      continue;

    std::string strFilePath;
    if(strUseBase.empty())
      strFilePath = StringUtils::Format("pvr://recordings/%s/", strCurrent.c_str());
    else
      strFilePath = StringUtils::Format("pvr://recordings/%s/%s/", strUseBase.c_str(), strCurrent.c_str());

    pt1 += (XbmcThreads::SystemClockMillis() - time);
    time = XbmcThreads::SystemClockMillis();

    CFileItemPtr pFileItem;
    myVideoDBLoaded += current->UpdateMetadata(db, myVideoDBLoaded); //Metaron mod

    pt2 += (XbmcThreads::SystemClockMillis() - time);
    time = XbmcThreads::SystemClockMillis();

    if (!results->Contains(strFilePath))
    {
      pFileItem.reset(new CFileItem(strCurrent, true));
      pFileItem->SetPath(strFilePath);
      pFileItem->SetLabel(strCurrent);
      pFileItem->SetLabelPreformated(true);
      pFileItem->m_dateTime = current->RecordingTimeAsLocalTime();

      // Assume all folders are watched, we'll change the overlay later
      pFileItem->SetOverlayImage(CGUIListItem::ICON_OVERLAY_WATCHED, false);
      results->Add(pFileItem);
    }
    else
    {
      pFileItem=results->Get(strFilePath);
      if (pFileItem->m_dateTime<current->RecordingTimeAsLocalTime())
        pFileItem->m_dateTime  = current->RecordingTimeAsLocalTime();
    }

    pt3 += (XbmcThreads::SystemClockMillis() - time);
    time = XbmcThreads::SystemClockMillis();

    if (current->m_playCount == 0)
      unwatchedFolders.insert(pFileItem);

    pt4 += (XbmcThreads::SystemClockMillis() - time);
    time = XbmcThreads::SystemClockMillis();
  }
  //Metaron Mod
  if (myVideoDBLoaded)
    db.Close();

  CLog::Log(LOGDEBUG, "CPVRRecordings - %s - pt1: %i, pt2: %i, pt3: %i, pt4: %i, total: %i", __FUNCTION__, pt1, pt2, pt3, pt4, (time-start));
  CLog::Log(LOGDEBUG, "CPVRRecordings - %s - remove watched setting..", __FUNCTION__);
  // Remove the watched overlay from folders containing unwatched entries
  for (std::set<CFileItemPtr>::iterator it = unwatchedFolders.begin(); it != unwatchedFolders.end(); ++it)
    (*it)->SetOverlayImage(CGUIListItem::ICON_OVERLAY_WATCHED, true);
  CLog::Log(LOGDEBUG, "CPVRRecordings - %s - end", __FUNCTION__);
}

This is hardly elegant c++ (like I said, it isn't my language), but seems to work.
I'm guessing there is someone out there who could tidy this up and submit it to kodi or openelec as a patch.
I guess there are quite a few raspberry pi users out there who could benefit from this. Call it my late Christmas present to the kodi community :-).

I've got my sights set on the slowdown when loading recording icons next.
I know janbar's 1.10.1 version allows them to be disabled - and this makes the addon usable, but I like pictures...

[popcornmix]

I have a solution!

Tracked the slowness to CPVRRecording::Update Metadata in xbmc/pvr/recordings/PVRRecording.cpp
Each time CPVRRecording::Update is called by CPVRRecordings::GetSubDirectories, it loads and closes the CVideoDatabase, which was taking ~ 45ms (and 850 recordings * 45ms = 38250ms or 38 seconds...)

Excellent work! It's great to see someone stepping in and helping to fix an issue they are seeing.

I've taken your patch and tidied it up a little. I don't have a PVR setup, so my version is completely untested. I'd be grateful if you could test if this still works:
https://github.com/popcornmix/xbmc/commi...c63985d0bf

My view was that if opening/closing the database is expensive compared to updating the metadata, then make the caller open the database *always*.
All calls to UpdateMetadata are in loops, so make the caller open the database outside the loop.
This means there are two other places that may benefit from your change.

This patch should appear in next newclock4 builds (so it would be good if you can confirm it works), so should be in tonight's Milhouse build.

[metaron]

Thanks for the encouragement popcornmix

I found the other two instances you pointed out when testing a bit more myself this afternoon.
One of them was causing a similar delay after pressing 'stop' when playing a file.

I'll check out the latest Millhouse build tomorrow to confirm your version works and post back, but from the commit link you sent it looks like it will.