Skip to content

  • Projects
  • Groups
  • Snippets
  • Help
  • Sign in / Register
Minds Backend - Engine
Minds Backend - Engine
  • Project overview
  • Repository
  • Issues 297
    • List
    • Boards
    • Labels
    • Service Desk
    • Milestones
  • Merge Requests 42
  • CI / CD
  • Security & Compliance
  • Packages
  • Wiki
  • Snippets
  • Members
  • Collapse sidebar
  • Graph
  • Charts
  • Create a new issue
  • Jobs
  • Commits
  • Issue Boards
  • Minds
  • Minds Backend - EngineMinds Backend - Engine
  • Issues
  • #1120

Closed
Open
Opened 1 day ago by Guy Thouret@gthouret
Report abuse New issue

Thumbnail request causing OOM in PHP

Sentry Issue: ENGINE-HF

ErrorException: Allowed memory size of 134217728 bytes exhausted (tried to allocate 116526568 bytes)
  File "/lib/elgglib.php", line 947, in fatalErrorShutdownHandler
    \Sentry\captureLastError();
  File "[internal]", line 0

Related issues
0

Related merge requests
1
  • WIP: Memory efficient method of getting Mime Types
    !397
  • Discussion 24
  • Designs 0
  • Guy Thouret @gthouret added Priority::1 - High Regression::Production Sprint::11/06 - Rolling Rabbit Squad::Blue Status::InProgress Type::Bug scoped labels 1 day ago

    added scoped labels

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

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

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

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

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

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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
  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

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

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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()

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 1 day ago
    Developer

    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...

  • Guy Thouret
    Guy Thouret @gthouret · 17 hours ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 17 hours ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 17 hours ago
    Developer

    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
  • Guy Thouret
    Guy Thouret @gthouret · 17 hours ago
    Developer

    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???

  • Guy Thouret
    Guy Thouret @gthouret · 16 hours ago
    Developer

    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

  • Guy Thouret @gthouret added 7h of time spent at 2019-11-12 16 hours ago

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

  • Guy Thouret
    Guy Thouret @gthouret · 5 hours ago
    Developer

    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"
    Edited by Guy Thouret 5 hours ago
  • Guy Thouret
    Guy Thouret @gthouret · 5 hours ago
    Developer

    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,
            ]);
    Edited by Guy Thouret 4 hours ago
  • Guy Thouret
    Guy Thouret @gthouret · 5 hours ago
    Developer

    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.

    Edited by Guy Thouret 4 hours ago
  • Guy Thouret
    Guy Thouret @gthouret · 4 hours ago
    Developer

    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.

    Edited by Guy Thouret 4 hours ago
  • Guy Thouret
    Guy Thouret @gthouret · 4 hours ago
    Developer

    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.

  • Guy Thouret
    Guy Thouret @gthouret · 4 hours ago
    Developer

    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.

  • Guy Thouret @gthouret mentioned in commit fd48c406 4 hours ago

    mentioned in commit fd48c406

  • Guy Thouret @gthouret mentioned in commit 2ad460ab 4 hours ago

    mentioned in commit 2ad460ab

  • Guy Thouret @gthouret mentioned in commit 8a44ae34 4 hours ago

    mentioned in commit 8a44ae34

  • Guy Thouret @gthouret mentioned in merge request !397 4 hours ago

    mentioned in merge request !397

  • Guy Thouret @gthouret mentioned in commit f8fddc82 4 hours ago

    mentioned in commit f8fddc82

  • Guy Thouret @gthouret added Status::Review scoped label and automatically removed Status::InProgress label 4 hours ago

    added scoped label and automatically removed label

  • Guy Thouret
    Guy Thouret @gthouret · 3 hours ago
    Developer

    With the fix up, PHP is bombing out with the following:

    [13-Nov-2019 11:54:45] WARNING: [pool www] child 16, script '/var/www/Minds/engine/index.php' (request: "POST /index.php") executing too slow (1.062722 sec), logging
    [13-Nov-2019 11:54:45] NOTICE: child 16 stopped for tracing
    [13-Nov-2019 11:54:45] NOTICE: about to trace 16
    [13-Nov-2019 11:54:45] ERROR: failed to open /proc/16/mem: Permission denied (13)
    [13-Nov-2019 11:54:45] NOTICE: finished trace of 16
    127.0.0.1 -  13/Nov/2019:11:54:47 +0000 "POST /index.php" 200
    [13-Nov-2019 11:54:47] WARNING: [pool www] child 16 exited on signal 9 (SIGKILL) after 1762.599356 seconds from start
  • Guy Thouret @gthouret mentioned in commit af223984 3 hours ago

    mentioned in commit af223984

  • Guy Thouret
    Guy Thouret @gthouret · 1 hour ago
    Developer

    This is likely related to resource constraint in the sandbox environment. Caputured the following from dmesg within the php-fpm pod when a failing request is made:

    [11639952.932291] php-fpm invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null),  order=0, oom_score_adj=984
    [11639952.940242] php-fpm cpuset=5fd6f4700aa2e4b35f3323fdcce4dda438dae29068fc04f280456492f17da530 mems_allowed=0
    [11639952.947273] CPU: 6 PID: 15268 Comm: php-fpm Not tainted 4.14.123-111.109.amzn2.x86_64 #1
    [11639952.953651] Hardware name: Amazon EC2 c5.2xlarge/, BIOS 1.0 10/16/2017
    [11639952.958004] Call Trace:
    [11639952.960684]  dump_stack+0x5c/0x82
    [11639952.963699]  dump_header+0x94/0x229
    [11639952.966804]  oom_kill_process+0x223/0x420
    [11639952.970109]  out_of_memory+0x2af/0x4d0
    [11639952.973296]  mem_cgroup_out_of_memory+0x49/0x80
    [11639952.976832]  mem_cgroup_oom_synchronize+0x2ed/0x330
    [11639952.980515]  ? mem_cgroup_css_online+0x30/0x30
    [11639952.984270]  pagefault_out_of_memory+0x32/0x77
    [11639952.987744]  __do_page_fault+0x4b4/0x4c0
    [11639952.991031]  ? async_page_fault+0x2f/0x50
    [11639952.994324]  async_page_fault+0x45/0x50
    [11639952.997547] RIP: 00a0:          (null)
    [11639953.000793] RSP: 157ceec0:000055ca157d4b20 EFLAGS: 00000001
    [11639953.000868] Task in /kubepods/burstable/poda2a57466-060f-11ea-84fb-02f67eb6b970/5fd6f4700aa2e4b35f3323fdcce4dda438dae29068fc04f280456492f17da530 killed as a result of limit of /kubepods/burstable/poda2a57466-060f-11ea-84fb-02f67eb6b970/5fd6f4700aa2e4b35f3323fdcce4dda438dae29068fc04f280456492f17da530
    [11639953.021460] memory: usage 1048576kB, limit 1048576kB, failcnt 0
    [11639953.025539] memory+swap: usage 1048576kB, limit 1048576kB, failcnt 3957
    [11639953.029922] kmem: usage 10492kB, limit 9007199254740988kB, failcnt 0
    [11639953.034225] Memory cgroup stats for /kubepods/burstable/poda2a57466-060f-11ea-84fb-02f67eb6b970/5fd6f4700aa2e4b35f3323fdcce4dda438dae29068fc04f280456492f17da530: cache:31872KB rss:1006212KB rss_huge:0KB shmem:31864KB mapped_file:31868KB dirty:0KB writeback:0KB swap:0KB inactive_anon:31864KB active_anon:1006212KB inactive_file:4KB active_file:0KB unevictable:0KB
    [11639953.054422] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
    [11639953.061224] [15182]     0 15182   542863    10458      36       4        0           984 php-fpm
    [11639953.067852] [15263]    82 15263   556973    12098      52       4        0           984 php-fpm
    [11639953.074473] [15264]    82 15264   556965    11612      52       4        0           984 php-fpm
    [11639953.081112] [15265]    82 15265   556965    11800      52       4        0           984 php-fpm
    [11639953.087739] [15267]    82 15267   556963    11560      52       4        0           984 php-fpm
    [11639953.094425] [15268]    82 15268   795258   247747     519       5        0           984 php-fpm
    [11639953.101099] [15269]    82 15269   556965    11572      52       4        0           984 php-fpm
    [11639953.107733] [15270]    82 15270   556987    12515      52       4        0           984 php-fpm
    [11639953.114362] [15271]    82 15271   556965    11333      52       4        0           984 php-fpm
    [11639953.120977] [15272]    82 15272   556965    11577      52       4        0           984 php-fpm
    [11639953.127627] [15279]    82 15279   556985    11924      52       4        0           984 php-fpm
    [11639953.134264] [15864]     0 15864      437      292       5       3        0           984 sh
    [11639953.140718] Memory cgroup out of memory: Kill process 15268 (php-fpm) score 1930 or sacrifice child
    [11639953.147494] Killed process 15268 (php-fpm) total-vm:3181032kB, anon-rss:945016kB, file-rss:15400kB, shmem-rss:30572kB
    [11639953.205124] oom_reaper: reaped process 15268 (php-fpm), now anon-rss:0kB, file-rss:0kB, shmem-rss:30572kB
  • Guy Thouret
    Guy Thouret @gthouret · 1 hour ago
    Developer

    Kubernetes killed my proc :dagger:

  • Guy Thouret
    Guy Thouret @gthouret · 34 minutes ago
    Developer

    Also confirmed this issue occurs under PHP 7.1 in sandbox also.

Please register or sign in to reply
Assignee
Guy Thouret's avatar
Guy Thouret @gthouret
none
Epic
None
None
Milestone
None
Time tracking
Spent: 7h
None
Due date
None
6
Labels
Priority::1 - High Regression::Production Sprint::11/06 - Rolling Rabbit Squad::Blue Status::Review Type::Bug
None
Weight
None
Confidentiality
Not confidential
Lock issue
Unlocked
1
1 participant
user avatar
Guy Thouret
Reference: minds/engine#1120