[Uatschitchun]

First off, this is a mem.log from this afternoon running with Xonfluence. Just out of curiosity
http://sprunge.us/XKic

Sadly there wasn't any crashes as I did hope we get some useful information out of them because of having debug symbols ;(

Code:
SELECT count(idAlbum) as albumtotal FROM album;

Code:

MariaDB [MyMusic60]> SELECT count(idAlbum) as albumtotal FROM album;
+------------+
| albumtotal |
+------------+
|       8106 |
+------------+
1 row in set (0.15 sec)

Results:
Ok, what definetly is to state is, one query after the other, giving every query time to finish, shows correct behaviour as fas as I can tell. You can see that from the beginning of the mem.log. It's about 420MB free and each query uses up memory but releases it again short time afterwards.
I first tried JSON 3 with N=800, N=1500, N=3200, N=6400 and N=10000. Sadly (luckily) I can't reproduce a leakage with this.
Then I tried JSON 2 and got the same beahviour.

What's relevant, as LDP not only asks MyMusic, but also MyVideo, is that when multiple queries come together, the memory isn't recovering (buffering/cache?). For it being a caching issue speaks, that later on some queries do not use up memory so the queriy seemd to be cached/buffered.

It is viewable from the mem.log, that from starting with 420MB free, we do not get this allocated memory back, Mem.log is kept running while I'm writing and is about 313MB free atm with no sign of coming back to 420... (it isn't 420 friendly so to say

So from my observations and tests the following is to be kept:
* limiting the number of queried items (N) not uses up that amount of memory as JSON 2 (logical)
* running only one qurey after the other (even JSON 2) leads to memory being allocated and freed again.
* JSON 1 is definetly out of the race. Even fireing up 10 queries in a row doesn't hurt
* Once doing multiple heavy queries "simultaniously", in this case here multiple JSON 2 (like LDP probably does as it also queries Movies, Series, etc) eats up memory without giving it free again. (I would maybe need to adapt the mem.log script to also take buffers/cache into account)
* In some cases issuing a query after waiting some time frees up memory!?
* Multiple queries at once or in a short time lead to using up memory without giving it free again completly (no 420 reached ever agin). So if not after say 10-20min the buffers/cache aren't given free again or being reuseable, the memory fills up slowly but steady, You can see that in logs at about 22:40 when I fired 3 Json 1, 3 Json 2 and 3 Json 3 (N=3200) and after that 5 JSON 2 reduces memory from about 300MB to 220MB without freeing.
* Remarkable: Even JSON 2 takes round about 400ms on mysql side, but 30sec until web request is finished!!
* I let the mem.log run a little more now (10min) until I upload the logs for to see if memory returns...

I'll check against Chewitt's build asap

One thing I have to tell is, the Amlogic Box running kszaq's build is not using the same AudioDB as the RPi...
It has 2 profiles. One using another audio source (Audiobooks and Radioplays) with far less files! I'll let it run on the other profile against the "normal" music and see ... sorry, forgot about that somehow. So maybe also the Amlogic Box is suffering ^^!

So, now it's 10min later and mem is only up to 255MB free, so I'll upload...

kodi.log & memory.log

Gn8

[DaveBlake]

Excellent stuff Roman :Cool:
Many thanks for your persistent testing, all down to processing overlaping JSON requests. I can dig onto that. It also possibly means this is not platform dependant either, just that RPi exposes the issue more immediately.

*Remarkable: Even JSON 2 takes round about 400ms on mysql side, but 30sec until web request is finished!!

Indeed. It shows how the slow node issue is not about db schema design, efficient queires, indexes etc. and all about what Kodi does with the resulting dataset.

Not to say that good DB design doesn't matter, obviously it does, but Kodi is currently throttled by how the retrieved data is subsequently handled.

[Tolriq]

About JSON and rpi, one big issue is the JSON encoding part too.

There was an attempt to change the library used https://github.com/xbmc/xbmc/pull/8008 for a more efficient (both memory and cpu) one but it was never finished, maybe someone can get it on track again

That's one of the main reasons nearly any JSON consumers use small chunks to get the data on those devices.

This needs to be taken in accounts for perf maths

[Uatschitchun]

Good to know it's helpful! :-)

What I still don't get is how fast the memory in real life (with using Xonfluence) is eaten up (see the first mem.log) against these tests. There seems to be more flaws waiting under the hood...

I'm looking forward to what influences a change to rapidjson will have. But if the switch will be done, we'll surely get a Milhouse build to see :-)

Nevertheless, even if the improvements coming out of this will not show big on other platforms, the "Schwupdizität" will surely improve on these, too.

If there's anything I can do to support...

If @chewitt is reading, it would be nice to know, at what point he thinks the provided build will help.

[DaveBlake]

By throwing a rapid fire of heavy JSON GetSongs calls at a large MySQL music lib (140k songs) v17.0 on Win32 I managed to reproduce the memory leak. So it is not just RPi or LE, or at least some elements aren't.

I used one of the queries that the LDP addon triggers - 20 random songs with artist data.

Code:

jsonrpc?request={"jsonrpc": "2.0", "id": "1", "method": "AudioLibrary.GetSongs", "params": { "limits": { "start" : 0, "end": 20 }, "properties": [ "title", "playcount", "genre", "artist", "album", "year", "file", "thumbnail", "fanart", "rating", "lastplayed"],"sort": { "method": "random"} }}

Note v17.0 implementation of this request is horribly inefficient and fetches all the songs into memory before selecting 20 random ones to return. Fixed for 17.1, but useful here because it uses heaps of memory internally, but only a small amount is returned through JSON.

Implication is that it is the memory used within overlapping CMusicDatabase::GetSongsFullByWhere() calls that isn't being cleared fully, rather than JSON output. Next is to see if SQLite will do it too.

What I still don't get is how fast the memory in real life (with using Xonfluence) is eaten up (see the first mem.log) against these tests. There seems to be more flaws waiting under the hood...

Maybe, I guess there could be other issues in the addons themselves, but that is not my thing.

We have shown that the kind of JSON requests that the LDP addon makes can cause memory leaks if they happen at the same time on a large library. That is a core issue, and needs resolving.

Nevertheless, even if the improvements coming out of this will not show big on other platforms, the "Schwupdizität" will surely improve on these, too.

Is that German for memory leak?
Google gave me "sloppiness" as a translation

But yes this is well worth pursuing. Such a large lib on MySQL is not average use, but it has exposed issues that will benefit all platforms once they are resolved.

[DaveBlake]

Even better....
After trying really hard I got a memory leak on SQLite as well (v17.0 Win32)

A JSON GetSongs call returning 11k of records, repeated but waiting for each command to complete, also eat memory on SQLite. Initially a big chunk, but left alone for 15mins and something clean ups evetually (nothing in debug log to tell me what).

So overlapping calls or return lots = memory leak.
But I need to a) re-test, b) work out why

[Uatschitchun]

I managed to reproduce the memory leak. So it is not just RPi or LE, or at least some elements aren't.

Ah.. nice
That will make fixing easier!

Implication is that it is the memory used within overlapping CMusicDatabase::GetSongsFullByWhere() calls that isn't being cleared fully, rather than JSON output. Next is to see if SQLite will do it too.

That's what I found with testing. Must be something happening when overlapping queries apper.

the "Schwuppdizität" will surely improve

Is that German for memory leak?
Google gave me "sloppiness" as a translation

lol, no, it's an invented word from a german pc magazine coming from "Schwuppdiwupp" (presto, blink of the eye, quickly) and is meant as a felt speed of a computer. Some kind of reactiveness, responsivity

[Uatschitchun]

So overlapping calls or return lots = memory leak.
But I need to a) re-test, b) work out why

I told you I was feared as a bug hunter

If I can help ...

[DaveBlake]

So overlapping calls or return lots = memory leak.
But I need to a) re-test, b) work out why

I told you I was feared as a bug hunter

If I can help ...

Feared by bugs or devs?

I have got a sore finger from pressing F5, but I do have a repeatable leak. I can skip all the CFileItem sorting and storing etc. and still get an issue, so it is on the dataset management side of things. It happens on both MySQL and SQLite so is not a product issue, but more in the way Kodi has implemented them in the generic wrapper. Process more than one query simultaneously and a little something goes missing.

But I am stuck at that point for now

When I have a fix to test you will be my first contact.

[Uatschitchun]

Feared by bugs or devs?

Both

[DaveBlake]

Ha, ha. I'm pretty good at breaking things myself. :p
I consider it a useful skill, no fears. As I have said, I appreciate users that test rigorously, report clearly and persist!

For Krypton I fear it will be a matter of not using LDP with a very large library, or maybe an addon fix to space out the requests. Not sure we can get a full fix into the 17.1 deadline, given it seems to be a db wrapper issue (and I haven't found the exact problem yet). Despite how it shows up for your vast library on a RPi, it is not easy to reproduce generally. I've had to really push my win32/SQLite version to show it.

But testing with a large (fake) lib has brought home the difficulties that a large library presents. Will see what improvements I can make for v18 for sure.

[DaveBlake]

Just for the record (and meditation purposes) here is a plot of the memory log from above (MySQL and RPi)


After overlapping calls, there is some phased recovery, but never back to the beginning levels. In my testing I have tried waiting, but "natural healing" does not happen.

Here fetching fewer albums takes less memory, but the leak still happens. In my testing (on win32 and SQLite) I seem to need to fetch large amounts of data to see this issue.

Thread safety has been discussed as a possible cause, but every JSON call in effect initiates its own connection to the db so this does not seem to be the issue.

[DaveBlake]

Since you have had some time off Roman, a bit more testing for you.
I just want to try out a hunch if you are up for it, and your data gathering is better than mine on Windows.

JSON command No.4

Code:

http://<RPi IP address>/jsonrpc?request={"jsonrpc": "2.0", "id": 1, "method": "audioLibrary.Getalbums", "params": { "limits": { "start" : 0, "end":1000 }, "properties": ["title", "description", "albumlabel", "theme", "mood", "style", "type", "artist", "genre", "year", "rating", "playcount"] } }

Replace <RPi IP address> of course.

Maybe modify the end limit of 1000 depending on how things go.

Try this with rapid repeats on Kodi without Xonfluence or LDP or Skin Helper Service addons etc., and this time also turn off the TV Show - Next Aired addon (enabled by default in v18), keep the log nice and clean.

If you can report the memory and kodi debug log just as you did before that would be great.

My hunch is texture related, hence not requesting artwork this time otherwise the JSON processing uses the thumbnail loader. Flailing around a bit with this really, but worthwhile since your Pi and real library are more sensitive than my test setup is to this issue.

[Uatschitchun]

Nice graph... already meditating on it :-)

I'll see that I can come up with some results tomorrow!

[DaveBlake]

Om.... Om.... Om....

Sadly I fear my hunch is a bust
So do something more fun with your Sunday.