• 1(current)
  • 2
  • 3
  • 4
  • 5
  • 9
Problem scanning huge source (mem leak)?
#1
Hi there,

I've got a problem getting my music source to scan completely :-(

It has only scanned half the source after about 1 hole day. Kodi is crashing and using up all memory:
Code:
# free -m
             total       used       free     shared    buffers     cached
Mem:           735        698         37          5         13         52
-/+ buffers/cache:        632        103
Swap:            0          0          0


Together with that I get some of these:
Code:
ERROR: SQL: [MyMusic60] Undefined MySQL error: Code (1205)


It's a Mysql DB. Kodi is RPi3 with LE 7.95.3

I had kodi hanging some times and after restart, I see mem usage in system-info screen go up rapidly until kodi hangs.

I'll send log to Dave directly.
Reply
#2
Memory issue, interesting. There are other team members looking at a Kodi memory use issue, so is it OK to post your debug log link here incase so more eyes can check it? I don't think there is anything too private in there, but obviously your choice.

If you had a crash do you have a crash log too? Although I rarely seem to get any useful info from them someone else might.

The log only shows ~1 hour of use, was that from the last crash or did you truncate the log to paste?

Quote:I had kodi hanging some times and after restart, I see mem usage in system-info screen go up rapidly until kodi hangs.
Was this always connected with scanning music into the lib? On restart what Kodi screen was on display, or what actions had you taken?

For the db errors in the log
Running MySQL version 5.5.54-0ubuntu0.14.04.1
Error 1205 is "Lock wait timeout exceeded"

Error is logged at 08:31:32.326 after Mysql execute: delete from path... at 08:30:41.808, that is 50.518s later. This makes sense as the default value for innodb_lock_wait_timeout is 50 seconds. But I guess the question is why was the delete of a record taking more than 50s? Was the server busy doing something else (playback of a video perhaps) or temp locked my something? Is that reasonable, and so should the timeout be set to longer on your MySQL server?

The next timeout is at 08:32:24.336 on an insert attempted at 08:31:33.602, (50.734s delay) interrupted by an EPG scan. The subsequent timeout errors all seem to have PVR/EPG tasks, or skin widget data requests happening at a similar time.

My intital suggestion is that you increase the innodb_lock_wait_timeout on your MySQL server, say to 60s at least.

Unfortunately MySQL timeout errors by default do not rollback transactions.This means that there will be music that is incompletely added e.g. have the song entry but not the album genre. I am uncertain how much a library update will be able to fix this, it will depend on what action timed out. So it probably means dropping the music source and starting again just to be sure, but I would test out some scanning first to ensure the timeout errors are gone.

EDIT: It also could be worth starting the server with the --innodb_rollback_on_timeout option so that timeouts do rollback transactions.

At the end of this may well be a "best pratice" guide on setting up Kodi on MySQL server.

Regarding your music collection.
I know you have a lot of music files, and I can see from the log that some previously scanned into the library OK. Can we get some numbers on how many of your files are in the library so far. Either look at the (very very slow) songs node, or look inside the MySQL database directly and check the total number of records in the song table. Also how many music files were on the music source(s)?

Have you added multiple music sources, splitting your collection into chunks, or just one that contains everything?

So that leaves the memory use. Maybe it was related to the db errors in some way, but I don't see why that would be the case. Probably need to exclude it by getting scanning working without MySQL timeout, and then see if you still get memory use problem.
Reply
#3
The timeout occurred on some special albums, as far as I could see. Seemed like a duplicate album I've got under 2 different subfolders and with german Umlaute (Die Ärzte).

Kodi starts on music and there's a widget showing random albums, but this widget doesn't show up after starting kodi...

I started scanning yesterday morning and am now on a little less than the half (60MB DB size). Scanning one album takes longer and longer the further you go. Right now I'm at app 30-40sec per album. You can see what's added with
Code:
tail - f /storage/.kodi/temp/kodi.log |grep open

It's one source only, no chunks. The server's doing nothing but running vdr at 1-2%, serving nfs and Mysql. When kodi is adding to the db, Mysql is running at about 100% on a dual core (virtual quad, Intel atom).

There's no crash log, as it's kodi being restarted cause of memory issue. Journalctl gives kernel warnings cause of ram and stops services to keep alive

Quote:total number of records in the song table
I sadly don't talk sql, have you got the query on that?

The pvr updates are epg only as vdr has its own epg data, I don't use epg db.

In Jarvis I had that source added completely. Between Jarvis and Krypton import on a fresh db, I "only" tagged about 80% of the files with MB. (you know, 90% laptop 10% kodi 10ft :-)

As I'm writing here, I had 2 hang ups already with
Code:
watch - n1 free -m
being at 20MB free ram, no errors in kodi log. Only rebooted, waited till 'housekeeping' is done and restarted db update. So no timeouts in Mysql

Quote:Unfortunately MySQL timeout errors by default do not rollback transactions.
Hm... then, if that happens, no one knows about... :-(

I definitely can say from the last hang, there were no timeouts

Here's journalctl
http://sprunge.us/OVEU

There's nothing of interest, as far as I can see in debug.log. I'll send it to you

A crash log wouldn't be of any great help as no debug symbols are in LE's kodi. Maybe I can get some...
Reply
#4
Btw, adding one album takes 30-40s average once db has that size
Reply
#5
An hour long kodi is now scanning further. No timeouts or errors.

2 mem hick ups were seen. One time up to 28MB free and recovering (no kodi restart) and a while it was on 200 free, although else it is 380MB free
Reply
#6
Ok, this morning kodi was hung up again and restarting lead to out of memory, so I dropped music db and restarted scanning.

Before dropping db:

In mysql-slow.log I found:
Code:
# Time: 170213  8:15:06
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 15.317274  Lock_time: 0.001682 Rows_sent: 171966  Rows_examined: 952844
SET timestamp=1486970106;
SELECT songview.*, songartistview.* FROM songview JOIN songartistview ON songartistview.idsong = songview.id
ong  WHERE ((CAST(songview.iTimesPlayed as DECIMAL(5,1)) < 1)) ORDER BY songartistview.idsong, songartistvie
.idRole, songartistview.iOrder;

I remembered having enabled status line in skin settings, which displays song, album and artist count when on music in main menu, but it was disabled. So I don't know, why that query is done when kodi starts?
I also disabled music widgets prior to the next step

Dropping db:

I added
Code:
innodb_lock_wait_timeout=60
innodb_rollback_on_timeout=1
to my.cnf
and dropped music db, rebooted
Scanning is now in progress and one album needs app 2-3s instead of 30-40s. It will surely get slower, whyever that is? Why is it, scanning gets slower and slower the more files were scanned?

What I even noticed in mysql logs was that although kodi was hung up, restarting mysql lead to killing kodi threads which seemed still open in mysql log
Reply
#7
(2017-02-13, 09:57)Rusendusen Wrote: Ok, this morning kodi was hung up again and restarting lead to out of memory, so I dropped music db and restarted scanning.
So starting again from the beginning, I think you may as well stop that.

I have not had time to digest everything, but I am pretty sure that having all your music (200k songs was it?) in one single music source is a bad idea. You have done that test, and Kodi broke. Instead can you divide it into more sources and add/scan into the lib one at a time.

Edit:
We have 2 kinds of test here:
a) Can we scan that many items into the library, and how best to do that
b) If we can get that in there, can the library function (or what breaks)
Reply
#8
I need to get some leverage on all this, find the best place to stick the crow bar (I hope that translates!).
Here are my mumblings...

Eating up memory and getting slower to scan an album would seem to be related. Some kind of caching? Is there a step point in number of songs processed when it begins to slow, or is it gradual? Is it the large debug log?

The log files you sent are very moderate in size, scanning for hours where is the rest?

Don't think the name "Die Ärzte" is reason for timeouts, many of the SQL updates that timeout were on album_genre table. They were however repeats of the same genre, but that is normal.

These music files, before being tagged with mbids, loaded into music lib in Jarvis.
As one music source?
Debug off or on?
Picard tagging does add data - musicians, composer etc. so the db will be bigger. But are duplicated albums (same mbids) causing some issue?

What is calling a query of all unplayed songs on start up?
Estuary skin, try swap to Confluence? An addon? I can't replicate on my system.
Can the timestamp in the MySQL_slow.log be matched to entries in Kodi.log?

~~~~~~~~~~

At this point I need some more input. @Rusendusen maybe you have answers to at least some of the above questions?
Reply
#9
(2017-02-13, 11:47)DaveBlake Wrote: Eating up memory and getting slower to scan an album would seem to be related. Some kind of caching? Is there a step point in number of songs processed when it begins to slow, or is it gradual? Is it the large debug log?

The slowing down is gradual from what I can tell. It starts quite fast, but slows down with each album added. After half an hour it was already from 2-3s to 5-6s.
There's no connection between mem usage and number of songs. Kodi is mostly at same memory usage but suddenly starts eating up quite fast (300MB free ram eaten up in just seconds until kernel throws OOM, out of memory, see journal).

Quote:The log files you sent are very moderate in size, scanning for hours where is the rest?
I've only got kodi.log and kodi.old.log, so cause of several restarts, I've only got the last

Quote:These music files, before being tagged with mbids, loaded into music lib in Jarvis.
As one music source?
Debug off or on?
Picard tagging does add data - musicians, composer etc. so the db will be bigger. But are duplicated albums (same mbids) causing some issue?
With Jarvis I had not tagged with mbids. I did MB tagging prior the switch from 16 to 17.
Yes, the source was read in as one source in Jarvis

Quote:What is calling a query of all unplayed songs on start up?
Estuary skin, try swap to Confluence? An addon? I can't replicate on my system.
Can the timestamp in the MySQL_slow.log be matched to entries in Kodi.log?
I rechecked settings, using xonfluence as skin. There are settings for calculate number of songs and status line which shows statistics, no. of albums, artists, songs
I've deactivated these settings already.
The entry in mysql-slow is from when kodi starts. I'll have a closer look when at home.

What I'm going to do is take a fresh LE 7.95.3 on another SD card and just adapt advancedsettings to use Mysql. Will then try again on a clean base. Have downgraded to 7.95.2 already this morning

~~~~~~~~~~

Quote:At this point I need some more input. @Rusendusen maybe you have answers to at least some of the above questions?

I'll first try to sort out the timeouts. Haven't had them lately and changed innodb settings already.
Second will be to use a clean base and maybe use kodi on my laptop to sort out RPi3 or LE issues
Third, I'll try to fetch as many logs as possible (kodi, journal, mysql) for to compare timestamps throughout different logs
Reply
#10
Great more input comming Smile

Can you confirm that when scanning on Jarvis you did not have debug on? I do wonder if that is where the memory is going, or at least some?

Xonfluence skin, switch to Confluence please, nice common ground for me.
Reply
#11
I have debug on since possibly the very beginning Wink

Ok, so I'm back home now. Scanning started this morning is still running, but has not reached the level I started this thread.
It's LE 7.95.2 right now, so not latest Beta

Did check some logging parallels:

mysql-slow.log:
Code:
# Time: 170213 15:53:07
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 12.660630  Lock_time: 0.001491 Rows_sent: 137472  Rows_examined: 753738
SET timestamp=1486997587;
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;
At that time kodi.log shows:
Code:
15:53:06.697 T:1391403936   DEBUG: Mysql execute: UPDATE song SET dateAdded='2017-02-09 02:06:37' WHERE idSong=32129
15:53:08.013 T:1961804704   DEBUG: CAnnouncementManager - Announcement: OnUpdate from xbmc
15:53:08.013 T:1961804704   DEBUG: GOT ANNOUNCEMENT, type: 32, from xbmc, message OnUpdate

There are no Mysql timeouts
Code:
cat kodi.log | grep Undefinded
gives nothing

Found another:

mysql-slow:
Code:
# Time: 170213 17:07:08
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 15.029499  Lock_time: 0.001206 Rows_sent: 146388  Rows_examined: 805031
SET timestamp=1487002028;
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;
and kodi.log:
Code:
17:07:08.572 T:1829761952   DEBUG: GetAlbumsByWhere - query took 2247 ms
memory usage goes up at this time (mysql-slow errors show up) but kodi did recover until now.

The last one at 17:18
Code:
# Time: 170213 17:18:22
# User@Host: kodi[kodi] @ libreraspi [192.168.5.20]
# Query_time: 13.821188  Lock_time: 0.002915 Rows_sent: 148206  Rows_examined: 814852
SET timestamp=1487002702;
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;
lead to a hung up system cause of OOM

No ssh access possible anymore. I'll wait if kernel OOM manager kills/restarts kodi

I don't know what's causing these queries, but its corresponding to the "DEBUG: GetAlbumsByWhere - query"
Reply
#12
Have your server and RPi got clocks set to the same time? Or maybe the MySQL-slow.log time is the end of the slowness while the kodi.log event would be at the begining.

Whatever, it is not GetAlbumsByWhere that calls the unplayed songs query - that is not in the code, and anyway it also reports that the query took 2247ms

I still suspect Xonfluence for calling unplayed songs, and for anyone with such a large lib it is a disaster to be querying all the songs randomly. But I am also shocked that MySQL takes so long to do the query, but I guess it is already busy with the scans loading. At least I can see you have 148206 songs scnned so far.

And the memory hang is just after? Do we know that for sure?

When you restart Kodi switch to Confluence skin before scanning.
Reply
#13
I was observing the logs and free and noticed free was down to 23MB when the system hung up, so I looked at the logs around that time.

Clocks are running in sync (ntp)

No, its at 35740 from round about 150k
Code:
17:18:23.298 T:1391403936   DEBUG: Mysql execute: UPDATE song SET dateAdded='2017-02-10 15:56:42' WHERE idSong=35740

Is Estuary ok, too?
Reply
#14
Of course 148206 was a join..... silly me. Up to 35740 songs so far, do you know how many files you have? Going to assume that it is individual files per song rather than cuesheets unless you tell me otherwise.

Estuary has more widgets than old fashioned, tried and tested Confluence, that might try and query something silly. But Estuary if you have to, the author isn't a fan of the songs node so probably has not added anything that would query it.
Reply
#15
Ahhhh ... I still get this ominous query even with confluence!?

Could it be, as this query takes about 15s, that kodi is scanning further and mem is filling up?
Reply
  • 1(current)
  • 2
  • 3
  • 4
  • 5
  • 9

Logout Mark Read Team Forum Stats Members Help
Problem scanning huge source (mem leak)?0