What's causing this slowdown in HTTP requests compared to CLI requests?

Question

I'm developing a Laravel 5.5 app using PHP 7.1 in a WAMP environment. I'm using a value object for Money and wanted to benchmark it to ensure that basic arithmetic operations with it aren't too expensive. So I wrote the following test which compares adding money using PHP floats (the control) vs using the Money object (the test). It averages out the times over multiple tests.

<?php

namespace App\Delegators;
use App\Admin\Attributes\Money;
use App\Admin\General\Currency;
use App\Admin\Marketplaces\NetworkStore;
use App\Admin\Repo;

/**
 * Benchmark helper class.
 */
class Benchmark
{
    public function money()
    {
        /** @var NetworkStore $store */
        $store = Repo::GetSelectedStore();

        /**
         * Declare at what numbers the test starts and ends.
         *
         * This numbers represent the bounds for the number of times money will be added together.
         */
        $testFrom = 90;
        $testTo = 100;

        // Declare the number of times each test will be run.
        $numberOfTests = 2;

        dump('Money Benchmark: Control');

        // Foreach test.
        for ($t = $testFrom; $t < $testTo; $t++)
        {
            // Declare the average time taken for this test.
            $averageTimeTaken = 0;

            // Average the times over multiple such tests.
            for ($c = 0; $c < $numberOfTests; $c++)
            {
                $from = microtime(true);

                $money1 = 100;

                for ($i = 0; $i < $t; $i++)
                {
                    $money2 = (float) random_int(1, 10);

                    $money1 += $money2;
                }

                $averageTimeTaken += microtime(true) - $from;
            }

            // Divide the average by the total number of tests.
            $averageTimeTaken /= $numberOfTests;

            // Declare the themed time in ms.
            $themedTime = round($averageTimeTaken * 1000) .'ms';

            dump("Test $t: $themedTime");
        }

        dump('Money Benchmark: Value Object');

        /** @var Currency $currency */
        $currency = $store->getCurrency();

        // Foreach test.
        for ($t = $testFrom; $t < $testTo; $t++)
        {
            // Declare the average time taken for this test.
            $averageTimeTaken = 0;

            // Average the times over multiple such tests.
            for ($c = 0; $c < $numberOfTests; $c++)
            {
                $from = microtime(true);

                $money1 = new Money(100, $currency);

                for ($i = 0; $i < $t; $i++)
                {
                    $money2 = new Money(random_int(1, 10), $currency);

                    $money1->add($money2);
                }

                $averageTimeTaken += microtime(true) - $from;
            }

            // Divide the average by the total number of tests.
            $averageTimeTaken /= $numberOfTests;

            // Declare the themed time in ms.
            $themedTime = round($averageTimeTaken * 1000) .'ms';

            dump("Test $t: $themedTime");
        }

        dd("Money Test Complete");
    }
}

And I'm testing it in two places: at the top of a controller's index method and inside an artisan CLI command, respectively shown below.

Controller:

<?php

namespace App\Http\Controllers\Admin;

...

class HomeController extends Controller
{
    /**
     * Show the application dashboard.
     *
     * @return \Illuminate\Http\Response
     */
    public function index(Request $request)
    {
        $benchmark = new Benchmark;
        $benchmark->money();

        return view('admin.home');
    }
}

CLI:

<?php

namespace App\Console\Commands;

...

class Test extends Command
{
    ...

    /**
     * Execute the console command.
     *
     * @return mixed
     * @throws
     */
    public function handle()
    {
        $benchmark = new Benchmark;
        $benchmark->money();
    }
}

But the results of the benchmark in the CLI environment are over 10 times faster than what I get with a HTTP request, as shown below. I would expect there to be differences between the two environments based on cache and other configurations, but I don't understand how any of that would effect performance of the test I wrote.

Results for HTTP Request:

"Money Benchmark: Control"
"Test 90: 0ms"
"Test 91: 0ms"
"Test 92: 0ms"
"Test 93: 0ms"
"Test 94: 0ms"
"Test 95: 0ms"
"Test 96: 0ms"
"Test 97: 0ms"
"Test 98: 0ms"
"Test 99: 0ms"
"Money Benchmark: Value Object"
"Test 90: 27ms"
"Test 91: 23ms"
"Test 92: 23ms"
"Test 93: 24ms"
"Test 94: 24ms"
"Test 95: 24ms"
"Test 96: 24ms"
"Test 97: 25ms"
"Test 98: 24ms"
"Test 99: 25ms"
"Money Test Complete"

Results for CLI Request:

"Money Benchmark: Control"
"Test 90: 0ms"
"Test 91: 0ms"
"Test 92: 0ms"
"Test 93: 0ms"
"Test 94: 0ms"
"Test 95: 0ms"
"Test 96: 0ms"
"Test 97: 0ms"
"Test 98: 0ms"
"Test 99: 0ms"
"Money Benchmark: Value Object"
"Test 90: 2ms"
"Test 91: 1ms"
"Test 92: 1ms"
"Test 93: 1ms"
"Test 94: 1ms"
"Test 95: 1ms"
"Test 96: 1ms"
"Test 97: 1ms"
"Test 98: 1ms"
"Test 99: 1ms"
"Money Test Complete"

The number 90 in "Test 90: 1ms", for instance, means that $money2 was created and added to $money1 90 times.

My only guess is that it's a memory issue, with the application loading over the HTTP request being more memory intensive, so I tried using gc_disable() at the top of the application, confirming that garbage collection was disabled, but this did nothing. I also tried doubling the memory limit in php.ini, but that also had no effect.

At this point I'm pretty much at a loss as to what is causing such a massive difference in performance here. Any ideas?

Update

I've since run further tests that have narrowed the problem down to a general performance gap. It's more reproducible as well as it's a simple addition test:

<?php

...

/**
 * Benchmark helper class.
 */
class Benchmark
{
    public function addition()
    {
        /**
         * Declare the number of times to add a float.
         */
        $numberOfAdditions = 10000;

        // Declare the number of times each test will be run.
        $numberOfTests = 4;

        dump('Addition Benchmark');

        // Declare the number to add to.
        $number = 0;

        // Declare the average time taken for this test.
        $averageTimeTaken = 0;

        // Average the times over multiple such tests.
        for ($c = 0; $c < $numberOfTests; $c++)
        {
            $from = microtime(true);

            for ($i = 0; $i < $numberOfAdditions; $i++)
            {
                $number += rand(1, 5);
            }

            $averageTimeTaken += microtime(true) - $from;
        }

        // Divide the average by the total number of tests.
        $averageTimeTaken /= $numberOfTests;

        // Declare the themed time in ms.
        $themedTime = round($averageTimeTaken * 1000) .'ms';

        dd("Addition Test Complete: $themedTime");
    }
}

And here again are the tests run in the controller vs in the CLI via an artisan command.

Controller:

"Addition Benchmark"
"Addition Test Complete: 20ms"

CLI:

"Addition Benchmark"
"Addition Test Complete: 2ms"

Update 2

Here are additional details about my development environment that's running on WAMP:

PHP Version: 7.1.22
System: Windows NT LAPTOP 10.0 build 17134 (Windows 10) AMD64
Build Date: Sep 13 2018 00:39:35
Compiler: MSVC14 (Visual C++ 2015)
Architecture: x64
Zend Engine v3.1.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.1.22, Copyright (c) 1999-2018, by Zend Technologies
    with Xdebug v2.6.1, Copyright (c) 2002-2018, by Derick Rethans

Apache/2.4.35 (Win64) OpenSSL/1.1.1a PHP/7.1.22

Answer 1

Almost over a year later, I ran into this again, and after some more digging around I learned it was because of the XDebug extension. Unbelievable really, but simply disabling that extension increased performance 10 fold. I'm using WAMP and am really surprised that such an expensive extension is enabled by default.

Answer 2

Update

As you pointed out, the performance issue in non related to kernels. I dig further into the problem and find out that on my system the behaviour is the opposite.

Browser response

 "Addition Test Complete: 1ms"

CLI response

 "Addition Test Complete: 13ms"

So I started thinking that maybe php and web server versions as well as the operating system might engrave the outcome of the runs.

Furthermore, while looking at the php's help in the cli, I noticed a flag:

-n      No configuration (ini) files will be used

So I tried to run the cli command with that flag (php -n bench-test.php) and it did take the same time as the web browser: 1ms

I still don't have a 100% answer, but I think that's some parameter in the php.ini that's doing some sort of caching and in your case it's triggered by default in your cli, but not when executing php from webserver.

Could you provide more infos about your php version, operating system and web server? As well as if you did any kind of special configuration or installed any extension

For reference, my machine is running Windows 10 with the latest updates and the following versions:

PHP

PHP 7.3.2 (cli) (built: Feb  5 2019 23:16:38) ( ZTS MSVC15 (Visual C++ 2017) x86 )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.2, Copyright (c) 1998-2018 Zend Technologies
    with Xdebug v2.7.0RC2, Copyright (c) 2002-2019, by Derick Rethans

Apache

Server version: Apache/2.4.35 (Win64)
Apache Lounge VC15 Server built:   Sep 19 2018 16:08:47

---

Original answer

One of the noticeable differences is what is being bootstrapped when you receive an HTTP request compared to when you execute a command through artisan (cli).

That's because, for some obvious reasons, we don't need all the route, requests, middleware and http related stuff handling in a CLI execution.

That why the two executions has similar, but different Kernel and bootstrapping process.

---

CLI Bootstrap (Console Kernel)

This process starts when you execute any artisan command:

php artisan [rest of command]

Briefly, artisan^(source) is a php file that acts like the public/index.php (the HTTP entry-point of your laravel application which we will analyze later).

The artisan script, after loading the boostrap/app.php ^(source) file to obtain the application instance ($app), resolves the class bounded to Illuminate\Contracts\Console\Kernel interface in the IoC container.

This class has just been bound to App\Console\Kernel.php ^(source) in the boostrap/app.php ^(source) with this code:

$app->singleton(
    Illuminate\Contracts\Console\Kernel::class,
    App\Console\Kernel::class
);

Then artisan continues by executing the handle method on the $kernel instance (remember this is an instance of App\Console\Kernel.php class) he has just got, which extends the core console kernel class of Laravel: the Illuminate\Foundation\Console\Kernel ^(source) in which this method is defined at line 126.

The kernel does the following:

1. Bootstrap the kernel by executing a few classes declared in the $bootstrappers property (line 64)
2. Obtain the singleton instance of Illuminate\Console\Application ^(source) (or create a new one if it hasn't been created yet) (line 340)

Note: This class can be "simplified" as a wrapper around the symfony console application class (that's out of scope in this explanation).

3. Register commands into the application instance (line 341)
4. Pass the input to the application's run method (line 131)

Note: the run method is defined in the symfony console application class, but it's inherited by the Illuminate\Console\Application class

5. Return the outcome of the point 4 (line 131)

---

Web Browser Bootstrap (HTTP Kernel)

The process is pretty similar, but the entry point this time is no longer artisan, but public/index.php file.

If you compare this file to artisan, you notice only a few differences, the crucial one is that kernel resolved from the container is the class bound to Illuminate\Contracts\Http\Kernel class.

Again, this class has just been bound to App\Http\Kernel ^(source) in the boostrap/app.php with the following code:

$app->singleton(
    Illuminate\Contracts\Http\Kernel::class,
    App\Http\Kernel::class
);

So this time the Kernel class file is: Illuminate\Foundation\Http\Kernel ^(source)

You can start to notice some differences with the components used by the two kernels, as well as the size of the two because the http one contains more code related to the router component.

In fact, the http kernel does the following operations upon class creation:

1. Copy middleware priority in the router
2. Register middleware groups and aliases

Then the index file captures and parses the incoming HTTP request and executes the handle method, so the operations of the http kernel will keep on going:

3. Prepare request
4. Bootstrap the kernel (same logic as point 1 of the CLI Kernel)
5. Send the request through all the registered middlewares (the global ones, not the ones attached to routes that will be done at a later stage inside the router).
6. Dispatch the request to the router that will have to find the matching route, check its middleware, run the associated function/controller method, get a response from it and return it back to the caller to display it as output.

Conclusions

Especially the last point of the http kernel (apart from having summarized all of the router's work in a sentence), it's a pretty heavy job compared to registering a few classes (for commands) and make a matching between the input in the console kernel.

The former has a lot more going under the hood as more components/functionalities are interacting among them (you can think of request, response, middlewares, policies, api resources, validation, authentication, authorization, etc).

I gave you a more technical answer as I wanted to give you the idea of what's really going under the hood of that framework. I hope that's the kind of answer you were looking for.

If any point is unclear in my answer, I'm open to argue more in detail my answer.