search

hhxsv5 / laravel-s

LaravelS is an out-of-the-box adapter between Laravel/Lumen and Swoole.
MIT License
3.82k stars 470 forks source link

Response time increases possible memory leaks #468

Open DevilSerj opened 7 months ago

DevilSerj commented 7 months ago
  1. Your software version (Screenshot of your startup)

+--------------------------+---------+ | Component | Version | +--------------------------+---------+ | PHP | 7.4.33 | | Swoole | 4.8.13 | | LaravelS | 3.7.36 | | Laravel Framework [prod] | 8.25.0 | +--------------------------+---------+

  1. Detail description about this issue(error/log)

The problem is that I observe an increase in the response time from the server if it works for a certain time without restarting laravel-s. I started researching it to understand where the problem is and I realized that it happens at the moment of $laravel->cleanProviders(); in handleDynamicResource My log looks something like this:

end
[2024-02-24 02:40:59] prod.INFO: Time test onRequest handleDynamicResource end [43.0391]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource clean [42.933]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource send [42.455]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource setChunkLimit [42.295]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource end [42.2001]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource DynamicResponse end [42.105]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource DynamicResponse start [42.0079]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource fireEvent [41.909]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource setServer [41.7759]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource handleDynamic [41.6529]
[2024-02-24 02:40:59] prod.DEBUG: Time test route [40.9729]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource cleanProviders [39.9721]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders register 2 end [39.839]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders register 2 start [4.1599]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders class_exists [3.9661]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders provider [3.768,"Tymon\\JWTAuth\\Providers\\LaravelServiceProvider"]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders loadedProviders [3.577]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders start [3.376]
[2024-02-24 02:40:59] prod.INFO: Time test handleDynamicResource start [3.1719]
[2024-02-24 02:40:59] prod.INFO: Time test onRequest handleStaticResource [2.9171]
[2024-02-24 02:40:59] prod.INFO: Time test onRequest fireEvent [2.7149]
[2024-02-24 02:40:59] prod.INFO: Time test onRequest bindRequest [2.4419]
[2024-02-24 02:40:59] prod.INFO: Time test onRequest convertRequest [2.182]
[2024-02-24 02:40:59] prod.INFO: Time test onRequest [0.0439]
start

As you can see, the problem occurs at this step

[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders register 2 end [39.839]
[2024-02-24 02:40:59] prod.INFO: Time test cleanProviders register 2 start [4.1599]

Now it is 35 milliseconds, but it can reach up to 200 milliseconds.

As I understood, this happens when cleaning Tymon\JWTAuth\Providers\LaravelServiceProvider, but how can I fix it? Please help me with this.

  1. Some reproducible code blocks and steps

    
'register_providers' => [
    \Tymon\JWTAuth\Providers\LaravelServiceProvider::class,
],

'cleaners' => [ Hhxsv5\LaravelS\Illuminate\Cleaners\SessionCleaner::class, Hhxsv5\LaravelS\Illuminate\Cleaners\AuthCleaner::class, Hhxsv5\LaravelS\Illuminate\Cleaners\JWTCleaner::class, Hhxsv5\LaravelS\Illuminate\Cleaners\ConfigCleaner::class, \App\Cleaners\EventsCleaner::class, \App\Cleaners\SocialiteCleaner::class, ],


The part of the code where this happens

public function cleanProviders($log) { $loadedProviders = $this->reflectionApp->loadedProviders(); foreach ($this->providers as $provider) { if (class_exists($provider, false)) { if ($this->config['is_lumen']) { unset($loadedProviders[get_class(new $provider($this->currentApp))]); } switch ($this->reflectionApp->registerMethodParameterCount()) { case 1: $this->currentApp->register($provider); break; case 2: if ($log) { \Log::info('Time test cleanProviders register 2 start', [round((microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"])1000, 4)]); } $this->currentApp->register($provider, true); if ($log) { \Log::info('Time test cleanProviders register 2 end', [round((microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"])1000, 4)]); } break; case 3: $this->currentApp->register($provider, [], true); break; default: throw new \RuntimeException('The number of parameters of the register method is unknown.'); } } }

    if ($this->config['is_lumen']) {
        $this->reflectionApp->setLoadedProviders($loadedProviders);
    }
}
DevilSerj commented 7 months ago

I made the logging more detailed and I see the problem in Tymon\JWTAuth\Providers\AbstractServiceProvider in the register method, it takes a very long time and the time increases over time.


[2024-02-24 20:41:23] prod.INFO: Time test onRequest handleDynamicResource end [138.2208]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource clean [138.1369]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource send [137.7289]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource setChunkLimit [137.5299]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource end [137.4509]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource DynamicResponse end [137.3708]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource DynamicResponse start [137.2769]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource fireEvent [137.1968]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource setServer [137.0909]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource handleDynamic [136.9989]
[2024-02-24 20:41:23] prod.DEBUG: Time test route [136.4658]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource cleanProviders [135.6339]
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders register 2 end [135.5479]
[2024-02-24 20:41:23] Test time Application register 8 - 135.5319
[2024-02-24 20:41:23] Test time Application register 7 - 135.4358
[2024-02-24 20:41:23] Test time Application register 6 - 135.4189
[2024-02-24 20:41:23] Test time Application register 5 - 135.4029
[2024-02-24 20:41:23] Test time Application register 4 - 135.3619
[2024-02-24 20:41:23] prod.INFO: Time test register commands [135.278]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTCommand [135.1948]
[2024-02-24 20:41:23] prod.INFO: Time test register registerPayloadFactory [135.0989]
[2024-02-24 20:41:23] prod.INFO: Time test register registerClaimFactory [131.3658]
[2024-02-24 20:41:23] prod.INFO: Time test register registerPayloadValidator [131.1929]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTAuth [129.1618]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWT [123.4798]
[2024-02-24 20:41:23] prod.INFO: Time test register registerTokenParser [119.6859]
[2024-02-24 20:41:23] prod.INFO: Time test register registerManager [119.4968]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTBlacklist [112.355]
[2024-02-24 20:41:23] prod.INFO: Time test register registerStorageProvider [101.7389]
[2024-02-24 20:41:23] prod.INFO: Time test register registerAuthProvider [88.7339]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTProvider [29.8479]
[2024-02-24 20:41:23] prod.INFO: Time test register registerAliases [16.1288]
[2024-02-24 20:41:23] prod.INFO: Time test register start [16.0329]
[2024-02-24 20:41:23] Test time Application register 3 - 16.0189
[2024-02-24 20:41:23] Test time Application register 2 - 15.996
[2024-02-24 20:41:23] Test time Application register start - "Tymon\\JWTAuth\\Providers\\LaravelServiceProvider" - 15.013
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders register 2 start [14.9269]
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders class_exists [14.843]
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders provider [14.7519,"Tymon\\JWTAuth\\Providers\\LaravelServiceProvider"]
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders loadedProviders [14.627]
[2024-02-24 20:41:23] prod.INFO: Time test cleanProviders start [1.298]
[2024-02-24 20:41:23] prod.INFO: Time test handleDynamicResource start [1.2138]
[2024-02-24 20:41:23] prod.INFO: Time test onRequest handleStaticResource [1.1098]
[2024-02-24 20:41:23] prod.INFO: Time test onRequest fireEvent [1.0278]
[2024-02-24 20:41:23] prod.INFO: Time test onRequest bindRequest [0.9189]
[2024-02-24 20:41:23] prod.INFO: Time test onRequest convertRequest [0.8218]
[2024-02-24 20:41:23] prod.INFO: Time test onRequest [0.0088]

The part where repeated register is performed

[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTCommand [135.1948]
[2024-02-24 20:41:23] prod.INFO: Time test register registerPayloadFactory [135.0989]
[2024-02-24 20:41:23] prod.INFO: Time test register registerClaimFactory [131.3658]
[2024-02-24 20:41:23] prod.INFO: Time test register registerPayloadValidator [131.1929]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTAuth [129.1618]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWT [123.4798]
[2024-02-24 20:41:23] prod.INFO: Time test register registerTokenParser [119.6859]
[2024-02-24 20:41:23] prod.INFO: Time test register registerManager [119.4968]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTBlacklist [112.355]
[2024-02-24 20:41:23] prod.INFO: Time test register registerStorageProvider [101.7389]
[2024-02-24 20:41:23] prod.INFO: Time test register registerAuthProvider [88.7339]
[2024-02-24 20:41:23] prod.INFO: Time test register registerJWTProvider [29.8479]
[2024-02-24 20:41:23] prod.INFO: Time test register registerAliases [16.1288]

Tell me in which direction to move? How do I avoid re-registration? What could I be doing wrong?

DevilSerj commented 7 months ago

I had minimal success by overwriting Tymon\JWTAuth\Providers\LaravelServiceProvider I created a new CustomJwtServiceProvider and used there only what is needed so that the user is not transferred between requests

use Tymon\JWTAuth\Providers\AbstractServiceProvider;

class CustomJwtServiceProvider extends AbstractServiceProvider
{
    public function boot()
    {
        $this->aliasMiddleware();

        $this->extendAuthGuard();
    }

    public function register()
    {
        $this->registerAuthProvider();
    }

    protected function registerStorageProvider()
    {
        $this->app->singleton('tymon.jwt.provider.storage', function () {
            $instance = $this->getConfigInstance('providers.storage');

            if (method_exists($instance, 'setLaravelVersion')) {
                $instance->setLaravelVersion($this->app->version());
            }

            return $instance;
        });
    }

    protected function aliasMiddleware()
    {
        $router = $this->app['router'];

        $method = method_exists($router, 'aliasMiddleware') ? 'aliasMiddleware' : 'middleware';

        foreach ($this->middlewareAliases as $alias => $middleware) {
            $router->$method($alias, $middleware);
        }
    }
}

And I use it now

'register_providers' => [
     App\Providers\CustomJwtServiceProvider::class,
],

'providers' => [
      ...
      App\Providers\CustomJwtServiceProvider::class
]

It seems to work well for me. Now not so much time is spent on re-registration of the provider and the time does not increase. Friends, please analyze what I wrote and tell me if this is a normal approach?