Possible memory leak

[PHLAK]

• Laravel Version: 9.30.1
• PHP Version: 8.1.10
• Database Driver & Version: N/A

Description:

We've been having memory related issues in CI recently where the memory consumption continuously grows. This is a particular problem when enabling coverage checks (i.e. artisan test --coverage) as this eventually exhausts the memory in the CI environment. A few weeks ago we thought we had this traced back to this issue in PHP core which was fixed as of v8.1.10, however, after updating to 8.1.10 we're still having memory issues in CI.

I recently found this article which recommends creating a test to repeatedly create, boot and flush the (Laravel) application multiple times to see the memory consumption over time. I did this on a fresh Laravel application and, as you can see below, the memory usage constantly rises over time.

I tried to reproduce this on a personal project that doesn't use Laravel to determine if it was an issue with phpunit or PHP core but was unable to reproduce the leak so I'm leaning towards Laravel at the moment (however, I'm not convinced of this yet).

I haven't dug any deeper at this point as I wanted to bring this to your attention but am happy to keep investigating if necessary.

Steps To Reproduce:

Create a new Laravel application.

$ laravel new test-app

Add the following test case to the newly created application.

public function test_leaks_memory_on_1000_iterations()
{
    $this->app->flush();
    $this->app = null;

    for ($i = 1; $i < 1000; ++$i) {
        $this->createApplication()->flush();

        dump('Using ' . ((int) (memory_get_usage(true) / (1024 * 1024))) . 'MB in ' . $i . ' iterations.');
    }

    $this->app = $this->createApplication();
}

Run the test and observe the ever increasing memory consumption.

$ phpunit tests/Feature/ExampleTest.php
PHPUnit 9.5.24 #StandWithUkraine

^ "Using 20MB in 1 iterations."
^ "Using 20MB in 2 iterations."
^ "Using 20MB in 3 iterations."
[TRUNCATED FOR BREVITY]
^ "Using 26MB in 100 iterations."
[TRUNCATED FOR BREVITY]
^ "Using 28MB in 200 iterations."
[TRUNCATED FOR BREVITY]
^ "Using 38MB in 500 iterations."
[TRUNCATED FOR BREVITY]
^ "Using 48MB in 800 iterations."
[TRUNCATED FOR BREVITY]
^ "Using 54MB in 997 iterations."
^ "Using 54MB in 998 iterations."
^ "Using 54MB in 999 iterations."

The more iterations, the more memory used.

[rodrigopedra]

Adding this line:

\Illuminate\Console\Application::forgetBootstrappers();

Right after $this->createApplication()->flush(); reduced the memory increase dramatically (from 54MB to 28MB)

And commenting the last 2 bootstrapers in:

https://github.com/laravel/framework/blob/f40fe7d303544a66f7bcbee8e25c96c743d64d1a/src/Illuminate/Foundation/Console/Kernel.php#L82-L90

Further reduced from 28MB to 18MB. (in my machine it starts with 12MB)

This last one is less objective (could be any loaded service provider), and impacts the application. But at least it gives a hint on where to look further.

[PHLAK]

I've found a slightly better way to illustrate that there is no code outside of Laravel causing the memory usage to increase.

Add the following test class as tests/Feature/ExampleTest.php to a brand new Laravel installation.

class ExampleTest extends TestCase
{
    protected function tearDown(): void
    {
        parent::tearDown();

        dump(sprintf('%d MB', (int) (memory_get_usage(true) / (1024 * 1024))));
    }

    public function test_true()
    {
        $this->assertTrue(true);
    }
}

Run the test repeatedly using the --repeat flag and watch the memory usage grow.

$ phpunit --repeat 1000 tests/Feature/ExampleTest.php
^ "20 MB"
.^ "20 MB"
.^ "20 MB"
[TRUNCATED]
.^ "22 MB"
[TRUNCATED]
.^ "24 MB"
[TRUNCATED]
.^ "30 MB"

[DarkGhostHunter]

Lol that's my article.

I assume these test are done in vanilla Laravel. Did anyone tried the Opcache trick?

BTW, seems that RegisterProviders deals also with compiling providers, retrieving a manifest, and requiring them manually. I could bet is the getRequire() line in Illuminate\Foundation\ProviderRepository::loadManifest().

[driesvints]

Seems this is indeed still a culprit even after a fix in PHP core was merged here: https://github.com/php/php-src/pull/9265. Also see https://github.com/laravel/framework/issues/30736

@olsavmic do you might have knowledge of any other memory leaks in PHP core?

BTW, seems that RegisterProviders deals also with compiling providers, retrieving a manifest, and requiring them manually. I could bet is the getRequire() line in Illuminate\Foundation\ProviderRepository::loadManifest().

@DarkGhostHunter I disabled that call and the memory leak still happens.

Also, I think for this to be investigated we shouldn't focus on Opcache? Not sure what that has to do with anything.

[PHLAK]

I'd like to continue digging into this but not sure how to proceed (aside from a lot of code commenting). Is there an easy way to profile the code while running tests?

[DarkGhostHunter]

@driesvints I know but is just a workaround while we pinpoint the culprit.

[driesvints]

@PHLAK not that I know. Just use time <cmd> maybe?

[KristianI]

I'd like to continue digging into this but not sure how to proceed (aside from a lot of code commenting). Is there an easy way to profile the code while running tests?

Maybe xdebug profiler could be helpful in this connection.

[PHLAK]

I've profiled my application code while running tests. This generated several cachegrind.out.*.gz files that I am able to extract and open in qcachegrind. I read this Stack Overflow post to familiarize myself with the tool but there's still so much data to comb through so any recommendations as to what I should be looking for would be helpful.

[driesvints]

Just pinging you @brendt as well (since you originally opened the other issue) to see if you had any thoughts here?

[nunomaduro]

Going to take a look at this next Monday. ✅

[taylorotwell]

Has anyone tried to recreate the issue on initial release of Laravel 8.0? or Laravel 7.0? So we can see possibly when the memory leak was introduced if it is indeed something new. Or, if it something that has been around for some time.

[PHLAK]

I ran the example test against Laravel v8.83.24 with similar results.

I'm getting errors when trying to install Laravel 7 (i.e. composer create-project laravel/laravel=7.* laratest) so couldn't evaluate it there. Can dig into it more later.

[ljubadr]

There is a discussion about this as well - [8.x] Memory leak on testing #39255. Might have some useful info

[olsavmic]

I found and issue with registration of error handlers in Illuminate\Foundation\Bootstrap\HandleException.

I tried to fix it in https://github.com/laravel/framework/pull/44293 but it's not trivial (as already stated in the original MR https://github.com/laravel/framework/pull/40656#issuecomment-1022954055).

It just the one class that's leaking and the memory increases very slowly so I guess it's not the problem the author of this issue is dealing with :/

@PHLAK just for reference, the original test from the article you used is not performing the cleanup completely which is the reason it leaks so fast. Look at \Illuminate\Foundation\Testing\TestCase::tearDown, line 220 - 222. The second test case with repeated PHPUnit test case runs works correctly but it leaks significantly slower (and stops leaking after the fix is applied).

[nunomaduro]

Friends, can you please try out your test suite on the latest 9.x-dev branch, and tell me the before / after result?

[DarkGhostHunter]

I’ll do it after I get out of work today. Italo Baeza C.El 26-09-2022, a la(s) 15:04, Nuno Maduro @.***> escribió: Friends, can you please try out your test suite on the latest 9.x-dev branch, and tell me the before / after result?

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you were mentioned.Message ID: @.***>

[PHLAK]

I ran my app's test suite locally with and without the applied fixes and oddly the memory consumed was identical between the runs ~~but the time went down dramatically~~. I should probably repeat these tests to see if the results are similar across multiple runs but here's the initial results.

EDIT: I re-ran the tests multiple times and the time was more consistent between runs. The difference in reported time was probably a fluke. As for the memory usage being identical across runs I think this has to do with parallel testing.

Before Fix

Time: 03:33.834, Memory: 112.50 MB

EDIT: Additional runs

Time: 01:55.963, Memory: 112.50 MB
Time: 01:59.639, Memory: 112.50 MB
Time: 02:26.264, Memory: 112.50 MB

After Fix

Time: 02:01.386, Memory: 112.50 MB

I then pushed a branch with the fixes to CI and it failed the same as before.

All of these tests were run with the artisan test --parallel command.

[JayBizzle]

Also seeing no improvement (non-parallel test run)...

Before

Time: 03:32.268, Memory: 251.00 MB
Tests: 1271, Assertions: 4089, Skipped: 3.

After

Time: 03:37.094, Memory: 251.00 MB
Tests: 1271, Assertions: 4089, Skipped: 3.

[PHLAK]

I did a few more (partial) test runs with before and after fix code, this time not using the --parallel flag. I also dumped the memory usage in the tearDown() method to see it's change over time.

In both cases the memory usage continued to grow indefinitely. However, with the fixes applied the memory growth appeared (subjectively) to grow much slower and was (objectively) much lower in the end (625 MB before fixes vs 252 MB after fixes). I also noticed a few points where the memory reported went down (albeit only one or two MB) between reportings with the fixed code.

Here are the results.

Before Fix

$ artisan test tests/Feature/Http/Controllers/

^ "109 MB"
^ "109 MB"
^ "111 MB"
^ "111 MB"
^ "113 MB"
^ "115 MB"
^ "115 MB"
^ "117 MB"
^ "120 MB"
^ "122 MB"
...
^ "227 MB"
^ "227 MB"
^ "229 MB"
^ "229 MB"
^ "229 MB"
...
^ "623 MB"
^ "625 MB"
^ "625 MB"
^ "625 MB"

...

  Tests:  30 skipped, 1160 passed
  Time:   250.23s

After Fix

$ artisan test tests/Feature/Http/Controllers/

^ "109 MB"
^ "109 MB"
^ "111 MB"
^ "111 MB"
^ "113 MB"
^ "115 MB"
^ "115 MB"
^ "117 MB"
^ "117 MB"
^ "117 MB"
...
"155 MB"
"155 MB"
"157 MB"
"157 MB"
"157 MB"
"157 MB"
"155 MB" // Notice the decrease
"155 MB"
"157 MB"
"157 MB"
"155 MB" // Another decrease
"157 MB"
"157 MB"
"157 MB"
...
"250 MB"
"250 MB"
"252 MB"
"252 MB"
"252 MB"
"252 MB"
"252 MB"
"252 MB"

...

  Tests:  30 skipped, 1160 passed
  Time:   253.40s

[PHLAK]

One more thing to note, I just installed a fresh Laravel app from the 9.x-dev branch and repeated my test from above and still see the memory increasing (though slightly less than before).

$ laravel new --dev laratest

$ cd laratest

// Edited tests/Feature/ExampleTest.php

$ phpunit --repeat 1000 tests/Feature/ExampleTest.php
PHPUnit 9.5.25 #StandWithUkraine

"20 MB"
."20 MB"
."20 MB"
...
.  244 / 1000 ( 24%)
"26 MB"
."26 MB"
."26 MB"
...
.  549 / 1000 ( 54%)
"28 MB"
."28 MB"
."28 MB"
...
.  732 / 1000 ( 73%)
"28 MB"
."28 MB"
."28 MB"
...
."28 MB"
."28 MB"
."28 MB"
.                                      1000 / 1000 (100%)

Time: 00:12.838, Memory: 28.00 MB

OK (1000 tests, 1000 assertions)

[rodrigopedra]

I wrote this shell script (tested in Linux) that:

• Creates a fresh Laravel
• Updates laravel/framework to 9.x-dev
• Creates 1,000 test classes, with a single test case and a single assertion
• Runs the tests

#!/bin/sh
########### options and variables
while getopts 'u' options; do
    case $options in
        u) namespace="Tests\Unit";;
    esac
done

shift $((OPTIND-1))

project=$1
namespace=${namespace:-"Tests\Feature"}
parent=$([ $namespace == "Tests\Feature" ] && echo "Tests\TestCase" || echo "PHPUnit\Framework\TestCase")

########### script commands
rm -rf $project
composer create-project laravel/laravel $project
cd $project || exit
composer require laravel/framework:9.x-dev

# verify git hash
composer show laravel/framework | grep "source   :"

# verify nuno's last commit
sed -n -e '220,221p' ./vendor/laravel/framework/src/Illuminate/Foundation/Testing/TestCase.php

# give a chance to verify
sleep 3

rm ./tests/Unit/ExampleTest.php
rm ./tests/Feature/ExampleTest.php

i=1

while [ $i -le 1000 ]; do
prefix=$(printf 'Case%04d' $i)

echo "<?php

namespace ${namespace};

use ${parent};

class ${prefix}Test extends TestCase
{
    public function test_memory_leak()
    {
        echo \PHP_EOL, 'Memory: ', ((int) (memory_get_usage(true) / (1024 * 1024))), 'MB';

        \$this->assertTrue(true);
    }
}" > ./tests/Feature/${prefix}Test.php

i=$(( $i + 1 ))
done

php artisan test

cd ..
rm -rf $project

It accepts a -u flag to create and run tests as Unit Tests, or -- when missing -- as Feature tests.

It also requires a project name. Note that the project folder will be forcefully removed before and after execution.

Below are the memory outputs, truncated to just the first and last test output for brevity

Running for Feature Tests

$ ./create-test.sh leak-test 
Memory: 56MB
   PASS  Tests\Feature\Case0001Test
  ✓ memory leak

# ...

Memory: 238MB
   PASS  Tests\Feature\Case1000Test
  ✓ memory leak

  Tests:  1000 passed
  Time:   4.22s

Running for Unit Tests

$ ./create-test.sh -u leak-test 

Memory: 38MB
   PASS  Tests\Unit\Case0001Test
  ✓ memory leak

# ...

Memory: 42MB
   PASS  Tests\Unit\Case1000Test
  ✓ memory leak

  Tests:  1000 passed
  Time:   0.15s

Note that there is a small overhead when running only Unit Tests. This is also present when running the tests with the ./vendor/bin/phpunit command.

Hope this helps.

[PHLAK]

Thanks @rodrigopedra but it's unecessary to create 1000 actual test cases. You can use phpunit --repeat to repeat a single test an arbitrary number of times.

[DarkGhostHunter]

Got similar results.

Does this happen with other testing frameworks?

[rodrigopedra]

@PHLAK thanks for reviewing it.

When running a single test class with --repeat=1000 the memory:

• goes from 20MB to 28MB on Feature Tests
• stays constant at 8MB on Unit tests

That is why I created 1,000 test cases, to mimic an environment with several test classes instead of repeating a single test over and over.

You can verify this with the slightly modified script below. Changed lines have a comment # CHANGED at their end.

Usage is the same as before:

#!/bin/sh
########### options and variables
while getopts 'u' options; do
    case $options in
        u) namespace="Tests\Unit";;
    esac
done

shift $((OPTIND-1))

project=$1
namespace=${namespace:-"Tests\Feature"}
parent=$([ $namespace == "Tests\Feature" ] && echo "Tests\TestCase" || echo "PHPUnit\Framework\TestCase")

########### script commands
rm -rf $project
composer create-project laravel/laravel $project
cd $project || exit
composer require laravel/framework:9.x-dev

# verify git hash
composer show laravel/framework | grep "source   :"

# verify nuno's last commit
sed -n -e '220,221p' ./vendor/laravel/framework/src/Illuminate/Foundation/Testing/TestCase.php

# give a chance to verify
sleep 3

rm ./tests/Unit/ExampleTest.php
rm ./tests/Feature/ExampleTest.php

i=1

while [ $i -le 1 ]; do # CHANGED
prefix=$(printf 'Case%04d' $i)

echo "<?php

namespace ${namespace};

use ${parent};

class ${prefix}Test extends TestCase
{
    public function test_memory_leak()
    {
        echo \PHP_EOL, 'Memory: ', ((int) (memory_get_usage(true) / (1024 * 1024))), 'MB';

        \$this->assertTrue(true);
    }
}" > ./tests/Feature/${prefix}Test.php

i=$(( $i + 1 ))
done

php artisan test --repeat=1000 # CHANGED

cd ..
rm -rf $project

[nunomaduro]

Thank you for sharing your feedback. To keep the output of everyone focused, please only share results of real test suites without the parallel flag (not repeats, not scripts, not loops), and share the output of PHPUnit via ./vendor/bin/phpunit (or pest with the memory plugin) like so:

# Before:
Time: X:XX, Memory: XX.XX MB

OK (XXXX tests, XXXX assertions)

# After:
Time: X:XX, Memory: XX.XX MB

OK (XXXX tests, XXXX assertions)

[rodrigopedra]

@nunomaduro , thanks for looking into it.

The app I tested only has the standard breeze tests installed. It is a real app, but without any further tests written.

The only change I made was just adding the memory output on the ./tests/TestCase.php's tearDown() method, as it wasn't clear how we'd measure the memory leak without seeing its progress.

<?php

namespace Tests;

use Illuminate\Foundation\Testing\TestCase as BaseTestCase;

abstract class TestCase extends BaseTestCase
{
    use CreatesApplication;

    protected function tearDown(): void
    {
        parent::tearDown();

        echo \PHP_EOL, 'Memory: ', ((int) (memory_get_usage(true) / (1024 * 1024))), 'MB';
    }
}

If you have a better way of tracking memory usage, let me know.

Running Laravel 9.31.0

# Before:
PHPUnit 9.5.25 #StandWithUkraine

.
Memory: 28MB.
Memory: 32MB.
Memory: 32MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 36MB.
Memory: 38MB.
Memory: 38MB.
Memory: 38MB.
Memory: 38MB.                                                   15 / 15 (100%)
Memory: 38MB

Time: 00:00.401, Memory: 38,50 MB

Running Laravel 9.x-dev a6d80b7

# After:
PHPUnit 9.5.25 #StandWithUkraine

.
Memory: 28MB.
Memory: 32MB.
Memory: 32MB.
Memory: 32MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 34MB.
Memory: 38MB.
Memory: 38MB.
Memory: 38MB.
Memory: 38MB.                                                   15 / 15 (100%)
Memory: 38MB

Time: 00:00.673, Memory: 38,50 MB

[nunomaduro]

@rodrigopedra 👍🏻

Going to keep working on this. For info everyone, there is a memory leak on the package bugsnag.

• https://github.com/bugsnag/bugsnag-php/pull/651
• https://github.com/bugsnag/bugsnag-laravel/pull/493

[driesvints]

Are you all using Bugsnag?

[nunomaduro]

For info everyone, here is the recap of my investigation yesterday. And going to keep working on it today.

Use case: Using Vapor's test suite, more than 600 HTTP / Jobs / Console tests.

# Leak #1: https://github.com/laravel/framework/pull/44306
Before: 280.50 MB // Using v9.31.0.
After: 190.50 MB
Down: 33% 📉

# Leak #2: https://github.com/bugsnag/bugsnag-php/pull/651
Before: 190.50 MB
After: 168.50 MB
Down: 14% 📉

# Leak #3: https://github.com/laravel/framework/pull/44307
Before: 168.50 MB
After: 166.50 MB
Down: 1% 📉