(cache)Thumbnail request causing OOM in PHP (#1120) · Issues · Minds / Minds Backend - Engine

added scoped labels

Example request: https://www.minds.com/fs/v1/thumbnail/1026508015016828928/xlarge

Link to media page: https://www.minds.com/media/1026508015016828928

Offending section of code in /api/v1/thumbnail.php:

            try {
                $finfo = new \finfo(FILEINFO_MIME);
                $contentType = $finfo->buffer($contents) ?: 'image/jpeg';
            } catch (\Exception $e) {
                error_log($e);
                $contentType = 'image/jpeg';
            }

Issue appears related to finfo under PHP 7.3.

Running a referenced test script show the clear performance degradation between our 7.1 and 7.3 builds when calling finfo.

While I'm not able to reproduce the OOM condition in our sandbox, I am able to demonstrate the performance degradation.

PHP 7.1

/var/www/Minds/engine # ITERS=100 php test.php
Took: 0.094574928283691
/var/www/Minds/engine # ITERS=1000 php test.php
Took: 0.91444492340088

PHP 7.3

/var/www/Minds/engine # ITERS=100 php test.php
Took: 0.42086601257324
/var/www/Minds/engine # ITERS=1000 php test.php
Took: 4.215017080307

Likely this is a good place to start looking for the OOM issue.

The referenced performance relates to finfo::file() whereas we are using finfo::buffer().

Using finfo::buffer() does not cause a slow down.

Continuing by instrumenting some mock code to show memory usage before and after finfo::buffer()

There is also the possibility that something prior to this call is using too much memory and this final call tips it over the limit where it would not have done previously.

The use of $finfo->buffer() to get the mime type has an impact on the memory overhead of the script. The difference between PHP 7.1 and PHP 7.3 is minimal.

I suspect the real issue is that the entire image file is read into memory from S3 and then passed around before being written to the HTTP response.

After a couple of requests these values are stabilised:

finfo usage: 3585240
after usage: 3782552
total usage: 3782552

finfo is the memory delta just before and after the finfo calls. total is the delta from the start of request to the end after is the memory usage at the end of the script

finfo call accounts for most of the total memory usage of the script though is probably just when the memory is assigned for the file.

With and S3 backend, we already set the mime type to the metadata using the same finfo call when the file was written so we shouldn't need to repeat this process again.

Looking to see if we can extend the S3 calls to fetch the metadata...

Filestore interface does not provide method for reading mime type.

Attempts to reduce the memory usage of the API request in sandbox by just reading the header did not make much difference.

The memory delta is an unreliable measure. I edited out the finfo call just returning a string constant for the mime type and it still recorded the same level of memory delta without touching the file content buffer.

libmagic version is different between PHP versions

7.3:

fileinfo

fileinfo support => enabled
libmagic => 533

7.1:

fileinfo

fileinfo support => enabled
version => 1.0.5
libmagic => 522

Alternatively we are using chunked file sending so could do chunked reading of file which would require a smaller memory buffer but more round trips to S3???

While the abstract ElggFilestore does support offset and length reads, we are using a modified the Service interface and S3 service has no seek implementation.

The S3 lib does have a stream interface that could be used. https://docs.aws.amazon.com/sdk-for-php/v3/developer-guide/s3-stream-wrapper.html

added 7h of time spent at 2019-11-12

Got the source file referenced in first comment.

I can now recreate the issue during upload of the source image.

2019/11/13 09:27:17 [warn] 8#8: *1137 a client request body is buffered to a temporary file /var/cache/nginx/client_temp/0000000005, client: 192.168.13.110, server: _, request: "POST /api/v1/media HTTP/1.1", host: "fix-1119-image-regress.minds.io", referrer: "https://fix-1119-image-regress.minds.io/newsfeed/subscriptions"
2019/11/13 09:27:33 [error] 8#8: *1137 FastCGI sent in stderr: "PHP message: PHP Fatal error:  Allowed memory size of 134217728 bytes exhausted (tried to allocate 146703512 bytes) in /var/www/Minds/engine/Core/Storage/Services/S3.php on line 67" while reading response header from upstream, client: 192.168.13.110, server: _, request: "POST /api/v1/media HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "fix-1119-image-regress.minds.io", referrer: "https://fix-1119-image-regress.minds.io/newsfeed/subscriptions"
2019/11/13 09:27:33 [error] 8#8: *1137 FastCGI sent in stderr: "PHP message: Fatal error: Array<br />
(<br />
    [type] =&gt; 1<br />
    [message] =&gt; Allowed memory size of 134217728 bytes exhausted (tried to allocate 146703512 bytes)<br />
    [file] =&gt; /var/www/Minds/engine/Core/Storage/Services/S3.php<br />
    [line] =&gt; 67<br />
)<br />
PHP message: PHP WARNING: 2019-11-13 09:27:33 (UTC): "Cannot modify header information - headers already sent by (output started at /var/www/Minds/engine/Core/Storage/Services/S3.php:67)" in file /var/www/Minds/engine/lib/elgglib.php (line 942)PHP message: PHP WARNING: 2019-11-13 09:27:33 (UTC): "file_get_contents(/var/www/Minds/errors/500.html): failed to open stream: No such file or directory" in file /var/www/Minds/engine/lib/elgglib.php (line 944)" while reading upstream, client: 192.168.13.110, server: _, request: "POST /api/v1/media HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "fix-1119-image-regress.minds.io", referrer: "https://fix-1119-image-regress.minds.io/newsfeed/subscriptions"

Offending code for previous error message:

 public function write($data)
    {
        
        //TODO: check mime performance here
        $finfo = new \finfo(FILEINFO_MIME_TYPE);
        $mimeType = $finfo->buffer($data);

        $write =  $this->s3->putObject([
          // 'ACL' => 'public-read',
          'Bucket' => Config::_()->aws['bucket'],
          'Key' => $this->filepath,
          'ContentType' => $mimeType,
          'ContentLength' => strlen($data),
          //'ContentLength' => filesize($file),
          'Body' => $data,
        ]);

In total isolation:

<?php
$startMem = memory_get_usage();
$finfo = new finfo(FILEINFO_MIME);
$buffer = file_get_contents('/Users/guythouret/Downloads/master.gif');
$type = $finfo->buffer($buffer);
$endMem = memory_get_usage();
echo 'type: ' . print_r($type, true). PHP_EOL;
$usage = $endMem - $startMem;
echo 'usage: ' . $usage . PHP_EOL;

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 146703512 bytes) in /Users/guythouret/Library/Preferences/PhpStorm2019.2/scratches/scratch.php on line 5

Without the call to $finfo->buffer($buffer) it outputs: usage: 18342712 which is not much more than the size of the source file.

finfo exceeds maximum script limit of 128M when given a 12.5M file.

dd if=/dev/zero of=/tmp/12.5M bs=1024 count=12500

<?php
$finfo = new finfo(FILEINFO_MIME);
$buffer = file_get_contents('/tmp/12.5M');
$type = $finfo->buffer($buffer);

When using a 12M file, it returns ok.

Doubling the limit to 256M with ini_set('memory_limit', '256M'); only let the file size go up to 27M. the overhead of finfo is not a fixed value and seems in proportion to the size of the buffer passed to it.

This is resolved by only passing the header bytes to finfo to keep it within limits.

<?php
$finfo = new finfo(FILEINFO_MIME);
$buffer = file_get_contents('/tmp/100M');
$header = substr($buffer, 0, 16);
$type = $finfo->buffer($buffer);

Files in excess of 100M are acceptable while still returning the correct mime type.

mentioned in commit fd48c406

mentioned in commit 2ad460ab

mentioned in commit 8a44ae34

mentioned in merge request !397

Thumbnail request causing OOM in PHP

Related issues 0

Related issues
0