Maps: scan-photos process memory consumption increases over runtime

[myxor]

After some time the scan-photos process starts consuming a lot of memory and the amount increases even more over the time.

This is a screenshot from htop running on my Nextcloud host:

and some time later:

This leads to crashing of the process on my machine with 2GB of RAM after scanning around 32k pictures.

[1] 19349 killed sudo -u www-data php /var/www/nextcloud/occ maps:scan-photos marco

Is it possible to run the job with a set memory limit?

[tacruc]

I head this problem, too. But no time and idea how to fix it. I just increased the memory limit, which is not an option if you do not have more RAM. If you have big Tiff pictures, it might be worth to remove them temporally, as one library for reading the exif extracts the hole picture to the RAM. I head cases where a 150mb TIFF used multiple GB of Ram.

[myxor]

I am not using TIFF images, mostly JPEGs.
As the amount of RAM consumed grows constant it seems that there is some memory leak inside the script. I will have a look into it and see if i can find anything.

[bilibilistack]

I have the same issue, the process posts killed after scanned 30k photos.

[YoSiJo]

I have the same problem.
But see the following messages in the logs:

Sep 07 14:54:08 waimanu-nc Nextcloud[8516]: {PHP} A non-numeric value encountered at /var/www/nc.waimanu.io/main/apps/maps/vendor/lsolesen/pel/src/PelIfd.php#370
Sep 07 14:54:12 waimanu-nc Nextcloud[8516]: {PHP} A non well formed numeric value encountered at /var/www/nc.waimanu.io/main/apps/maps/vendor/lsolesen/pel/src/PelIfd.php#370
Sep 07 14:54:12 waimanu-nc Nextcloud[8516]: {PHP} A non well formed numeric value encountered at /var/www/nc.waimanu.io/main/apps/maps/vendor/lsolesen/pel/src/PelIfd.php#370     
Sep 07 14:54:17 waimanu-nc Nextcloud[31572]: {core} {"Exception":"OC\\AppFramework\\Middleware\\Security\\Exceptions\\NotLoggedInException","Message":"Current user is not logged in","Code":401,"Trace":[{"file":"\/var\/www\/nc.waiman
u.io\/main\/lib\/private\/AppFramework\/Middleware\/MiddlewareDispatcher.php","line":95,"function":"beforeController","class":"OC\\AppFramework\\Middleware\\Security\\SecurityMiddleware","type":"->","args":[{"__class__":"OCA\\Files\
\Controller\\ViewController"},"index"]},{"file":"\/var\/www\/nc.waimanu.io\/main\/lib\/private\/AppFramework\/Http\/Dispatcher.php","line":97,"function":"beforeController","class":"OC\\AppFramework\\Middleware\\MiddlewareDispatcher"
,"type":"->","args":[{"__class__":"OCA\\Files\\Controller\\ViewController"},"index"]},{"file":"\/var\/www\/nc.waimanu.io\/main\/lib\/private\/AppFramework\/App.php","line":126,"function":"dispatch","class":"OC\\AppFramework\\Http\\D
ispatcher","type":"->","args":[{"__class__":"OCA\\Files\\Controller\\ViewController"},"index"]},{"file":"\/var\/www\/nc.waimanu.io\/main\/lib\/private\/AppFramework\/Routing\/RouteActionHandler.php","line":47,"function":"main","clas
s":"OC\\AppFramework\\App","type":"::","args":["ViewController","index",{"__class__":"OC\\AppFramework\\DependencyInjection\\DIContainer"},{"_route":"files.view.index"}]},{"function":"__invoke","class":"OC\\AppFramework\\Routing\\Ro
uteActionHandler","type":"->","args":[{"_route":"files.view.index"}]},{"file":"\/var\/www\/nc.waimanu.io\/main\/lib\/private\/Route\/Router.php","line":297,"function":"call_user_func","args":[{"__class__":"OC\\AppFramework\\Routing\
\RouteActionHandler"},{"_route":"files.view.index"}]},{"file":"\/var\/www\/nc.waimanu.io\/main\/lib\/base.php","line":975,"function":"match","class":"OC\\Route\\Router","type":"->","args":["\/apps\/files\/"]},{"file":"\/var\/www\/nc
.waimanu.io\/main\/index.php","line":42,"function":"handleRequest","class":"OC","type":"::","args":[]}],"File":"\/var\/www\/nc.waimanu.io\/main\/lib\/private\/AppFramework\/Middleware\/Security\/SecurityMiddleware.php","Line":143,"C
ustomMessage":"--"}

In the end the job took about 40Gb.
With -vvv I couldn't find more, because the output hasn't changed.

[tacruc]

@eneiluj Do you have an Idea what might leak the memory here?

[YoSiJo]

Ok I have found a defective image file.

# exiftool -exif:all= -tagsfromfile @ -all:all -unsafe 'example.jpg'                                                                                                  
Warning: [minor] Fixed incorrect URI for xmlns:MicrosoftPhoto - example.jpg                                                                                                                                  
Warning: [minor] Fixed incorrect URI for xmlns:MicrosoftPhoto - example.jpg                                                                                                                                  
    1 image files updated 

After the repair the image, the error massage have changed. I'm still checking whether the new error is still related to it.

[tacruc]

@YoSiJo I think your having two different problems, the first is the memory leak discussed in this issue and the second are files which can not be read by php_exif or lsolesen/pel. Lets stick here to the first issue. I think the second is probably better disscussed in php_exif or loslesen/pel.

[YoSiJo]

The error with the RAM is now gone. The new error is related to loslesen/pel and has probably nothing to do with this issue.
The solution for me was this:

find . -type f -regextype posix-egrep -iregex '.*jpg' -print0 | xargs -0 exiftool -warning
exiftool -exif:all= -tagsfromfile @ -all:all -unsafe ${FILE}

[tacruc]

I tried to find the leak today. I have the feeling that there are different parts leaking memory, but the biggest seams to be the two methods for exif decoding. Pel probably the most.

But no madder how I changed the code, the memory consumption did only increase.
@eneiluj what do you think of starting one process per Picture or small chunk as a work arround?

[myxor]

It seems that the Pel project https://github.com/pel/pel is pretty much dead :(

[eneiluj]

@tacruc Yes, processing pictures in chunks seems a good solution. But then we have a new problem to solve: We have to make sure the script which scans actually ends to release the memory involved in the leak(s) but we don't want the total scan process to be longer because there is some time between the chunks. So we have to find a way to run each process independently (in a different script call) and sequentially without having to wait between them. I never tried to do such things.

[srwareham]

If not too redundant, it would certainly seem there is a severe memory leak on my system. To be specific, maps:scan-photos crashes if I have more than 45 photos on my system:

...
[45] Photo "photo.jpg" added
PHP Fatal error:  Allowed memory size of 536870912 bytes exhausted (tried to allocate 573226904 bytes) in /var/www/h tml/lib/private/Files/Storage/Local.php on line 217

I've tried deleting the photos this crashes with, so it's definitely not a corrupt file issue.

[daniel-a-h]

I get the same error in the current Version of the app. I was able to add 14k Photos, but there would be triple that yet to add. Since there process stops with an error there is no commit to the DB and therefor nothing on the map.

PHP Fatal error: Allowed memory size of 536870912 bytes exhausted (tried to allocate 20480 bytes) in /usr/local/www/nextcloud/apps/maps/vendor/lsolesen/pel/src/PelIfd.php on line 816

[slackfan]

I second the issue and vote for a fix. In my case 23k images are processed before the crash. PHP has a memory limit of 2GB on the server. The maps version is the very latest using Nextcloud 17.0.2.

[22918] Photo "....jpg" added
PHP Fatal error:  Allowed memory size of 2147483648 bytes exhausted (tried to allocate 20480 bytes) in /nextcloud/www/apps/maps/vendor/lsolesen/pel/src/PelIfd.php on line 816

If fixing that leak is so complicated, maybe a data structure can be used, which serializes to disk during the scan process.

[tacruc]

PR #232 reduces the impact as it moves the scanning in bg processes which are restarted after a crash, at the next picture. Just needs to be tested an reviewed.

@slackfan could you test if it works for your?

[slackfan]

I applied https://github.com/nextcloud/maps/pull/232.patch. The maps:scan-photos process now runs really fast for all the found photos (nearly 70k). The downside is: It seems it does nothing :) No single photo appears in the maps frontend. Is there any logging I could provide?

[tacruc]

It just creates the jobs which are then run by the cron job. This hast the advantage that it is restarted if it crashes and will just skip the single picture which failed.

[tacruc]

so you have to execute cron.php

[slackfan]

Ah! Postgres is running crazy at moment in regards to CPU utilization so it seems to do something. I'll update the ticket, once this lead to any result :) Thanks!

[slackfan]

The processes succeeded to add 4258 images to the database and I can see them in the frontend.
Monitoring the processes the chunking process could be observed pretty well: The cron.php process and the postgres DB played ping pong with the CPU.

Further processing fails now due to an unrelated error message

{"reqId":"Qm04j1rCgCe6L1dwouz4","level":3,"time":"2020-01-17T21:00:17+00:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"A non-numeric value encountered at \/var\/www\/nextcloud\/apps\/maps\/vendor\/lsolesen\/pel\/src\/PelIfd.php#370","userAgent":"--","version":"17.0.2.1"}
{"reqId":"Qm04j1rCgCe6L1dwouz4","level":3,"time":"2020-01-17T21:00:21+00:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"A non-numeric value encountered at \/var\/www\/nextcloud\/apps\/maps\/vendor\/lsolesen\/pel\/src\/PelIfd.php#370","userAgent":"--","version":"17.0.2.1"}
{"reqId":"Qm04j1rCgCe6L1dwouz4","level":3,"time":"2020-01-17T21:00:21+00:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"A non-numeric value encountered at \/var\/www\/nextcloud\/apps\/maps\/vendor\/lsolesen\/pel\/src\/PelIfd.php#370","userAgent":"--","version":"17.0.2.1"}
{"reqId":"Qm04j1rCgCe6L1dwouz4","level":3,"time":"2020-01-17T21:00:26+00:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"A non-numeric value encountered at \/var\/www\/nextcloud\/apps\/maps\/vendor\/lsolesen\/pel\/src\/PelIfd.php#370","userAgent":"--","version":"17.0.2.1"}

That's good news I guess :+1: Need to digg into the other issue now.

[jancborchardt]

Could you test if this is fixed for you with the latest release 0.1.4? Thanks! :)

cc @nextcloud/maps

[slackfan]

Odd question, I updated this morning three new apps but for the maps app - and only tihs one I am now getting a message "Could not extract app maps"

{"reqId":"XiQ3WMN7SPFx0j-KCF3i-QAAAAM","level":3,"time":"2020-01-19T11:02:52+00:00","remoteAddr":"85.150.3.126","user":"nextcloud","app":"settings","method":"POST","url":"\/index.php\/settings\/apps\/enable","message":{"Exception":"Exception","Message":"Could not extract app maps","Code":0,"Trace":[{"file":"\/var\/www\/nextcloud\/settings\/Controller\/AppSettingsController.php","line":444,"function":"downloadApp","class":"OC\\Installer","type":"->","args":["maps"]},{"file":"\/var\/www\/nextcloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php","line":170,"function":"enableApps","class":"OC\\Settings\\Controller\\AppSettingsController","type":"->","args":[["maps"],[]]},{"file":"\/var\/www\/nextcloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php","line":99,"function":"executeController","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->","args":[{"__class__":"OC\\Settings\\Controller\\AppSettingsController"},"enableApps"]},{"file":"\/var\/www\/nextcloud\/lib\/private\/AppFramework\/App.php","line":126,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->","args":[{"__class__":"OC\\Settings\\Controller\\AppSettingsController"},"enableApps"]},{"file":"\/var\/www\/nextcloud\/lib\/private\/AppFramework\/Routing\/RouteActionHandler.php","line":47,"function":"main","class":"OC\\AppFramework\\App","type":"::","args":["OC\\Settings\\Controller\\AppSettingsController","enableApps",{"__class__":"OC\\AppFramework\\DependencyInjection\\DIContainer"},{"_route":"settings.AppSettings.enableApps"}]},{"function":"__invoke","class":"OC\\AppFramework\\Routing\\RouteActionHandler","type":"->","args":[{"_route":"settings.AppSettings.enableApps"}]},{"file":"\/var\/www\/nextcloud\/lib\/private\/Route\/Router.php","line":297,"function":"call_user_func","args":[{"__class__":"OC\\AppFramework\\Routing\\RouteActionHandler"},{"_route":"settings.AppSettings.enableApps"}]},{"file":"\/var\/www\/nextcloud\/lib\/base.php","line":997,"function":"match","class":"OC\\Route\\Router","type":"->","args":["\/settings\/apps\/enable"]},{"file":"\/var\/www\/nextcloud\/index.php","line":42,"function":"handleRequest","class":"OC","type":"::","args":[]}],"File":"\/var\/www\/nextcloud\/lib\/private\/Installer.php","Line":283,"CustomMessage":"--"},"userAgent":"Mozilla\/5.0 (X11; Linux x86_64) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/79.0.3945.118 Safari\/537.36","version":"17.0.2.1"}

I do not believe that this is an issue with the server as it never happened before. This happens also after fully removing the older version 0.1.2. Is the download checksum covered and there is an issue with the downloaded file which does not recover? Given that I would like but cannot continue to test.

[tacruc]

There is a known Issue #240. You can download an extract the release manually or wait until the release is fixed.

[slackfan]

I proceeded as suggested and can confirm that the out-of-memory issue seems to be fixed.

What I now get is the following Undefined property: OC\\Files\\Node\\File::$getSize error

{"reqId":"XiS@bGq8JpvfzRoQEswKTQAAAA8","level":3,"time":"2020-01-19T20:39:18+00:00","remoteAddr":"<remoteip>","user":"<user>","app":"PHP","method":"GET","url":"\/index.php\/apps\/maps\/photos","message":"Undefined property: OC\\Files\\Node\\File::$getSize at \/var\/www\/nextcloud\/apps\/maps\/lib\/Service\/GeophotoService.php#98","userAgent":"<useragent>","version":"17.0.2.1"}
{"reqId":"XiS@bGq8JpvfzRoQEswKTQAAAA8","level":3,"time":"2020-01-19T20:39:18+00:00","remoteAddr":"<remoteip>","user":"<user>","app":"PHP","method":"GET","url":"\/index.php\/apps\/maps\/photos","message":"Undefined property: OC\\Files\\Node\\File::$getSize at \/var\/www\/nextcloud\/apps\/maps\/lib\/Service\/GeophotoService.php#98","userAgent":"<useragent>","version":"17.0.2.1"}

and it seems I'll get it for each image which got successfully processed during each request. Two hours after indexing I have that error message about 80k times in my nextcloud.log file. This is definitely a new issue, should I file a ticket? :)

[tacruc]

Yeah I noticed this typo a while ago. There is allready a PR #241 which fixes this. I thought fixing the issue is faster than open the issue, but feel free to open it anyway.

[slackfan]

Thank you. PR #241 fixes the zillions of error messages. So far no further issues. Thank you! 👍

[tacruc]

We have now a good work arround I will close this issue.