Huge amount of onadd calls

[hablaras]

Hi,

I am using Eminence 2 MOD skin (on RPi3 with OSMC), which in turn utilizes Skin Helper Service and Skin Helper Widgets.

Issue: movies start really slow after a couple of repeated starts:

Playing and stopping one movie in a movie set, starts it almost immediate
Immediately playing and stopping a second movie, starts the movie after a couple of seconds
Immediately playing and stopping a third movie after that, starts the movie after a couple of minutes!

When opening a movie set with 2 movies, there is no performance / starting issue:

23:06:04.359 T:1937765360 DEBUG: StartScript - calling plugin Skin Helper Service('plugin://script.skin.helper.service/','1','?action=getcast&downloadthumbs=true&movie=')
23:06:19.145 T:1742255088 DEBUG: Skin Helper Service --> plugin called with parameters: {u'action': u'getcast', u'downloadthumbs': u'true'}
23:06:42.452 T:1443886064 DEBUG: Skin Helper Service --> Started Background worker...
23:06:58.496 T:1443886064 DEBUG: Skin Helper Service --> Ended Background worker...
23:07:07.514 T:1688515568 DEBUG: StartScript - calling plugin Skin Helper Service('plugin://script.skin.helper.service/','2','?action=alphabet&reload=')
23:07:09.777 T:1395651568 DEBUG: Skin Helper Service --> plugin called with parameters: {u'action': u'alphabet'}
23:07:50.686 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2456,"type":"movie"},"playlistid":1,"position":0}
23:07:50.687 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2458,"type":"movie"},"playlistid":1,"position":1}
23:07:51.681 T:1937765360 DEBUG: StartScript - calling plugin Skin Helper Service('plugin://script.skin.helper.service/','3','?action=getcast&downloadthumbs=true&movie=Movie 1')
23:07:52.251 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnPlay - data: {"item":{"id":2456,"type":"movie"},"player":{"playerid":1,"speed":1}}
23:08:51.126 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnStop - data: {"end":false,"item":{"id":2456,"type":"movie"}}
23:08:51.647 T:1937765360 DEBUG: StartScript - calling plugin Skin Helper Service('plugin://script.skin.helper.service/','4','?action=alphabet&reload=0')
23:08:51.916 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: VideoLibrary.OnUpdate - data: {"item":{"id":2456,"type":"movie"}}
23:08:53.952 T:1688515568 DEBUG: Skin Helper Service --> plugin called with parameters: {u'action': u'alphabet', u'reload': u'0'}
23:09:42.674 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnClear - data: {"playlistid":1}
23:09:42.675 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2457,"type":"movie"},"playlistid":1,"position":0}
23:09:44.468 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnPlay - data: {"item":{"id":2457,"type":"movie"},"player":{"playerid":1,"speed":1}}

All my home movies of 7 years are in one huge set with 2100+ items. When you try to start a movie it debug logs this:

23:10:32.586 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnStop - data: {"end":false,"item":{"id":2457,"type":"movie"}}
23:10:33.575 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: VideoLibrary.OnUpdate - data: {"item":{"id":2457,"type":"movie"}}
23:11:45.621 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnClear - data: {"playlistid":1}
23:11:46.022 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":1,"type":"movie"},"playlistid":1,"position":0}
23:11:46.023 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2,"type":"movie"},"playlistid":1,"position":1}
23:11:46.024 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":3,"type":"movie"},"playlistid":1,"position":2}

23:12:44.718 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2110,"type":"movie"},"playlistid":1,"position":2109}
23:12:44.718 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2111,"type":"movie"},"playlistid":1,"position":2110}
23:12:44.719 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnPlay - data: {"item":{"id":2091,"type":"movie"},"player":{"playerid":1,"speed":1}}
23:12:46.806 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnStop - data: {"end":false,"item":{"id":2091,"type":"movie"}}
23:12:47.032 T:1695667184 DEBUG: Skin Helper Service --> plugin called with parameters: {u'action': u'getcast', u'movie': u'20170506-1453-00825', u'downloadthumbs': u'true'}
23:12:47.155 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: VideoLibrary.OnUpdate - data: {"item":{"id":2091,"type":"movie"}}

... and more or less the same number of .OnAdd logging with Skin Helper Widgets

I've been using this skin (or variants of it) for years without issue, but now it is.

As a test, I removed the skin and Skin Helper services and just used the OSMC Skin and then the delay in starting movies does not occur.

The delay (and massive Playlist.OnAdd logs) happens when starting a movie using either:

Skin Helper Service 1.1.3 and 1.1.15 (from your beta repository)
Skin Helper Widgets 1.0.22 and 1.0.28 (from your beta repository)

Has this functionality been added recently? It also causes the CPU usage to be 150% on my RPi3 for minutes, while it normally idles at 10%

I guess the .OnAdd is running in the background and keeps adding to a queue when you repeatedly start/stop movies?

Can this process be improved or eliminated, perhaps via a addon setting?

Greetings,

Hablaras

[marcelveldt]

The log lines you posted are absolutely fine. In fact that process is Kodi itself and not Skin helper service. Because SH has a logger activated it just prints whatever Kodi is doing.

I need a full debug log in order to better help you, not just some random lines.
The log must be created after you have reproduced the issue with slow starting movies.

I do observe a few things:

1. You have created a movie set with 2100 items ?!! It's simply not build for that, you should use tags for that purpose.

2. I suspect that you have "auto play next item" enabled in the Kodi settings for videos. This will mean that if you play one movie from your fake 2100+ movies set, Kodi will add all movies into the player's playlist!! Again, you should use tags for your purpose.

I suggest you to change your set workaround into using tags, which is build for that purpose and try again. Offcourse I'm willing to take a look at your logfile to check why it's hogging your cpu to fix it eventually in my code but I know for sure other things are also not up against such a query.

[hablaras]

Hi Marcel,

Offcourse I'm willing to take a look at your logfile to check why it's hogging your cpu to fix it eventually in my code but I know for sure other things are also not up against such a query.

Thanks a lot! Really appreciate that!

The log lines you posted are absolutely fine. In fact that process is Kodi itself and not Skin helper service. Because SH has a logger activated it just prints whatever Kodi is doing.

Not to be disrespectful, but then the application does something, even if it is just handling/passing an OnAdd event to a log routine. E.g. it might be that it synchronizes and asychronous process. Say the Kodi OnAdd processes runs on the back while the movie starts, but Skinhelper first adds them to a queue it then synchronously processes. Not saying this is the case, just saying it is possible.

Really just trying to help here...

The log must be created after you have reproduced the issue with slow starting movies.

I started by renaming .Kodi to have it create a new, fresh folder.

I've created two versions:

1. enabled debugging, rebooted, start and stop movies as quick as the GUI allows me:
   kodi_without_eminence2mod.zip: only with OSMC Skin, and there is no problem at all. I started 10 homemovies without noticeable delay.
   The OnAdd events maximum take up a couple of seconds in total, more or less the time it takes each movie to start and CPU is about 150% (out of 400%) for this period

2. installed Eminence 2 MOD with Skinhelper, rebooted,
   kodi_with_eminence2mod.zip: added Eminence 2 MOD, which installed Skin Helper Service and Skin Helper Widgets.
   Starting and stopping movies becomes increasingly slower, the fourth movie took 60 seconds to start and CPU is about 150% for this entire period and even 10+ minutes after finishing that fourth movie.

Just an observation: you see SH Service and SH Widgets logging interleaved for all the OnAdd events.

I suspect that you have "auto play next item" enabled in the Kodi settings for videos.

You're correct :)

I suggest you to change your set workaround into using tags, which is build for that purpose and try again.

I use this setup for children (3 yrs old) and have to keep it as simple as possible. I really think there is no other way as simple for them as this.

My setup is (with "group movies in sets" enabled):

Playlist "children", hooked up to key F2, which in turn contains:

• Folder A (with subfolders) with the homemovies, each with an .nfo file classifying them as set ".Homemovie"
• Folder B with 30 children's movies

They only have to press F2, the AVR and TV start and take them immediately to playlist "children", where the first icon is ".Homemovies" and the other 30 movies are just visible. This way they can easily pick a movie OR watch homemovies. The "auto play next item" has to be on, because some movies last 10 seconds and pressing play on each of them is undoable.

Using tags, I would still have to devise a way to put them in one list with 2100 items... and the problem would be the same. I really want them in one big list, not split by year or whatever.

Not putting them in a set would mean having 2130 items in one big list, where it would be impossible for them to find a children's movie because it is buried under the homemovies. And the OnAdd problem would even be bigger.

You have created a movie set with 2100 items ?!! It's simply not build for that, you should use tags for that purpose.

I cannot find this stated anywhere. In fact, I first posted this issue on the OSMC forum and one of the developers responded that there is no size limit with regard to performance of a movie set. And again, using just the OSMC Skin there is no issue.

I also assume (big assumption here) that the skin itself is a "dead thing", unless of course it kicks of a lot of other services in the background, but I cannot find that in the definition.

kodi_with_eminence2mod.zip
kodi_without_eminence2mod.zip

[marcelveldt]

Skinhelper contains a feature to provide some info about a movie set. By default kodi is lacking this info.
It will provide the skinner a way to show some information about a movie set like number of watched-umwatched items etc.

The behaviour I´m seeing now is that the method that generates this info is called with every Playlist.OnAdd callback from Kodi. So if you start playing 1 movie it´s actually 2100 times generating that info.

Offcourse I will fix this issue in Skinhelper. What I meant to say is that I will be fixing this now but there may be other addons out there that don´t suspect a movie set to have 2100 items :-)

[marcelveldt]

BTW, still I think you should reconsider your current approach of one big set and auto play enabled. I can clearly see in your logs that kodi is taking several seconds to process all those 2100 files to add them to the video playlist, regardless of what Skinhelper is doing with that callback...

[marcelveldt]

OK, checked the code... My theory was wrong. There's really nothing happening with that callback on the playlist.onadd. Only if the database was actually modified or playback stopped there's an action involved. All it does is logging the entry so that will do no harm.

I do see some other stuff. It seems that the skin is calling the alphabet jump method very, very often and also the widgets seem to be refreshing like crazy. That could also explain high cpu spikes.

Can you do me a favor and test with another skin that also utilizes Skin Helper Service ?
For example my Titan skin which uses almost every single part of the skinhelper.

I'm very curious if the issue also exists when using that.
Another approach could be to just leave skinhelper addons installed and use teh default skin Estuary or Confluence.

[hablaras]

Hi Marcel,

Can you do me a favor and test with another skin that also utilizes Skin Helper Service ? For example my Titan skin which uses almost every single part of the skinhelper.

Of course, no problem!

I installed the regular "titan" skin, so not the "titan beta for krypton", enabled debugging and rebooted.
CPU usage was high for about two minutes (~ 150-200%) when the GUI came up, so I let that drop to about 50%, which is actually still reasonably high.

Then I took out a stopwatch and started a home movie. Took about 6 seconds to start and CPU went up to 150%. Stopped the movie and it took about 70 seconds for CPU to return to 50%. Stopped and started twice again, high CPU and startup times increasing every time. The fourth movie, after stopping, it took a little more then 4 minutes to return to 50%! Starting that fourth movie took 30 seconds after pressing play. Refresh rate drops to ~9 FPS during that 4 minutes.

I also note that whatever it is doing is a single-threaded process that runs 100% and gets rescheduled from core to core (if I can trust the debug info on screen).

So, in short, almost the same behavior as with Eminence 2 MOD. Perhaps even worse.

BTW that skins looks really good! Have to dive into the different view types, etc., to see its full potential

kodi is taking several seconds to process all those 2100 files

I know, but as mentioned, I don't notice it when starting or stopping home movies when using OSMC Skin (without Skinhelper installed) CPU drops back to below 50% after 2-3 seconds.

kodi_with_titan.zip

[marcelveldt]

Thanks for the additional tests, I will review the log and code to see if I can see what's going on.
Did you start the movie from a widget or from the library ?

[hablaras]

Did you start the movie from a widget or from the library ?

Hmm, not sure what the difference is?

I click movies on the home screen in Titan, then ".Homemovie" is the first item there (because it starts with a dot). If I just open that movie set, CPU now again goes up to 190% for about a minute.

I also have a keymap file entry:

<f2>activatewindow(videos,special://profile/playlists/video/children.xsp)</f2>

This directly opens the playlist.

Either using the movies entry or the keymap entry result in the same behavior, as far as I notice.

[marcelveldt]

Sorry for the late reply. was this issue fixed with most recent updates ?

[hablaras]

Hi Marcel,

Unfortunately, not, it still takes a couple of minutes to start a third movie, but the log now only contains this message 2500 times:

19:45:15.505 T:1958396912 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
19:45:15.505 T:1958396912 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
etc

like in the kodi_without_eminence2mod.zip file above. As if Eminence 2 MOD or Skinhelper service is not installed.

I would've expected these kind of log lines:

23:11:46.023 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":2,"type":"movie"},"playlistid":1,"position":1}
23:11:46.024 T:1715516400 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":3,"type":"movie"},"playlistid":1,"position":2}
etc

UPDATE

... and now they are there. It appears the first couple of times I open the set only xbmc is catching them, but now also SH again. So these loglines are still there:

20:05:58.535 T:1609135088 DEBUG: Skin Helper Widgets --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":6190,"type":"movie"},"playlistid":1,"position":504}
20:05:58.686 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":6652,"type":"movie"},"playlistid":1,"position":966}
20:09:03.691 T:1609135088 DEBUG: Skin Helper Widgets --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":7106,"type":"movie"},"playlistid":1,"position":1420}
20:09:03.706 T:1609135088 DEBUG: Skin Helper Widgets --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":7107,"type":"movie"},"playlistid":1,"position":1421

So after a couple of minutes is has gone from e.g. position 504 to 1421. CPU for one of the four threads is contantly 100% and it will take another couple of minutes until it reaches 2261.

Kodi also appears to rebuild this list after each auto-played movie

Each line between the ellipsis represents the endtime of 2261 loglines:

20:15:10.606 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:16:45.723 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:18:03.426 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:18:43.875 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:19:03.256 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:20:35.898 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}
...
20:22:58.832 T:1617523696 DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Playlist.OnAdd - data: {"item":{"id":8148,"type":"movie"},"playlistid":1,"position":2261}

etc

I assumed it would only built the list once and then autoplay the movies. But after each movie that is started automatically, it appears to rebuild this list?

Greetings,

Hablaras