[DaveBlake]

Ahhhh ... I still get this ominous query even with confluence!?

Then it isn't skin related. But what is calling for unplayed songs? Ahhhh!

Could it be, as this query takes about 15s, that kodi is scanning further and mem is filling up?

Isn't that 15mins, or have I been misreading?

What happens if you aren't scanning. Just start and wait. Can you see a log of all the MySQL activity. I want to catch it even it ithappens quickly on a server that isn't receiving scanned data.

[DaveBlake]

In the log without timesouts the query for unplayed songs happens shorty before

Code:

CWebServer[8080]: request received for /jsonrpc

Do you have Chorus or a remote app (Kore, Yatse etc) connected to Kodi?

Something is asking for unplayed songs, it could be an addon (as we have ruled out skin widget), but Kodi left alone does not do this.

If you view albums in Estuary then it gets the songs for that album, but that is not all the unplayed ones. Songs node gets all songs, played or otherwise.

[Uatschitchun]

Some more results:

memusage over time

Code:

13/02/2017 19:42:36 454 281
13/02/2017 19:42:37 468 266
13/02/2017 19:42:38 483 251
13/02/2017 19:42:39 499 235
13/02/2017 19:42:40 515 220
13/02/2017 19:42:41 570 165
13/02/2017 19:42:42 640 95
13/02/2017 19:42:43 701 34
13/02/2017 19:42:44 686 49
13/02/2017 19:42:45 686 49
13/02/2017 19:42:46 686 48
13/02/2017 19:42:47 688 47
13/02/2017 19:42:48 688 46
13/02/2017 19:42:50 689 46
13/02/2017 19:42:51 689 46
13/02/2017 19:42:52 689 46
13/02/2017 19:42:53 689 46
13/02/2017 19:42:54 579 156
13/02/2017 19:42:55 579 156
13/02/2017 19:42:56 579 156
13/02/2017 19:42:57 579 156
13/02/2017 19:42:58 579 156

mysql-slow:

Code:

# Time: 170213 19:42:40
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 14.180622  Lock_time: 0.001509 Rows_sent: 152960  Rows_examined: 842683
SET timestamp=1487011360;
SELECT songview.*, songartistview.* FROM songview JOIN songartistview ON songartistview.idsong = songview.idsong  WHERE ((CAST(songview.iTimesPlayed as DECIMAL(5,1)) < 1)) ORDER BY songartistview.idsong, songartistview.idRole, songartistview.iOrder;

kodi.log:

Code:

19:42:26.773 T:1797256096   DEBUG: GetSongsFullByWhere query = SELECT songview.*, songartistview.* FROM songview JOIN songartistview ON songartistview.idsong = songview.idsong  WHERE ((CAST(songview.iTimesPlayed as DECIMAL(5,1)) < 1)) ORDER BY songartistview.idsong, songartistview.idRole, songartistview.iOrder

So from my understanding, its this query that leads to leakage

Until now with only a hick-, not a hung up

[DaveBlake]

What is the rest of that kodi.log please, some sign of what is calling GetSongsFullByWhere

[Uatschitchun]

For logging to a file, times are written including the microseconds part.

From:
https://dev.mysql.com/doc/refman/5.7/en/...y-log.html

Some food for thought:

Code:

cat .kodi/temp/kodi.log | grep "GetSongsFullByWhere" | paste

http://sprunge.us/DLFa

Code:

mysql-slow

http://sprunge.us/GKGf

Code:

memusage

http://sprunge.us/BEHj

kodi.log takes a while to upload

I removed this host from all yatse apps, but still get JSON calls...

[Uatschitchun]

Code:

cat kodi.log | grep -C 20 "GetSongsFullByWhere" |paste

http://sprunge.us/OPgL

[Uatschitchun]

Btw, kodi's systeminfo shows about 80MB more free memory than "free -m"!?

[DaveBlake]

Logs helpful, have you heard my cogs grinding?

My current thinking is that it is a skin support addon called "Library Data Provider" that is randomly causing a number of background queries including the GetSongsFullByWhere query for unplayed songs. Could you check if you have this addon installed, and disable it if you do.

Finding out what is causing this query to execute is the first step, and if we can stop it doing so then that will be useful.

Next is to understand why it seems to eat memory and cause a crash. The memory issue could involve something else too, but having this run while trying to scan a vast music collection is obviously problematic. I can't comment of the differences in reported free mem, the LE people are most likely to know. But really we need to pin down what is eating the memory - what happens to the song data fetched - to be able to ask the right questions..

EDIT:
Once enabled Library Data Provider keeps fetching data every now and then, even if no skin is ever going to display it. The Library Data Provider addon call is causing something like the songs node processing to happen. On a separate thread so UI nor scanning jam, but memory consuming as well as slow. It should free that memory correctly, but I'm not sure what happens if there isn't enough free to start with. I don't think it bothers to check.

I want to prove that is the problem by turning it off, and then see what else we find.

[Uatschitchun]

Ah ja ... that's it?! Library Data Provider... Heard something strange, didn't thought it was you

Its coming with Xonfluence. It seems still active with other skins.

No mysql-slow, mem usage is +/- 100MB. Am up to 35MB DB.

Slowing down in scanning continously

[DaveBlake]

Yes once Library Data Provider is installed with a skin it stays enabled and randomly querying the databases even if you change to skin that does not use it, and the data fetched is not displayed.

This is made worse by the fact that Kodi (not the db) handles the request for 20 random unplayed songs really inefficiently (fetchs all the songs and their musicians from the db and manipulates the results dataset into other object list within list structures in memory, and then picks just 20). I am going to fix that!!

So your testing has been very useful so far, I did not know Library data Provider even existed let alone the inefficient queries it invoked in the background.

So where are we with scanning your music collection? How many songs?
To get a song count the SQL is

Code:

SELECT count(idSong) FROM song

You will need to look at your db using a tool like Heidi or PHPMyAdmin or MySQL Workbench....

Scanning is still getting progressively slower? But memory use on Pi now stable, or still increasing?

[Uatschitchun]

Ok, at 9:42 I stopped scanning. No hang ups until now, but still these in mysql-slow:

Code:

# Time: 170215  9:44:14
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 19.030705  Lock_time: 0.001124 Rows_sent: 191982  Rows_examined: 1344274
SET timestamp=1487148254;
SELECT songview.*, songartistview.* FROM songview JOIN songartistview ON songartistview.idsong = songview.idsong  WHERE ((CAST(songview.iTimesPlayed as DECIMAL(5,1)) < 1)) ORDER BY songartistview.idsong, songartistview.idRole, songartistview.iOrder;

every 10 minutes, LDP-Addon is deactivated!
It's Estuary, so I guess the widgets are provoking these...

As said, without LDP no hang ups, but huge mem usage and no freeing again, see:

Here's mysql-slow.log
http://sprunge.us/AbWh
and the one before:
http://sprunge.us/ZSPT

15 minutes after I stopped scanning, these are memory results:

Code:

# free -m
             total       used       free     shared    buffers     cached
Mem:           735        673         62          7         10         68
-/+ buffers/cache:        594        140
Swap:            0          0          0

Code:

# cat /proc/meminfo
MemTotal:         753336 kB
MemFree:           63740 kB
MemAvailable:      94792 kB
Buffers:           10288 kB
Cached:            70152 kB
SwapCached:            0 kB
Active:           623972 kB
Inactive:          35604 kB
Active(anon):     583356 kB
Inactive(anon):     3672 kB
Active(file):      40616 kB
Inactive(file):    31932 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                20 kB
Writeback:             0 kB
AnonPages:        579020 kB
Mapped:            35632 kB
Shmem:              7892 kB
Slab:              17912 kB
SReclaimable:       7120 kB
SUnreclaim:        10792 kB
KernelStack:        1680 kB
PageTables:         2556 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      376668 kB
Committed_AS:     761392 kB
VmallocTotal:    1310720 kB
VmallocUsed:           0 kB
VmallocChunk:          0 kB
CmaTotal:           8192 kB
CmaFree:            6592 kB

You see, mem is still fed up and doesn't recover. Kodi reports:

watch gallery

Here's mem-usage-log
http://sprunge.us/CMHc

DB is now at 82MB with

Code:

mysql> SELECT count(idSong) FROM song;
+---------------+
| count(idSong) |
+---------------+
|         49848 |
+---------------+
1 row in set (0.05 sec)

That's app 1/3

I'll upload the current kodi.log right now... as kodi crashed few minutes ago, it'll be a crashlog

Yes, scanning gets slower and slower. You can see that from the logs!
Every 'commit transaction' is an album from what I can tell, so here's a comparison:

Code:

17:02:52.180 T:1498411936   DEBUG: Mysql commit transaction
17:02:58.739 T:1498411936   DEBUG: Mysql commit transaction
17:03:02.406 T:1498411936   DEBUG: Mysql commit transaction
17:03:05.381 T:1498411936   DEBUG: Mysql commit transaction
17:03:10.659 T:1498411936   DEBUG: Mysql commit transaction
17:03:15.177 T:1498411936   DEBUG: Mysql commit transaction
17:03:17.226 T:1498411936   DEBUG: Mysql commit transaction
...
09:28:37.867 T:1498411936   DEBUG: Mysql commit transaction
09:29:04.666 T:1498411936   DEBUG: Mysql commit transaction
09:29:38.820 T:1498411936   DEBUG: Mysql commit transaction
09:30:14.659 T:1498411936   DEBUG: Mysql commit transaction
09:30:32.321 T:1498411936   DEBUG: Mysql commit transaction
09:30:53.451 T:1498411936   DEBUG: Mysql commit transaction

It's 3-6s in the beginning of log after disable of LDP and app. 30s this morning. As it's 1/3 of source, I'm 5times up already. So 5 times more for 2/3 and 5 times for 3/3 would be 25*30s=12,5m per album

I'm going to use a fresh sd-card with latest LE (7.95.3) and all standard, but advancedsettings for mysql and no online info while scanning and start from where I am right now with scanning further...

Anything other I can help with?

[DaveBlake]

So we are ~50000 songs out of ~150k, quite a collection

So LDP addon disabled, yet we still get the unplayed songs query
Did you restart Kodi after disabling it? I am wondering if the addon starts a thread that disabling doesn't terminate. May even need to power down the RPi?
It isn't Estuary calling it, I have had that running in debug for hours and don't get any song queries at all.
At least it is a slow query so we can clearly see it has happened!

That unplayed song query is going to need memory but it should give it back. The vanishing memory could be down to an issue in scanning itself, or related to a more general memory issue some other guys have been looking into that only shows when lots of memory is used and the released repeatedly. I don't know the details of the latter, but I will find out. The slow down of scanning could easily be memory related, so a little chicken and egg.

I need to get you running without the unplayed songs query happening every 10 mins, and then we can see where we are.

I'm going to use a fresh sd-card with latest LE (7.95.3) and all standard, but advancedsettings for mysql and no online info while scanning and start from where I am right now with scanning further...

OK, Estuary out the box, no LDP addon!!!!

The downside with having only one music source pointing at your entire collection is that Update Library will scan the time/size hash of every file it has scanned so far looking for changes, before it gets to the files it has not scanned before. That just takes time. You could circumvent that for testing purposes (get quicker answers) by using scan from context menu when in File View to start scan of a subfolder. In the end we can do Update Library to check we didn't miss anything, because I realise that the crashes have left you midway through a folder.

I leave you to choose over that. I would recommend in principle having multiple sources to break your collection up into more manageable pieces. But we have started with one big lump, so I guess we see that through.

All useful stuff, thank you.

[docwra]

I'm a bit late, but just a note that when testing like this you should always start from a blank install with the default skin and no extra Add-ons.

I'm importing 50,000+ and not had any issues with sqlite. It might be worth testing that as well first to see if you can identify the issue.

[Uatschitchun]

Can give some positive feedback. With a clean SD-card (LE 7.95.3) scanning is now at 100k songs with 135MB DB. No unplayed song queries, no mysql-slow errors!!

Scanning speed isn't glorious, but not that slow as expected:

Code:

06:44:39.754 T:1763701664   DEBUG: Mysql commit transaction
06:44:52.128 T:1763701664   DEBUG: Mysql commit transaction
06:45:04.151 T:1763701664   DEBUG: Mysql commit transaction
06:45:16.227 T:1763701664   DEBUG: Mysql commit transaction
06:45:28.227 T:1763701664   DEBUG: Mysql commit transaction
06:45:40.930 T:1763701664   DEBUG: Mysql commit transaction
06:45:52.821 T:1763701664   DEBUG: Mysql commit transaction
06:46:04.248 T:1763701664   DEBUG: Mysql commit transaction
06:46:17.282 T:1763701664   DEBUG: Mysql commit transaction
06:46:19.473 T:1763701664   DEBUG: Mysql commit transaction
06:46:21.399 T:1763701664   DEBUG: Mysql commit transaction
06:46:23.557 T:1763701664   DEBUG: Mysql commit transaction
06:46:34.568 T:1763701664   DEBUG: Mysql commit transaction
06:46:46.117 T:1763701664   DEBUG: Mysql commit transaction

About 12s per album

It feels like really these queries were the reason. Memory is slowing filling up during scanning, but somehow recovers again

[DaveBlake]

Can give some positive feedback. With a clean SD-card (LE 7.95.3) scanning is now at 100k songs with 135MB DB. No unplayed song queries, no mysql-slow errors!!

Great!

About 12s per album

It feels like really these queries were the reason. Memory is slowing filling up during scanning, but somehow recovers again

I had my suspicions. :p
But very interested to know if we get either a slow down, and or memory permanently taken over the long run. There still could be other issues for you to unroot.