php artisan test super slow after updating to v10.34.2 from v10.33.0

sts-ryan-holton commented 9 months ago

Laravel Version

10.34.2

PHP Version

8.2.12

Database Driver & Version

MySQL

Description

When running php artisan test, each test is now taking significantly longer to run since updating from v10.33.0 to v10.34.2. I'm using assertJsonFragment in my test cases.

The screenshots attached highlight the differences where all I did was both upgrade & downgrade. I have in excess of 50 tests, and here's the comparison of test times between framework versions:

v10.33.0 = takes less than 60 seconds
v10.34.2 = takes 155 seconds to run

I suspect that this change might be responsible for the performance bottle neck.

Steps To Reproduce

Create a Feature test that asserts JSON fragment

/**
 * A basic feature test example.
 */
public function test_user_notifications_endpoint_returns_correct_response_when_deleting(): void
{
    $userId = $this->user->id;

    $this->loginAs($this->user);

    $response = $this->delete("/api/account/$userId/notifications/99999");

    $response->assertStatus(404)
                ->assertJsonFragment([
                'metadata' => [
                    'message' => 'Notification not found or already marked as read.'
                ]
            ]);
}

Run php artisan test
Observe the performance outcome of both

Framework v10.33.0

laravel-framework-v10 33 0

Framework v10.34.2

laravel-framework-v10 34 2

Here's my composer.json file:

{
    "name": "laravel/laravel",
    "type": "project",
    "description": "The Laravel Framework.",
    "keywords": [
        "framework",
        "laravel"
    ],
    "license": "MIT",
    "require": {
        "php": "^8.1",
        "deployer/deployer": "7.3.3",
        "doctrine/dbal": "^3.6",
        "guzzlehttp/guzzle": "^7.2",
        "lab404/laravel-impersonate": "1.7.4",
        "laravel-notification-channels/webhook": "2.5.0",
        "laravel/fortify": "1.19.0",
        "laravel/framework": "10.34.2",
        "laravel/horizon": "5.21.4",
        "laravel/sanctum": "3.3.2",
        "laravel/slack-notification-channel": "3.1.0",
        "laravel/telescope": "4.17.2",
        "laravel/tinker": "^2.8",
        "mongodb/laravel-mongodb": "4.0.2",
        "mtownsend/collection-xml": "^1.7",
        "mtownsend/request-xml": "2.3.0",
        "mtownsend/response-xml": "2.2.0",
        "nesbot/carbon": "2.71.*",
        "php-http/message-factory": "^1.1",
        "propaganistas/laravel-disposable-email": "2.2.15",
        "propaganistas/laravel-phone": "5.0.3",
        "psr/http-factory-implementation": "*",
        "rappasoft/laravel-authentication-log": "3.0.0",
        "rinvex/countries": "9.0.1",
        "sentry/sentry-laravel": "4.1.0",
        "spatie/cpu-load-health-check": "1.0.4",
        "spatie/laravel-health": "1.23.7",
        "spatie/laravel-permission": "6.1.0",
        "spatie/laravel-schedule-monitor": "3.4.1",
        "square1/laravel-collection-rolling-average": "1.0.0",
        "staudenmeir/laravel-adjacency-list": "1.13.11",
        "thomasjohnkane/snooze": "2.3.1",
        "torann/geoip": "3.0.5",
        "yoeriboven/laravel-log-db": "1.1.1"
    },
    "require-dev": {
        "fakerphp/faker": "^1.9.1",
        "laravel/pint": "^1.0",
        "phpspec/prophecy": "~1.0",
        "laravel/sail": "1.26.2",
        "mockery/mockery": "^1.4.4",
        "nunomaduro/collision": "^7.0",
        "php-mock/php-mock": "^2.4",
        "phpunit/phpunit": "^10.0",
        "spatie/laravel-ignition": "^2.0"
    },
    "autoload": {
        "psr-4": {
            "App\\": "app/",
            "Database\\Factories\\": "database/factories/",
            "Database\\Seeders\\": "database/seeders/"
        },
        "files": [
            "app/helpers.php"
        ]
    },
    "autoload-dev": {
        "psr-4": {
            "Tests\\": "tests/"
        }
    },
    "scripts": {
        "post-autoload-dump": [
            "Illuminate\\Foundation\\ComposerScripts::postAutoloadDump",
            "@php artisan package:discover --ansi"
        ],
        "post-update-cmd": [
            "@php artisan vendor:publish --tag=laravel-assets --ansi --force"
        ],
        "post-root-package-install": [
            "@php -r \"file_exists('.env') || copy('.env.example', '.env');\""
        ],
        "post-create-project-cmd": [
            "@php artisan key:generate --ansi"
        ]
    },
    "extra": {
        "laravel": {
            "dont-discover": []
        }
    },
    "config": {
        "optimize-autoloader": true,
        "preferred-install": "dist",
        "sort-packages": true,
        "allow-plugins": {
            "pestphp/pest-plugin": true,
            "php-http/discovery": true
        }
    },
    "minimum-stability": "stable",
    "prefer-stable": true
}

driesvints commented 9 months ago

@nshiro since you sent in that PR, what are your thoughts here?

sts-ryan-holton commented 9 months ago

Additionally which may help...

I tried commenting out everything within the setUp function and createRolesWithPermissions function in my TestCase.php file just in case these caused a slow down:
I tried adding <ini name="memory_limit" value="4G" /> to the phpunit.xml file, no difference:

// <-- added to see if this made any improvement in v10.34.2



- Various runs range in excess of 150 seconds, here's one taking over 170 seconds. No test failures, on v10.33.0 the same number of tests take around 48 seconds.

![Screenshot 2023-12-05 at 12 41 22](https://github.com/laravel/framework/assets/25177538/ebbc79b9-b3bb-42a2-bf07-488042a87072)

crynobone commented 9 months ago

@sts-ryan-holton can you verify if your tests using UserFactory and share the content of UserFactory?

nshiro commented 9 months ago

@driesvints @sts-ryan-holton The code I changed is only used when you fail tests. So I don't think it affects the speed.

sts-ryan-holton commented 9 months ago

UserFactory looks like this:

<?php

namespace Database\Factories;

use Carbon\Carbon;
use Illuminate\Database\Eloquent\Factories\Factory;
use Illuminate\Support\Facades\Hash;

class UserFactory extends Factory
{
    /**
     * Define the model's default state.
     */
    public function definition(): array
    {
        return [
            'timezone' => 'UTC',
            'first_name' => $this->faker->firstName(),
            'last_name' => $this->faker->lastName(),
            'email' => $this->faker->unique()->safeEmail(),
            'email_verified_at' => Carbon::now(),
            'password' => Hash::make('password', [
                'rounds' => 5, // only for dummy users, do not use this value for production.
            ]),
            'country_code' => 'GB',
            'phone_number' => '+447900000000',
            'prefers_time_sensitive_notifications' => false,
            'notify_on_days' => [1, 2, 3, 4, 5, 6, 7],
            'notify_time_slot' => 'anytime',
            'datetime_format' => 'HH:mm, MMM Do YYYY',
            'on_holiday_until' => null
        ];
    }

    /**
     * Indicate that the model's email address should be unverified.
     */
    public function unverified(): Factory
    {
        return $this->state(function (array $attributes) {
            return [
                'email_verified_at' => null,
            ];
        });
    }
}

No difference setting hash to 1 btw. This file hasn't changed between versions.

driesvints commented 9 months ago

@sts-ryan-holton could you pinpoint the exact version where things went slow for you?

sts-ryan-holton commented 9 months ago

@driesvints Sure thing, I'll try my best :)

Basically, I update my project once a week with dependencies. Currently, on v10.34.2 with the composer.json file in the description and running php artisan test every single test is super slow. If I just update:

From:

"laravel/framework": "10.34.2"

To (downgrade):

"laravel/framework": "10.33.0"

Without changing anything else in my project and running composer update (only Laravel framework gets downgraded), then the tests in my project instantly get faster. Upgrading to 10.34.2 again slows it back down, no other changes in code.

Additionally, I even tried individual versions of the framework since that release, here's my results:

prior to v10.33.0 - fast sub minute)
v10.33.0 - fast (sub minute)
v10.34.0 - slow (150+ seconds)
v10.34.1 - slow (150+ seconds)
v10.34.2 - slow (150+ seconds)

taylorotwell commented 9 months ago

@sts-ryan-holton have you tried simply reverting this change in your vendor directory and seeing if it helps? Can you also share your entire test file? What database traits are you using?

https://github.com/laravel/framework/pull/49160

driesvints commented 9 months ago

It should be one of these PR's then. Would appreciate any help in figuring out which one it is: https://github.com/laravel/framework/releases/tag/v10.34.0

github-actions[bot] commented 9 months ago

Thank you for reporting this issue!

As Laravel is an open source project, we rely on the community to help us diagnose and fix issues as it is not possible to research and fix every issue reported to us via GitHub.

If possible, please make a pull request fixing the issue you have described, along with corresponding tests. All pull requests are promptly reviewed by the Laravel team.

Thank you!

taylorotwell commented 9 months ago

@sts-ryan-holton in addition, it would probably be helpful if you could create a fresh Laravel application that recreates the issue in the test suite and push it to GitHub. Then we can clone it down and actually try it locally.

sts-ryan-holton commented 9 months ago

I'll take a look now

sts-ryan-holton commented 9 months ago

@driesvints @taylorotwell Okay, just tried commenting out:

JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE

Removing those and reverting back to the original makes no difference in performance. For this reason then, unless anything else has changed, I don't think that particular PR is responsible for the significant performance bottleneck, but, it stood out as it's related to testing.

Another PR out of that list must be responsible as I have also just tried again reverting downwards and instantly get the speed up.

taylorotwell commented 9 months ago

@sts-ryan-holton it may be the transaction related PR - are you able to create a test repo for us to clone down?

sts-ryan-holton commented 9 months ago

@taylorotwell Is there a way I can revert that change locally to see if it is causing the problem? Creating a test repo might take longer than reverting that change and reverting the files?

If I revert those files or parts of them that might pinpoint the change?

crynobone commented 9 months ago

@sts-ryan-holton We still need to be able to replicate the issue and determine what can be done to improve the code. The only way to be able to do that is by having a reproducible code.

v10.34.0: https://github.com/laravel/framework/actions/runs/7020631916/job/19100818953 v10.33.0: https://github.com/laravel/framework/actions/runs/6945488635/job/18894960822

There no significant time increased in Framework own tests to suggest there is an issue with Transaction related changes.

taylorotwell commented 9 months ago

@sts-ryan-holton maybe - you would probably need to revert ManagesTransaction, DatabaseTransactionManager, and maybe Connection to make it happen.

Agree with @crynobone a repo is likely still necessary for us to actually fix it even if that is causing the issue.

cosmastech commented 9 months ago

Not much to add in way of a solution, but I've been noticing an increase in parallel worker crashes in our app pipelines since upgrading packages on Monday.

Didn't look into it too deeply, as I figured it may have just been an environment issue on our end.

sts-ryan-holton commented 9 months ago

@taylorotwell Okay, I've done some debugging. And things are getting interesting, please take the time to review these additional findings thus far:

First, I tried setting up a completely new Laravel project and setting my version to 10.34.2. I then created a simple controller, and a simple test, I copied over the dev dependencies from my main project, and copied over some of the same settings frfom my TestCase.php file, I then created a few tests and ran them.
- The findings from this: when switching between v10.33.0 and v10.34.2, I saw no difference at all, both versions of the framework took 0.55s to run.. I don't see this being beneficial to push to Github for this reason, but I can if you would like?
Next, I re-visited my main project, still on v10.34.2 and still extremely slow in comparison to v10.33.0.
I reverted the files in my vendor directory that you'd modified around the transaction stuff, I reverted them back to this set of changes from a month ago which is long before you'd made the edits.

So strangely, I don't think the transaction PR is to blame here either.

And, to further clarify, whilst reverting those files back, I ran php artisan test both on v10.33.0 and v10.34.2, and there's still a significant improvement in speed, see attached:

v10.34.2 (with reverted transaction db files)

old_db

v10.33.0

10 34 2

Also, now that v10.35.0 is out, I also tested on here. On v10.35.0 there's still a significant performance degradation.

@crynobone

As for performance differences, note that in the two sets of actions, in the newer version of v10.34.2, your tests are 25% slower than v10.33.0, which this is quite significant in my opinion.

crynobone commented 9 months ago

10.33.0

Time: 01:08.550, Memory: 325.50 MB

OK, but there were issues!
Tests: 9199, Assertions: 27320, Deprecations: 1, Skipped: 238.

10.34.0

 Time: 01:10.584, Memory: 327.50 MB

Tests: 9228, Assertions: 27393, Deprecations: 1, Skipped: 240.

Compared version using PHP 8.2 (prefer stable), the closest to your reported issue with the latest version having 29 more tests and only 2 extra seconds is minimal, I wouldn't call that significant.

crynobone commented 9 months ago

10.35.0 (PHP 8.2 stable)

Time: 01:08.005, Memory: 329.50 MB

Tests: 9234, Assertions: 27445, Deprecations: 1, Skipped: 240.

sts-ryan-holton commented 9 months ago

I'm simply comparing the difference in times from the links you'd sent above:

10.33.0 link

succeeded 2 weeks ago in 3m 16s

10 33 0-tests

10.34.0 link

succeeded last week in 4m 14s

10 34 0-tests

An entire minute increase in changing the version of the framework. Which, arguably, based on the number of tests shown in your most recent screenshot would imply that if quite a few tests were added and the time doesn't go up by that much that a minute increase is quite significant

I'd agree with @cosmastech that something is up, and seeing as it's not technically "broken", most people might be late in identifying this. Yet I update on the day for most weeks. In addition, we see the following error running tests locally as well on the newer version half-way through running tests on v10.34.0 which we don't see on v10.33.0 (note, I didn't see this, but this can be platform specific)

Allowed memory size of 134217728 bytes exhausted (tried to allocate 13912304 bytes)

crynobone commented 9 months ago

@sts-ryan-holton that time difference includes setting up the container, running composer install, and other requirements, you should instead just look at PHPUnit execution times.

We can only move forward with reproducible code. We have reviewed our other internal application and are unable to replicate this issue, and this doesn't seem to be a widespread issue as others would already submit similar issues.

taylorotwell commented 9 months ago

I agree it's tough for us to move this issue forward without a repo we can clone down to reproduce the issue. Happy to look if something like that can be produced. 👍

cosmastech commented 9 months ago

@sts-ryan-holton I wonder if there maybe isn't another shared package in both of our applications that is causing this to happen? 🤔

sts-ryan-holton commented 9 months ago

I've got a list of dependencies in my original description :)

devoidfury commented 9 months ago

In your test class that sees the big performance difference, what base test class are you extending, which traits are applied to the class? Is there any other setup code with those could be relevant here?

driesvints commented 9 months ago

We're going to close this as there's only one single report for this so far. So most likely this is something for your specific use case and not affecting other Laravel apps. Please try a support channel going forward, thanks.

EPGDigital-MW commented 7 months ago

I noticed my tests running slowly recently. It looks like there is an issue somewhere, 10.33.0 tests:

Tests: 2 risky, 96 passed (307 assertions) Duration: 10.73s

10.34.0

Tests: 2 risky, 96 passed (307 assertions) Duration: 24.47s

After updating to the latest:

Tests: 2 risky, 96 passed (307 assertions) Duration: 29.93s

However, I've isolated why my tests are running slow, if I comment out this sqliteCreateFunction from my test setup then they run fast again.

            DB::connection()->getPdo()->sqliteCreateFunction(
                'CONVERT_TZ',
                function ($value, $fromTimezone, $toTimezone) {
                    return Carbon::createFromFormat('Y-m-d H:i:s', $value, $fromTimezone)->setTimezone($toTimezone);
                }
            );

Not spotted the issue in the framework that's causing this.

sts-ryan-holton commented 7 months ago

Larwvel 10.34 and on certainly has slowed tests down significantly. We've had to factor this additional time into our build processes

apspan commented 5 months ago

I back @sts-ryan-holton. 10.34 introduced a significant delay of aprox 100ms per test. @EPGDigital-MW sqliteCreateFunction was my initial consideration but after I started timing everything I've excluded it. I have nearly 20 sqliteCreateFunctions in my tests and it takes about 5-10 ms to run.

Digging around to find discrepancies in the process, I started dumping raw migrations SQLs in files and compare between 10.33 and 10.44.

10.44 run the following two during migrations: select 1 from pragma_compile_options where compile_options = 'ENABLE_DBSTAT_VTAB') as enabled; select m.tbl_name as name, sum(s.pgsize) as size from sqlite_master as m join dbstat as s on s.name = m.name where m.type in ('table', 'index') and m.tbl_name not like 'sqlite_%' group by m.tbl_name order by m.tbl_name;

Digging around a little bit more, I found that these have been introduced because of the change in src/Illuminate/Database/Schema/Builder.php

Commit: https://github.com/laravel/framework/commit/50807dbcb79c863d5cb5da52de929ee9ca508d33#diff-1a147b8174f4809f7471525e9d676e831176efdbeb69af8af6e95c1a72aef962R162

This foreach calls getTables: https://github.com/laravel/framework/commit/50807dbcb79c863d5cb5da52de929ee9ca508d33#diff-5ceeb999b82b50cc8a3ec3e64b5a98af805fde210c2c58d407706965d109d38d

and that calls compileDbstatExists and compileTables and runs these two queries: https://github.com/laravel/framework/commit/50807dbcb79c863d5cb5da52de929ee9ca508d33#diff-7cf2f940b724463282b1dbae24464cb3a7c7c0864d40b4c3706eb99f65994d2cR46

Reverting the code in src/Illuminate/Database/Schema/Grammars/SQLiteGrammar.php from:

        foreach ($this->getTables() as $value) {
            if (strtolower($table) === strtolower($value['name'])) {
                return true;
            }
        }

To:

        return count($this->connection->selectFromWriteConnection(
                $this->grammar->compileTableExists(), [$table]
            )) > 0;

brings the testing speeds back to normal.

Digging a bit more (sorry I know 😢) I found that this: https://github.com/laravel/framework/commit/94634fe7127449ba438b6fd62cbcc31fa598e603 is what actually causing the delay. (i.e. the select 1 from pragma_compile_options where compile_options = 'ENABLE_DBSTAT_VTAB') as enabled; query)

\Illuminate\Database\Schema\SQLiteBuilder::getTables is being called by \Illuminate\Database\Schema\Builder::hasTable and every time hasTable is being called, effectively trying to get a true/false answer, we delay the response because we calculate the table size (something completely useless for our yes or no question).

This is my suggestion: https://github.com/laravel/framework/pull/50869

cc @taylorotwell

sts-ryan-holton commented 5 months ago

Tests have been super slow since updating and have been since. It's been 4 months+ now, yet still slow.

apspan commented 5 months ago

Benchmarks added: https://github.com/laravel/framework/pull/50888

hafezdivandari commented 5 months ago

Have you tried LazilyRefreshDatabase (PR #38861) instead of RefreshDatabase?

RefreshDatabase calls migrate:fresh command that uses hasTable() internally. LazilyRefreshDatabase does the same but only when the database is actually required in the test.

apspan commented 5 months ago

Have you tried LazilyRefreshDatabase (PR #38861) instead of RefreshDatabase?

RefreshDatabase calls migrate:fresh command that uses hasTable() internally. LazilyRefreshDatabase does the same but only when the database is actually required in the test.

Yes I'm using it for some time now. My test suite is made of nearly 10k tests and the 100ms delay adds about 15mins to the total CI pipeline.

As I mentioned in my latest PR, hasTable returns a Boolean and the table size is irrelevant, especially when it adds unnecessary overhead. Unless I missed something through the flow? Apologies if I did.

sts-ryan-holton commented 5 months ago

@hafezdivandari I'll jump back in an just mention, that although there might be alternative traits and features to improve the performance, but fundamentally, when the issue was initially open, simply upgrading without implementing said features caused a significant performance impact.

apspan commented 5 months ago

@sts-ryan-holton 10.48.5 went out an hour ago. I'm keen to know if my fix has sorted out your issue. It worked for me.

sts-ryan-holton commented 5 months ago

@apspan I can confirm after upgrading to this version, that prior to upgrading would take 156 seconds. After upgrading it took just 38 seconds, so yes, that change worked.

Worth also noting, I had a few tests on my most recent Laravel 11 project which has also become a few seconds faster.

Honestly can't believe that this bug has been around since December 2023, but glad it's resolved now 👍

laravel / framework