Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Response time increases possible memory leaks #468

Open
DevilSerj opened this issue Feb 24, 2024 · 2 comments
Open

Response time increases possible memory leaks #468

DevilSerj opened this issue Feb 24, 2024 · 2 comments
Assignees
@hhxsv5
Labels
analyzing Analyzing this issue

Comments

@DevilSerj
Copy link

DevilSerj commented Feb 24, 2024 •
edited

  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 DevilSerj added the analyzing Analyzing this issue label Feb 24, 2024
@DevilSerj
Copy link
Author

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
Copy link
Author

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@hhxsv5 hhxsv5

Labels
analyzing Analyzing this issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@hhxsv5 @DevilSerj