Bug KODI is too slow on huge lists of songs Part II
#1
Hi,

first off all: this is the 2nd try to place it in the right category and i hope, that i found the right place now (sry for that).
Here you can visit my 1st attempt, but as a result of the activities inside the KODI-Forum, most DEVs and MODs aren´t aware of the topic:
http://forum.kodi.tv/showthread.php?tid=213179


The Problem
If you have a large music database and try to play a song, KODI will take many, many minutes (or even freezes the device) to start the song.
Important note: it is not about the time, which is needed to populate the song list. The problem is the delay or freeze between pressing "play" and the song starts.

Reproduce the problem
Scrape a large music folder with many MP3s (e.g. 40k+).
Navigate "Music -> Title".
After a while (depends on your machine, e.g. the Raspberry Pi needs about 1 minute, my Win7-Notebook creates the list within 40 seconds) you see the list with all the songs inside your database.
Klick the "Play"-Button on your remote.
The system will "freeze" (no more user interaction, no "...working" is displayed, even in debug mode there is no more refresh of fps, memory and cpu usage).
After 30 minutes i shutted down the system, but maybe i was not patient enough (see log following later).


Affected systems
I tried it with the following 3 systems/versions and all show up the same behaviour:

KODI 14.0 and XBMC 13.? (aka Helix and Gotham) on Win-7-Notebook (WLAN)
Entering "Music -> Songs" 40 seconds delay till list is displayed
Starting the first song: 40 seconds delay till the song is played, but maybe i was in the wrong category (by artist i guess).
Later attempts had to kill KODI after a while.

KODI and XBMC on RPi with OpenELEC (4.2.1 & 5.0) (LAN)
Entering "Music -> Songs" 60 seconds delay till list is displayed
Starting the first song: device seems to freeze. even 30 minutes later the song will not played by KODI/XBMC

SPMC on FireTV (a Gothambuild) (WLAN)
Entering "Music -> Songs" 60 seconds delay till list is displayed
Starting the first song: device seems to freeze. even 30 minutes later the song will not played by SPMC

There is a central MySQL-DB which is used by the installations, but behaviour is also reproducable with a local database (tested only on RPi, because i had a local database at the first try).
The crash i had at a 1st try, is not reproducable anymore, but i just waited 30 minutes before i take down the devices.


Log
The kodi.log i inspected was > 1 MB (i stopped KODI after 6 Minutes of waiting) and had nearly 15k of lines.
Here is what the kodi.log shows up in the section which logged the "play" command:

Quote:...
13:03:03 T:1780 DEBUG: ------ Window Init () ------
13:03:12 T:3432 DEBUG: Thread RemoteControl 3432 terminating
13:04:02 T:1780 DEBUG: CAnnouncementManager - Announcement: OnScreensaverDeactivated from xbmc
13:04:02 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 4, from xbmc, message OnScreensaverDeactivated
13:04:02 T:1780 DEBUG: ------ Window Init (Pointer.xml) ------
13:04:02 T:1980 NOTICE: Thread JobWorker start, auto delete: true
13:04:03 T:1780 DEBUG: ------ Window Deinit () ------
13:04:03 T:1780 DEBUG: CApplication:TonguerocessMouse: trying mouse action leftclick
13:04:03 T:1780 DEBUG: SELECT albumview.*,albumartistview.* FROM albumview LEFT JOIN albumartistview ON albumview.idAlbum = albumartistview.idAlbum WHERE albumview.idAlbum = 5 ORDER BY albumartistview.iOrder
13:04:27 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:04:28 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:04:28 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd

....

13:10:09 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:10:09 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
13:10:10 T:1780 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
13:10:10 T:1780 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
...


Additionial information
I tried it with "Music -> Artist" and choosed an artist with some songs (round about 100) and it looks like, that for each entry in the songlist this both message lines are created if you start to play a song. Which means, that if you have 40k+ songs in your library, this action will take place more then 40.000 times (which could consume some time).
I made a test with my movie library and there is just one of this messages, regardless how many entries are in the list.


Conclusion
Now i hope, that more DEVs are able to examine this problem.
If further information or tests are needed: i am ready to go!
Even if i have to create a new music database and scrape all the content again Big Grin

Anyway: thx a lot for your great work on KODI and an extra "thank you" to Popcornmix and Milhouse, who already took a look inside my problem (dunno where the "reputation"-button is Confused ).
Reply
#2
Can you upload the log somewhere? The full version.
Reply
#3
What a great pitty, that you were not able to reproduce this behaviour.
Anyway: here is the kodi.log you reqested:
http://pastebin.com/K1pWqKMp

@20:17 i activated "Music -> Songs"
@20:20 i klicked "play"

I just made a copy of the first 1.000 lines, the following round about 4k of lines always prompt the same, so i did not copy them to pastebin (i killed KODI with the Windows Tasmanager, so there is no sense of the last lines).

[quote]
DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
[/qiote]

Hope that helps.
Reply
#4
That looks like a serious issue, I created a bug report and hopefully pinged the right people: http://trac.kodi.tv/attachment/ticket/15673/. If you post something in the report you'll get informed by e-mail whenever there's an update.
Reply
#5
thanks for all!
Reply
#6
Hi,
i have exactly the same problem/error.
when i want to turn on song from "Smart playlist for music" the logs are filled with
---
CAnnouncementManager - Announcement: OnAdd from xbmc
GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
---

from what i see in trac history the case is frozen, is there a way to do something with this bug?
Reply
#7
It looks like a significant design change needed in how now-playing playlist is created. You can get around this by not selecting "play next song automatically" in settings/music/playback. Or create a smart playlist with a "limit to" x items setting.

IMHO design might be changed to start playback while continuing to load/populate now-playing playlist in background.

scott s.
.
maintainer of skin  Aeon MQ5 mods for post-Gotham Kodi releases:
Matrix see: Aeon MQ5 Mod Matrix release thread
Nexus see: Aeon MQ5 Mod Nexus release thread
Aeon MQ 5 skin and addon repo 11.1.0
Reply
#8
Does anybody know the status of this issue? Still problem for my in Kodi 15.2 and OpenElec.
Reply
#9
I didn't know about this thread and posted about the same issue in krypton test builds thread http://forum.kodi.tv/showthread.php?tid=...pid2247776
Reply
#10
While I have over 53000 songs in my music library I haven't had any issues with it because I rarely have the urge (and certainly not the time!) to play them all in one go
Opening the list of all songs takes about 43 seconds which is about the same as the topicstarter experienced. A bit long but it is a huge list. Since I felt experimental I decided to play the entire list and see how long it would take or whether Kodi (15.2) would crash or not.
At the same time I kept a check on the logfile. Since it is stated that for each song the same two lines are written to the log I was expecting the log to grow with 106118 (53059 *2) lines.

The good news is that Kodi didn't crash. It just took about about 17 minutes and 30 seconds before Kodi started playing the first song in the list. The logfile had grown by 106142 lines, which isn't exactly the 106118 I was expecting but comes quite close. After sorting and counting the log entries it checked out perfectly (exactly two lines of code for every song added to the playlist).

Code:
17:59:39 T:3760   DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
17:59:39 T:3760   DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
17:59:39 T:3760   DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
...
18:17:07 T:3760   DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
18:17:07 T:3760   DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd

Kodi really has a lot to do here, It must retrieve all information from a SQL server in the network, stores them in a local playlist and also write two lines for each item in the logfile. The latter might add significantly to the amount of time it takes. The logfile is on a SSD drive which might make a difference as opposed to a slower HDD or SD-card (most Raspberries).

For me it isn't a big issue since I rarely create large playlists and those are only a few thousand songs which doesn't take very long.
I think all righthtinking people in this country are sick and tired of being told that ordinary, decent people are fed up in this country with being sick and tired.
Reply
#11
Already noticed a delay in my smaller library of about 5000 Songs. The delay is about 5 seconds on my Intel nuc4i3. Really annoying and I can imagine that it gets unusable when having a way larger library.

But that is also an issue in how he and I use the library. Because when you use views with fewer music files it works without problem. Like only viewing songs of a single artist and clicking on play. This is because only the songs of that view are added to playlist, so the OnAdd ist also called a few times.
So if you use it this way you can still use a large library.

The problem exists only when I want to have (shuffled) playback of my whole music library. Unfortunally this is how I use the library most of the time Tongue :S

Also when I'm already in the playback of all those songs and select another song from the view to play the whole playlist is recreated. Maybe the music player could just jump to the song in the playlist when selecting a song from same view of which the playlist was created once. So this delay would at least only occur once.
Of course it doesn't fix the root of the problem.
But it would already help a little bit, and could probably done within a minor version.

With a major version the event could be altered, which would then break the JSON RPC api once. This should be OK for a major version or not?
Reply
#12
ISTM that what might be desired is to have one thread add songs to the playlist that is asynchronous to playing the playlist.

As far as filtering or changing the playlist, seems like this would be better done with the playlist editing tools, rather than regenerating the playlist.

scott s.
.
maintainer of skin  Aeon MQ5 mods for post-Gotham Kodi releases:
Matrix see: Aeon MQ5 Mod Matrix release thread
Nexus see: Aeon MQ5 Mod Nexus release thread
Aeon MQ 5 skin and addon repo 11.1.0
Reply
#13
One dirt simple thing to do is comment out those useless logging that goes on

17:59:39 T:3760 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
17:59:39 T:3760 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd

We had a performance issue adding a large amount of items to a playlist, commenting those out definitely helped to speed up the load.
MrMC Forums : http://forum.mrmc.tv
Reply
#14
Threated add Songs would make the ui at least usable again. But it would be still totally imperformant. Specially the IO on writing the log would still be high. Also still logging those lines a thousand times would only flute the log. Further to write the log you probably have to sync that write log action again so it wouldn't even help. Maybe not, I only have little to none knowledge of the architecture.

If it would be logged on debug level only it could already help as long as it isn't enabled. And still exists for detailed logging. Would fix the issue quickly and without breaking any thing.

But I guess a OnAddMultiple event would be the best solution in the long term.

Edit:
MrMC is this commented out for the next Jarvis release? or did you just tried that? Or are you reffering to the issue Scf2k mentioned in the Krypton test Branche?

Would be great to See a improvement with the next Jarvis release Smile
Reply
#15
The MrMC fork has always had this logging spew removed. There are lots of places where development logging was removed to minimize useless log spew.

As for Kodi/Jarvis, that is up to Kodi devs to decide.
MrMC Forums : http://forum.mrmc.tv
Reply

Logout Mark Read Team Forum Stats Members Help
KODI is too slow on huge lists of songs Part II0