[steve1977]

Well, I have 5,000 movies and 20,000 episodes. So, this may just be the limit of RPi? Log file below:

http://xbmclogs.com/show.php?id=298332

[da-anda]

probably not what you want to hear, but will you watch all these movies and episodes ever again? Also, this is again no debug log. Please turn on debug mode, restart your PI and then go to your library. Also note that OpenElec is not creating a standalone log for every reboot. Your posted link contained 3 logs actually - the last one would be sufficient.

[steve1977]

No doubt that I will never watch them again, not even to mention that I probably watched most of them not even once. It is basically like collecting stamps... Not about watching, but about collecting... I know it doesn't make a lot of sense, but what hobby actually does?

Below is the proper log as requested.

http://xbmclogs.com/show.php?id=298345

[popcornmix]

Well, I have 5,000 movies and 20,000 episodes. So, this may just be the limit of RPi? Log file below:

The 20,000 episodes is not really an issue as that probably equates to ~200 shows which is a manageable number.
The 5000 movies is going to be slow as all 5000 movies get accessed whenever you enter movies view.

For comparison I have about 1500 movies and it takes about 7 seconds to enter the movies view after boot, and about 3 seconds when entered subsequently.
(Initially it looks up the 5000 movies from SQL database, and subsequently uses a cache). I assuming subsequently entering movies is quicker than first time?

From log:

Code:

09:34:34  81.639458 T:3058721664   DEBUG: RunQuery took 5024 ms for 5138 items query: select * from movieview
09:34:36  83.567749 T:2907698256   DEBUG: RunQuery took 18072 ms for 15115 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))
09:34:37  84.733887 T:2927858768   DEBUG: RunQuery took 15109 ms for 15115 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))

The first entry seems reasonable - its reading 5000 movies from sql database and it takes 5 seconds.
Possibly this would be quicker if using an external MySQL database from a more powerful server (as I do).

I'm a little confused by the next two entries. It seems to be looking up your tvshows twice and that is where most of the time (over 30 seconds) comes from.
How are you entering the movies view? Do you have any add-ons that might be accessing the library?

[da-anda]

could you please test if loading times are better with:
- GUI refresh rate lowered to 50 or 30 Hz (CPU less busy)
- Confluence instead of Conq (skin could do heavy regex for each file in a list)

According to your log you have opened "Movies -> Title" window (so listing all movies). The odd thing about this is though, that there are two queries logged that are fetching the unwatched episodes, which is the same query twice in a row (each taking 15 sec).
After this the log just stops, so if you did more in your debug session, OE didn't write the log buffer to SD in time. You could reboot after you are finished and then grab according section from the log file to get a complete log (noticed this behavior in OE myself a couple days ago when I tried to debug something)

But as said above - please test with Confluence to rule out that Conq is doing some special things that add additional slow downs (I assume the unwatched episodes are triggered by conq)

edit: popcornix was faster

[steve1977]

Thanks for your messages. Actually, the look-up of (15+15sec) is coming from entering the tvshows menu afterrwards and then selecting a show.

So, it appears that the issue is the following:

1) Accessing the TV shows library takes 15sec, which is quite long. Reason is because it reads all 15,000 episodes when entering the library and not only the 200 or so tvshows

2) Even worse than that, it re-reads all 15,000 episodes (another 15sec) when accessing one of the tvshows (15sec for entering libray, another 15sec when clicking on one of the shows)

3) The "double-load" also happens with movies, which is annoying. 3sec when entering movies, another 3sec when going one menu up within movies, etc.


I assume that all of above are default behaviors that cannot be changed?

Also, the really long waiting times (1min+) happen when I update the library at the same time.

[Milhouse]

@steve1977: Looking at your debug log, based on the thread identifiers, the slow queries are all being requested by addons, mainly the "Library Data Provider" addon (service.library.data.provider):

Code:

09:33:57  44.425217 T:2890921040   DEBUG: Library Data Provider: script version 0.0.5 started
09:34:07  54.005543 T:2890921040   DEBUG: RunQuery took 9302 ms for 5125 items query: select * from movieview  WHERE ((movieview.playCount IS NULL OR movieview.playCount = 0))

Code:

09:33:58  45.469742 T:2927858768   DEBUG: Library Data Provider: service version 0.0.5 started
09:34:10  57.547813 T:2927858768   DEBUG: RunQuery took 11655 ms for 5125 items query: select * from movieview  WHERE ((movieview.playCount IS NULL OR movieview.playCount < 1))
09:34:37  84.733887 T:2927858768   DEBUG: RunQuery took 15109 ms for 15115 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))

Code:

09:34:00  47.896164 T:2758104144   DEBUG: Library Data Provider: script version 0.0.5 started
09:34:02  49.519688 T:2758104144   DEBUG: RunQuery took 71 ms for 16 items query: select * from movieview  WHERE (movieview.idFile  IN (SELECT DISTINCT idFile FROM bookmark WHERE type = 1))

Code:

09:34:17  64.456177 T:2907698256   DEBUG: Library Data Provider: script version 0.0.5 started
09:34:36  83.567749 T:2907698256   DEBUG: RunQuery took 18072 ms for 15115 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))

You've also got the Skin Widgets addon (service.skin.widgets) running a slow query:

Code:

09:33:58  45.471077 T:2936247376   DEBUG: Skin Widgets: script version 0.0.29 started
09:34:11  58.327549 T:2936247376   DEBUG: RunQuery took 12454 ms for 5125 items query: select * from movieview  WHERE ((movieview.playCount IS NULL OR movieview.playCount = 0))

I believe both these third-party addons are intended to provide Recently Added/Recommended/Random movie and tvshow widgets.

The only "native" query (ie. not requested by a third-party addon) is this one:

Code:

09:34:26  73.408287 T:3058721664   DEBUG: Activating window ID: 10025
09:34:26  73.624168 T:3058721664   DEBUG: ------ Window Deinit (Home.xml) ------
09:34:27  74.778633 T:3058721664   DEBUG: ------ Window Init (MyVideoNav.xml) ------
09:34:27  74.778976 T:3058721664    INFO: Loading skin file: MyVideoNav.xml, load type: KEEP_IN_MEMORY
09:34:29  76.364243 T:3058721664   DEBUG: CGUIMediaWindow::GetDirectory (videodb://movies/titles/)
09:34:29  76.364693 T:3058721664   DEBUG:   ParentPath = [videodb://movies/titles/]
09:34:34  81.639458 T:3058721664   DEBUG: RunQuery took 5024 ms for 5138 items query: select * from movieview
09:34:52  99.357559 T:3058721664   DEBUG: Saving fileitems [videodb://movies/titles/]
09:34:58 104.996925 T:3058721664   DEBUG:   -- items: 5138, sort method: 0, ascending: true

which is when you first entered the Movies view, and the cached movie information is saved for subsequent re-use.

I would suggest disabling the "Library Data Provider" and "Skin Widgets" addons and see if this makes any difference. Maybe ask the addon author(s) why the same expensive query is being executed twice in two different threads.

Offloading your SQL queries, particularly those made by these addons, to an external MySQL server would in all likelihood prove highly beneficial.

[steve1977]

Thanks, let me try. Unfortunately, I cannot "disable" both addons. When clicking the "disable" button, nothing happens. It does not freeze, but it just does not change anything. Any thoughts?

[Milhouse]

What skin are you using?

These addons are typically dependencies of third-party skins, and when disabling the add-on you should be told the dependency, although yes you won't be able to disable the addon without first uninstalling the skin(s).

I've got both these addons installed and Skin Widgets is a dependency of Confluence Modified and also Amber, while Library Data Provider is a dependency of Aeon Nox.

I'm using stock Confluence and - despite being installed - I'm not seeing either add-on in use (no activity in my debug log) so maybe just switch to Confluence and see if performance improves when these add-ons are not hammering your database.

Or it could be how I've got these addons configured:

Skin Widgets: In the "General" tab, "Show plot for unwatched items" is enabled. "Recommended" and "Random Items" are both disabled. "Recent Items" is enabled (top two radio buttons enabled, bottom one disabled).

Library Data Provider: The radio buttons in "General", "Random Items" and "Recent Items" are all enabled. 20 is specified as the number of items to fetch in the "General" tab.

[steve1977]

Unfortunately, same issue with Confluence. I have switched to Confluence and accessed the tvshow library. Then selected a tvshow and then yet again another tvshow (to make sure that there is nothing wrong with this specific one). Log below. Thanks in advance!!!

http://xbmclogs.com/show.php?id=299130

[Milhouse]

What kind of delays are you experiencing in the GUI now (I can see there are still long running queries, but I'm not really sure how that impacts the GUI and the user experience).

Most of the Library Data Provider queries now occur when Kodi starts (which is what you'd expect, if it is caching this data), or are very brief.

There's still a ~15 second query being requested by something called CRecentlyAddedJob - not sure if this is a standard component or addon:

Code:

06:02:07  26.946909 T:2890921040   DEBUG: CRecentlyAddedJob::UpdateMusic() - Running RecentlyAdded home screen update
...
06:02:30  49.511822 T:2890921040   DEBUG: RunQuery took 14998 ms for 10 items query: select * from episodeview  ORDER BY dateAdded desc, idEpisode desc LIMIT 10

And Skin Widgets is still doing its thing...

Code:

06:02:06  25.890249 T:2928051280   DEBUG: CPythonInvoker(0, /storage/.xbmc/addons/service.skin.widgets/default.py): start processing
...
06:02:56  75.784279 T:2928051280   DEBUG: RunQuery took 14779 ms for 15115 items query: select * from episodeview  WHERE ((episodeview.playCount IS NULL OR episodeview.playCount < 1))

Bear in mind though that these kind of queries are to be expected during startup (first ~2 minutes).

But then there's this:

Code:

06:02:16  35.072514 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/e/ecff65d3.jpg 360x540
06:02:35  54.673958 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/8/8d2e76b1.jpg 367x540
06:02:35  54.889355 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/a/a202e45a.jpg 367x540
06:02:36  55.100403 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/4/4a756af2.jpg 367x540
06:02:36  55.327229 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/9/971d13fc.jpg 367x540
06:02:36  55.528412 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/8/876be513.jpg 367x540
06:04:53 193.021896 T:2532430928   DEBUG: RunQuery took 134356 ms for 9 items query: SELECT * FROM seasonview  WHERE seasonview.idShow = 18
06:04:54 193.214706 T:2532430928   DEBUG: RunQuery took 183 ms for 0 items query: select * from movieview join movielinktvshow on movielinktvshow.idMovie=movieview.idMovie WHERE movielinktvshow.idShow = 18
...
06:04:58 197.224869 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/f/f2e11290.jpg 374x540
06:05:04 203.972260 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/0/07978e02.jpg 367x540
06:05:05 204.119705 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/3/3a988c2a.jpg 367x540
06:05:05 204.285675 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/9/971d13fc.jpg 367x540
06:05:05 204.443878 T:2532430928   DEBUG: DecodeJpegToTexture: decoded special://masterprofile/Thumbnails/7/77d17113.jpg 367x540
06:06:25 284.705872 T:2532430928   DEBUG: RunQuery took 73409 ms for 10 items query: SELECT * FROM seasonview  WHERE seasonview.idShow = 27
06:06:25 284.873627 T:2532430928   DEBUG: RunQuery took 157 ms for 0 items query: select * from movieview join movielinktvshow on movielinktvshow.idMovie=movieview.idMovie WHERE movielinktvshow.idShow = 27

which suggests the queries took over 134 seconds and 73 seconds to return the 9 season rows and 10 season rows respectively for two different tvshows - that's just bonkers.

I'm not entirely sure what this thread is doing, but it looks like it's caching artwork (6 items and 5 items respectively), so presumably this was while you were browsing your TV library?

Perhaps your db is just too big for the available memory on your Pi? Does reducing gpu_mem from 192 to 128 have a noticeable impact on library browsing performance? Other than that, and moving to MySQL, I'm outta ideas.

[steve1977]

which suggests the queries took over 134 seconds and 73 seconds to return the 9 season rows and 10 season rows respectively for two different tvshows - that's just bonkers.

This is the main issue. When I am in the tvshow library view, I click on the show, which has 9 seasons (10 seasons respectively). This is taking ages and no idea why it is taking so long. I have not installed a single additional addon (beyond two additional skins that I am not using and a rpi utility).

I accessed one tvshow (9 seasons) and afterwards another one (with 10 seasons), that's why it shows up twice. Wanted to make sure that the reason is not one specific show.

Any more thoughts with this additional context?

I will try the gpu thing later today. Also thinking whether I should try mysql, but shouldn't this make things even worse as all my posters would then no longer be locally scored? Also, it wouldn't be too easy for me to do. I have a headless server (which would be perfect to host the mysql database), but unfortunately XBMC can still not run headless.

[nickr]

Your posters are still cached locally.

Why don't you actually forcefully remove the offending skins and addons and try again.

[Milhouse]

Any more thoughts with this additional context?

No, looking at the debug log there's not much going on in this thread apart from it waiting for the query to complete. There is other activity in other threads, which could be maxing out the CPU or maybe even causing some sort of database conflict/lock, but that's probably unlikely to be honest.

On the face of it, it just seems to be a straight issue with database performance - either your indexes are corrupted (or missing), or SQLite is struggling for some other reason. Do you have an older database such as MyVideos88? I would suggest deleting MyVideos89 and allow Kodi to re-create the MyVideos89 database again. To be sure there are no errors during database upgrade, leave debug enabled before you restart Kodi and then upload your debug log at least 2-3 minutes after Kodi has started and finished the update.

I will try the gpu thing later today. Also thinking whether I should try mysql, but shouldn't this make things even worse as all my posters would then no longer be locally scored?

MySQL has no impact on thumbnails, as these remain local in Textures13.db and the Thumbnails folder.

Also, it wouldn't be too easy for me to do. I have a headless server (which would be perfect to host the mysql database), but unfortunately XBMC can still not run headless.

What has XBMC got to do with running MySQL on your headless server? You don't need to run XBMC on the same server as MySQL - just configure your Pi to connect to the MySQL server.

The difficulty with migrating to MySQL is often transferring your existing library. Some people use the Library Export/Import approach, though personally I'd just re-scrape whatever you already have assuming that was good enough in the first place.

If you want to keep your watched statuses, you can use the texturecache script to backup the statuses while still on SQLite, then switch XBMC to MySQL, re-scrape the new library, then restore your watched statuses.

[da-anda]

Milhouse - rescraping THAT HUGE library on the PI will take like 1 week (depending on local NFOs or remote scrapers). So a export/import is probably better.

I'm also wondering if we might have some bad indexes that cause such slow queries, but that's probably a memory issue like you already mentioned.