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

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

  1. 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.'
                ]
            ]);
}
  1. Run php artisan test
  2. 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
}

About this issue

  • Original URL
  • State: closed
  • Created 7 months ago
  • Reactions: 2
  • Comments: 38 (22 by maintainers)

Most upvoted comments

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

@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 👍

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

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

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 could you pinpoint the exact version where things went slow for you?

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