Out Of Memory exceptions on Raspberry Pi 2

[bhaal275 0]

Hey,

 

I'm trying to run Emby Server on Raspberry Pi 2, using the official download taken from here: https://emby.media/community/index.php?/topic/43166-arm-devices-official-instructions/

 

I installed the server directly, as the Docker version doesn't seem to work (doesn't expose ports by default), and seems to be a bit older.

 

When the server runs, I see the app wizard, and I'm able to go through the whole wizard. The problem starts then the app starts to scan my media library. It crashes after some time with Out Of Memory exceptions in the logs coming from trying to run `ffprobe` on my files.

 

I attach the log file for reference. 

 

Does anyone has an idea what this might be connected to? I'd appreciate any help.

 

Cheers,

Dom

server-63625030093.txt

[trifleneurotic 63]

https://emby.media/community/index.php?/topic/39814-media-scanner-crashes-on-raspberry-pi-2/

https://emby.media/community/index.php?/topic/26171-out-of-memory/

 

These issues are similar but not the same. It was suggested that perhaps the permissions on ffprobe aren't set properly (can be fixed using chmod), or perhaps Mono's nursery size needs to be reduced.

 

Just a couple of ideas (:

[grant.g 0]

I'm running into the same issues, I believe.   I just installed Emby 3.2.10 on a Raspberry Pi 3.  I'm using it for music only - with a collection of about 46,000 tracks (mostly mp3).  I had a bit of a struggle getting mono to update to v4, that turned out to be the result of some hoops I'd gone through a few weeks back for Php.  

 

About 30 minutes into the initial media scan, emby crashed silently, with nothing special in the log.  After restarting, it ran for a while and crashed again.   I did manage to observe that its memory usage had got up to about 90% of the Pi's memory.   I also noticed that the Raspian swap was tiny.  So, I reconfigured the swap system to a much larger size.  Emby no longer appeared to crash silently, but now there are quite a few errors in the log about ffprobe having insufficient memory. 

 

(I've attached a clip of one such fault.)

 

At that point I found this posting and adjusted Mono's nursery to 64M and things appear to have settled down.

 

I'm not sure if that's the end of the story -- the scan still has a long way to go -- but I thought I'd report my experience. 

 

I am curious about what exactly ffprobe is doing during the scan, and why it is memory hungry.

 

G.

 

log.txt

[Luke 42078]

hi @@grant.g thanks for the info !

[grant.g 0]

Update:

 

The media scan completed over night, however, it looks like the albums processed before I changed the nursery size have no tags or cover images.  (Just the raw names from the filesystem.)

 

I tried to re-run the scan from the dashboard, but that ran through the library in 7 minutes and failed to pick up the missing data.   

 

Is there any way to repair this, or must I remove the library and start again ?

 

G.

[Luke 42078]

You can refresh titles from the detail screens using the 3-dot menu. Or you can remove and re-add.

[grant.g 0]

Hi Luke

 

I'm starting to get lost trying to keep track of everything that's happening - and not happening.

I removed my music library, and re-created it.  The media scan started up, but after a few minutes the dashboard showed "stopping" in red ink.  

 

On a whim I decided to restart Emby at that point, and then again I removed the library and re-created it.  This time things were more a little more successful - the media scan ran for about 4 hours.  It found all my tracks, and stored all the tag data.  However, it had still only found about 30% of the cover images (which are all stored in the tracks).  I was able to browse around through my music in all the ways I expected.  There are 2000+ albums.

 

I clicked on the menu on the Music library in the MyMedia screen and went to the refresh page.  I asked it to refresh the images.  It reported that the refresh was "queued".   I do see that ffprobe is once again popping up on my process list, but I don't seem to have any other way to see what's going on.  There's no Library scan reported on the dashboard and no progress indicator.  

 

I tried enabling the "debug log" checkbox on the logs page, but that does not appear to have produced any additional output in the log file.  

 

....

 

Before attempting to install Emby on the Pi3, I did have it running on my laptop (running windows 10) to see if it provided the user experience I was looking for.   Among all the systems I've tried (including Subsonic and Plex) Emby seems to have the best set of capabilities, so I'd really like to get it working.   I'd like to be able to provide better debugging information, but these silent failures are frustrating and I can only keep so many random visual observations in my head.

 

FYI, the Pi3 is NOT running on an SD card, it has a real USB/SCSI hard drive, and there are NO kernel messages in the system logs. 

 

But, poking around in /var/logs, I just discovered that the media scan is writing to /var/log/syslog -- not to the emby log files.  That's something I can look into !   

 

Sorry for the stream-of-consciousness report here, but who knows, my stumbling might help somebody else ...

[Luke 42078]

Hi, yes when you refresh something manually it gets processed in the background. We don't currently have a way of managing that refresh queue but it is something we're planning for a future update.

 

If you find in the log that it failed to extract an image for a particular audio file then if you provide a sample file for testing I can try it out. Thanks !

[grant.g 0]

Having found that the ffprobe debug information is all in syslog, I was able to find the spot where the scan stopped.  Unfortunately, I don't see any clue about why, yet.  

 

What I can say is that when I started the refresh, the ffprobe activity seems to have started up again - on the *next* album-artist folder.  It did not start over from the top of the library.

 

Does Emby use more than one method to extract tag information from the tracks ?   I'm confused that it seems to have found embedded text tags for all the albums, only the art is missing, yet, the ffprobe scans stopped at the time the dashboard reported that the scan had completed.

 

I've made a note of the last track processed by ffprobe before the scan quit.  I'll have a look to see what might be wrong with the next track - BUT, this same library scanned correctly on Windows, and this particular artist was also scanned correctly on the Pi3 last night, so I do not believe it's anything to do with the files. 

[Luke 42078]

We use ffprobe to extract embedded metadata, and then ffmpeg to extract the embedded image. It's always possible the image extraction failed, and this would be in the log.

 

By refresh if you mean the normal library scan, yes the server won't retry these operations if they fail because they are cpu intensive and we don't want to get stuck in a loop doing that over and over. If you refresh an album manually, does that result in images being available?

[grant.g 0]

Here's /var/log/syslog showing the last track processed before the media scan stopped.  

 

syslog clip.txt

 

it also shows the scan starting up again about 45 minutes later, after I had initiated a refresh of the entire library.   As I remarked earlier, the scan picked up at the next artist-level folder following the one where it failed.  

 

Here's the last track that appeared before the failure, and the one immediately following it in the library.

 

016 - Fuga canonica in epidiapente (6).mp3

017 - Canon 4 (B) Per augmentationem, contrari.mp3

 

And here's what was in the emby-server log around the time of the failure:

 

2017-03-31 14:41:33.1830 Info HttpServer: HTTP SUBSCRIBE http://192.168.1.15:8096/dlna/ebde754e267047db9ed7a80e76cc3674/contentdirectory/events. UserAgent:

2017-03-31 14:41:33.1852 Info HttpServer: HTTP Response 200 to 192.168.1.7. Time: 2ms. http://192.168.1.15:8096/dlna/ebde754e267047db9ed7a80e76cc3674/contentdirectory/events

2017-03-31 14:42:41.6224 Info HttpServer: HTTP GET http://192.168.1.15:8096/dlna/ebde754e267047db9ed7a80e76cc3674/description.xml. UserAgent:

2017-03-31 14:42:41.6289 Info Dlna: No matching device profile found. The default will need to be used.

        Host: 192.168.1.15:8096

        Connection: close

2017-03-31 14:42:41.6316 Info HttpServer: HTTP Response 200 to 192.168.1.6. Time: 10ms. http://192.168.1.15:8096/dlna/ebde754e267047db9ed7a80e76cc3674/description.xml

2017-03-31 14:43:01.7978 Info HttpServer: HTTP GET http://192.168.1.15:8096/dlna/ebde754e267047db9ed7a80e76cc3674/description.xml. UserAgent:

2017-03-31 14:43:01.8027 Info Dlna: No matching device profile found. The default will need to be used.

        Host: 192.168.1.15:8096

        Connection: close

 

To my eye, there's nothing there to explain what happened, 192.168.1.6 is my laptop with a browser, 192.168.1.7 is a NAS device that happens to have a DLNA server, but which is not otherwise involved in this project.

 

...

 

Replying to your most recent response, it does not appear that ffmpeg shows up in the logs at all (unless it's someplace else I haven't found yet).

 

As for the confusion about the scan, I'll try to recap the events again.

 

(1) Yesterday, I started a scan.   It ran into memory issues that started this thread.   After fixing the memory problems, the scan ran well into the night.  The first 10% of the albums were missing art, presumably because of the memory issues that I was fixing on the fly.

 

(2)  Today, I deleted the library and created it again.  In fact I did that twice because the first time, the scan stopped almost immediately, with a red "stopping" message on the dashboard - which never went away.   I got it to go away by restarting emby and then deleting the library and creating it again.

 

(3)  the third media scan stopped prematurely at about 30% of the way through.   This is the even I'm trying to understand.

 

(4)  rather than delete the library again, I tried initiating a refresh from the "three dots menu", on the top level of the library.  this action triggered the media scan to resume ... starting up on the next artist folder after the one where it had failed.  That scan is still running happily - and I can now see it stepping through all the tracks in sequence (I'm tailing syslog and grepping for "Input #0").

 

(5)  this is the puzzle:  when the scan stopped, all the tracks in the library were present in the database.   I could browse and see genres, artists, full titles, etc.   But no images beyond the point where it stopped.   Where did that data come from ?   I'm coming to the suspicion that I'm seeing ghost data in the database from last night's scan - does removing a library not erase the database tables ?

 

FYI, I have *all* external metadata sources turned off - I've invested a lot of time in tagging my music - much of which is not present in any of the external databases, and even more of which is totally wrong there.

 

 

[grant.g 0]

I just noticed something that leads me to another hypothesis ...

 

I have my syslog tail running in a window on my laptop, so I can see when it stalls or stops.   If I navigate to the Emby homepage and click on my library, the browser brings up a spinner for a minute or so while it loads all the album data (at least that's what it looks like to me).   Interestingly, while that's happening, the media scanner stalls.  I'm guessing that there's a database lock of some sort that prevents updates while the album list is being extracted.  (No dirty reads ?).

 

Is it possible some user activity could stall the scanner long enough that some timeout kicks in ?   Could I have caused the freeze at 14:42 just by poking around in the UI ?   As it happens, I was fiddling around trying to understand the "reports" page at that time.

[grant.g 0]

Update:

 

The media scan (the one that was manually initiated) ran through the night.  When it reached the end of the library, it looped back to the beginning and continued until it reached the spot where it had started yesterday. So, the missing (Jordi Savall) albums finally got scanned.   The library now looks to be in good shape, finally.

 

However, two notifications appeared on the dashboard this morning. Both read as follows:

 

Scan media library failed.

a day ago

Cannot access a disposed object. Object name: 'SqliteItemRepository has been disposed and cannot be accessed.'.

 

Presumably they are referring to the failed scans that I reported yesterday.  Where were these messages hiding ?  Why did they only appear the next day ?  

And, of course, what does this tell me about the cause of the events ?    Is there a race condition between deleting a library and creating a new one on the same data ?  

(Some background process deletes the old tables while the new one is being created, possibly ?)   Is there a need to document a correct procedure for removing and

recreating a library ?

 

I did learn that the "Debugging" switch on the logs page only takes effect on a server restart (it might be useful to say that next to the button   ).   It might also be useful to document what a server reset does and doesn't do - I didn't try it for fear that it would abort the media scan, but apparently it doesn't do that.

 

To come back to the original topic of the thread, is there also a need to document the changes to swap and nursery settings that appear to be necessary to get Emby working

on Raspbian ?

 

 

 

 

[Luke 42078]

The reports feature is mostly community contributed and is in dire need of an overhaul. It could very well be hitting the database inefficiently thus causing slowdowns with the library scan.

[grant.g 0]

Thanks for bearing with me through this, Luke.

 

Could you please have a look at message #13 above and comment on the error notifications that showed up this morning - what might underlie the attempt to access a disposed object ?

[Luke 42078]

Please accompany that with the corresponding server log. thanks.

[Luke 42078]

If the question is not just about the notification and not the exception, then the notifications are sent as soon the scheduled task fails so my only guess is that you just didn't notice it.

[grant.g 0]

While I'd be the first to admit that I could have missed those notifications, I was definitely looking everywhere for some explanation of the stopped scans.   

 

Here are two log files.  I found the "disposed" messages around 09:50 in the first log

 

server-63626539881.txt

 

They are close to the times that I was trying to delete and recreate the library.    The new log starts when I restarted the server.

 

server-63626550638.txt

 

I included part of this log, and parts of /var/log/syslog (where the ffprobe activity is logged) around 14:42 already yesterday - see message 11 (I believe).  

 

You can see that the scan reported that it stopped a few minutes after the ffprobe activity stopped.  it was about 45 minutes later when I initiated the "refresh" and the scan started up again.

 

 

 

[Luke 42078]

that's nothing really to worry about. It looks like you shut down the server in the middle of a library scan. if anything we should just not log that at all.

[grant.g 0]

I see that the "disposed" errors occur a few seconds before the server restarted, so I accept that they were caused by my activity - and do nothing to explain why the media scans were failing.

 

The issue that is still unresolved is why the scan that started at 09:53:14 terminated at 14:46:16 - after processing only 30% of the tracks.  I sent you the last track it processed and the one following.   I don't any failure messages in the emby-server log, nor in any of the OS logs.

 

Also, the background refresh did get back to those two tracks about 11 hours later and worked.

 

You didn't comment on why all the metadata (except the images) was present when the scan had never completed.   I'm still inclined to the theory that removing a library and recreating it with exactly the same parameters results in ghost data.

 

Maybe I should go read the code for the media scanner instead of pestering you any more.

 

Sorry to take up so much of your Saturday.

 

G.

[Luke 42078]

Most likely due to data from the previous library not being fully cleaned out yet. The clean database scheduled task handles that. Deleting the library.db file altogether may have been a better option, but it looks like you're settled now at least.