Slim 4 can be slowed down by Monolog

Currently I’m upgrading an application from Slim3 to Slim4.
With Slim3 I injected the container into all of my controllers, where with Slim4 I redesigned everything to dependency injection. The app runs now partly with Slim4 and I noticed, that the same site has significant longer loading time in Slim4 than in Slim3. For example 3.5s instead of less than 1s (according to chrome dev tools).
After some research I realized, that the instantiation of Monolog caused the long loading time. I use Monolog to write to a log file and also to send an email with the error to the admin. In Slim3 I registered the logger in the container.

//Slim Error abfangen
$container['errorHandler'] = function ($c) {
    return function ($request, $response, $error) use ($c) {
      $c->logger->error($error->getMessage(), ['Seite' => $request->getUri()->getScheme() . '://' . $request->getUri()->getHost() . $request->getUri()->getPath()]);

      return $c->view->render($response->withStatus(500), 'error.twig');
    };
};

//PHP Error abfangen
$container['phpErrorHandler'] = function ($c) {
      return $c->errorHandler;
};

//404 notFoundHandler überschreiben mit eigener Seite
$container['notFoundHandler'] = function ($c) {
  return function ($request, $response) use ($c) {
    return $c->view->render($response->withStatus(404), '404.twig');
  };
};

//405 notAllowedHandler überschreiben mit eigener Seite
$container['notAllowedHandler'] = function ($c) {
  return function ($request, $response) use ($c) {
    return $response->withRedirect($c->router->pathFor('home'));
  };
};

In Slim3 the error handler and so also Monolog were only instantiated in case of an error.

     if ($this->container->has($handler)) {
            $callable = $this->container->get($handler);
            // Call the registered handler
            return call_user_func_array($callable, $params);
        }

The Problem in Slim4 is, that if I inject the logger into the error handler, Monolog is instantiated on every request.
So I had a look at slim4-skeleton and at Daniels Blog Post about monolog.
In slim4-skeleton I just called the index page and had in my test environment a loading time of 1.3s. If I didn’t load the ErrorMiddleware, I had a loading time of about 0.5s. I had the same result if I just didn’t load the logger (commented out in DefaultErrorHandler and in container.php).

So I searched for a solution to only instantiate Monolog if an error occurs. I made a LoggerFactory as suggested by Daniel (@odan) . Then I inject this LoggerFactory in my ErrorHandler, but don’t call the createInstance() function in the constructor. So Monolog isn’t loaded. I call $this->loggerFactory->createInstance() in the logError() function, so it’s only called in case if really something has to be logged.

<?php

namespace App\Handlers;

use Psr\Http\Message\ResponseInterface;
use Slim\Exception\HttpBadRequestException;
use Slim\Exception\HttpException;
use Slim\Exception\HttpForbiddenException;
use Slim\Exception\HttpMethodNotAllowedException;
use Slim\Exception\HttpNotFoundException;
use Slim\Exception\HttpNotImplementedException;
use Slim\Exception\HttpUnauthorizedException;
use Slim\Handlers\ErrorHandler;
use Exception;
use Psr\Http\Message\ResponseFactoryInterface;
use Slim\Interfaces\CallableResolverInterface;
use Slim\Views\Twig;
use Throwable;
use App\Factory\LoggerFactory;

class HttpErrorHandler extends ErrorHandler
{
    public const BAD_REQUEST = 'BAD_REQUEST';
    public const INSUFFICIENT_PRIVILEGES = 'INSUFFICIENT_PRIVILEGES';
    public const NOT_ALLOWED = 'NOT_ALLOWED';
    public const NOT_IMPLEMENTED = 'NOT_IMPLEMENTED';
    public const RESOURCE_NOT_FOUND = 'RESOURCE_NOT_FOUND';
    public const SERVER_ERROR = 'SERVER_ERROR';
    public const UNAUTHENTICATED = 'UNAUTHENTICATED';

    protected $view;
    protected $loggerFactory;

    public function __construct(Twig $view,
        CallableResolverInterface $callableResolver,
        ResponseFactoryInterface $responseFactory,
        LoggerFactory $loggerFactory)
    {
        parent::__construct($callableResolver, $responseFactory);
        $this->view = $view;
        $this->loggerFactory = $loggerFactory;
    }

    protected function respond(): ResponseInterface
    {
        $exception = $this->exception;
        $statusCode = 500;
        $type = self::SERVER_ERROR;
        $description = 'An internal error has occurred while processing your request.';

        if ($exception instanceof HttpException) {
            $statusCode = $exception->getCode();
            $description = $exception->getMessage();

            if ($exception instanceof HttpNotFoundException) {
                $type = self::RESOURCE_NOT_FOUND;
            } elseif ($exception instanceof HttpMethodNotAllowedException) {
                $type = self::NOT_ALLOWED;
            } elseif ($exception instanceof HttpUnauthorizedException) {
                $type = self::UNAUTHENTICATED;
            } elseif ($exception instanceof HttpForbiddenException) {
                $type = self::UNAUTHENTICATED;
            } elseif ($exception instanceof HttpBadRequestException) {
                $type = self::BAD_REQUEST;
            } elseif ($exception instanceof HttpNotImplementedException) {
                $type = self::NOT_IMPLEMENTED;
            }
        }

        if (
            !($exception instanceof HttpException)
            && ($exception instanceof Exception || $exception instanceof Throwable)
            && $this->displayErrorDetails
        ) {
            $description = $exception->getMessage();
        }

        $error = [
            'statusCode' => $statusCode,
            'error' => [
                'type' => $type,
                'description' => $description,
            ],
        ];

        if($statusCode < 500){
             $payload =  $this->view->fetch('404.twig');
        } else {
            $payload =  $this->view->fetch('error.twig');
        }
        
        $response = $this->responseFactory->createResponse($statusCode);
        $response->getBody()->write($payload);
        
        return $response;
    }

    protected function writeToErrorLog(): void
    {
        $renderer = $this->callableResolver->resolve($this->logErrorRenderer);
        $error = $renderer($this->exception, $this->logErrorDetails);
        if (!$this->displayErrorDetails) {
            $error .= "\nTips: To display error details in HTTP response ";
            $error .= 'set "displayErrorDetails" to true in the ErrorHandler constructor.';
        }
        $this->logError($error);
    }

    protected function logError(string $error): void
    {
        $this->logger = $this->loggerFactory->createInstance();
        $this->logger->error($error, ['Seite' => $this->request->getUri()->getScheme() . '://' . $this->request->getUri()->getHost() . $this->request->getUri()->getPath()]);
    }
}

This seems to work and I have loading times comparable to Slim3 in my Application.

What do you think about this? Have you better or nicer ideas how to handle this?

1 Like

@philipp thank you for sharing. Yet another reason why I stuck with Slim3 instead of the container injection of Slim4. Your solution looks good, but I have not tried it. BTW, nice job using “use” on the closure, its something I’ve never used before.

I have made some performance tests with Apache ab, with and without the LoggerFactory.
The measurement shows that there is really no difference.

Results without the LoggerFactory:

Requests per second:    100.70 [#/sec] (mean)
Time per request:       993.002 [ms] (mean)
Time per request:       9.930 [ms] (mean, across all concurrent requests)
Transfer rate:          21.14 [Kbytes/sec] received

Results with the LoggerFactory:

Requests per second:    100.89 [#/sec] (mean)
Time per request:       991.198 [ms] (mean)
Time per request:       9.912 [ms] (mean, across all concurrent requests)
Transfer rate:          21.18 [Kbytes/sec] received

Fun fact, sometimes it’s even faster.

As a tip, try to use the Xdebug profiler (integrated in PhpStorm) to see where it’s really slow.

I’m not sure if this line will work, because you don’t add any file or console logger:

$this->logger = $this->loggerFactory->createInstance();

Also from the performance point of view, it would make more sense to create the logger instance only once. You can try to add at least one file logger, otherwise Monolog might trigger some errors:

private LoggerInterface $logger;

public function __construct(LoggerFactory $loggerFactory)
{
    $this->logger = $loggerFactory
        ->addFileHandler('error.log')
        ->createLogger();
}

Hi @odan

Thanks a lot for your reply and for your tests!

I don’t know why, but I get still different results, also if I test with Apache ab.
Important to say, that I realized, that I have an older version of slim4-skeleton in my test environment. I don’t know exactly when I downloaded it.
My test environment runs on Windows 10 with Wamp Server installed. Perhaps this has also an effect on my measurements.

I tested slim4-skeleton in the state, how I downloaded it. So in container.php I had

ErrorMiddleware::class => function (ContainerInterface $container) {
        $config = $container->get('settings')['error'];
        $app = $container->get(App::class);

        $logger = $container->get(LoggerFactory::class)
            ->addFileHandler('error.log')
            ->createInstance('default_error_handler');

        $errorMiddleware = new ErrorMiddleware(
            $app->getCallableResolver(),
            $app->getResponseFactory(),
            (bool)$config['display_error_details'],
            (bool)$config['log_errors'],
            (bool)$config['log_error_details'],
            //$logger
        );

        $errorMiddleware->setDefaultErrorHandler($container->get(DefaultErrorHandler::class));

        return $errorMiddleware;
    },

and in DefaultErrorHandler.php

public function __construct(
        Twig $twig,
        ResponseFactoryInterface $responseFactory,
        LoggerFactory $loggerFactory
    ) {
        $this->twig = $twig;
        $this->responseFactory = $responseFactory;
        $this->loggerFactory = $loggerFactory
            ->addFileHandler('error.log')
            ->createInstance('error');
    }


 public function __invoke(
        ServerRequestInterface $request,
        Throwable $exception,
        bool $displayErrorDetails,
        bool $logErrors
    ): ResponseInterface {
        // Log error
        if ($logErrors) {
            $this->logger->error(sprintf(
                'Error: [%s] %s, Method: %s, Path: %s',
                $exception->getCode(),
                ExceptionDetail::getExceptionText($exception),
                $request->getMethod(),
                $request->getUri()->getPath()
            ));
        }

Like this the ab-test gave me

K:\wamp64\bin\apache\apache2.4.46\bin>ab -n 1 -k http://slim4-skeleton.test/
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking slim4-skeleton.test (be patient).....done


Server Software:        Apache/2.4.46
Server Hostname:        slim4-skeleton.test
Server Port:            80

Document Path:          /
Document Length:        1131 bytes

Concurrency Level:      1
Time taken for tests:   0.845 seconds
Complete requests:      1
Failed requests:        0
Keep-Alive requests:    1
Total transferred:      1478 bytes
HTML transferred:       1131 bytes
Requests per second:    1.18 [#/sec] (mean)
Time per request:       845.039 [ms] (mean)
Time per request:       845.039 [ms] (mean, across all concurrent requests)
Transfer rate:          1.71 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   845  845   0.0    845     845
Waiting:      845  845   0.0    845     845
Total:        845  845   0.0    845     845

And in Chrome Dev Tools I got this

Then I tried it without Logger. Therefore I changed the code in container.php to this

ErrorMiddleware::class => function (ContainerInterface $container) {
        $config = $container->get('settings')['error'];
        $app = $container->get(App::class);

        // $logger = $container->get(LoggerFactory::class)
        //     ->addFileHandler('error.log')
        //     ->createInstance('default_error_handler');

        $errorMiddleware = new ErrorMiddleware(
            $app->getCallableResolver(),
            $app->getResponseFactory(),
            (bool)$config['display_error_details'],
            (bool)$config['log_errors'],
            (bool)$config['log_error_details'],
            //$logger
        );

        $errorMiddleware->setDefaultErrorHandler($container->get(DefaultErrorHandler::class));

        return $errorMiddleware;
    },

and DefaultErrorHandler.php to this

public function __construct(
        Twig $twig,
        ResponseFactoryInterface $responseFactory,
        LoggerFactory $loggerFactory
    ) {
        $this->twig = $twig;
        $this->responseFactory = $responseFactory;
        $this->loggerFactory = $loggerFactory;
            // ->addFileHandler('error.log')
            // ->createInstance('error');
    }


public function __invoke(
        ServerRequestInterface $request,
        Throwable $exception,
        bool $displayErrorDetails,
        bool $logErrors
    ): ResponseInterface {
        // Log error
        if ($logErrors) {
            $this->logger = $this->loggerFactory->addFileHandler('error.log')->createInstance('error');
            $this->logger->error(sprintf(
                'Error: [%s] %s, Method: %s, Path: %s',
                $exception->getCode(),
                ExceptionDetail::getExceptionText($exception),
                $request->getMethod(),
                $request->getUri()->getPath()
            ));
        }

The results with Apache ab

K:\wamp64\bin\apache\apache2.4.46\bin>ab -n 1 -k http://slim4-skeleton.test/
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking slim4-skeleton.test (be patient).....done


Server Software:        Apache/2.4.46
Server Hostname:        slim4-skeleton.test
Server Port:            80

Document Path:          /
Document Length:        1131 bytes

Concurrency Level:      1
Time taken for tests:   0.450 seconds
Complete requests:      1
Failed requests:        0
Keep-Alive requests:    1
Total transferred:      1478 bytes
HTML transferred:       1131 bytes
Requests per second:    2.22 [#/sec] (mean)
Time per request:       450.475 [ms] (mean)
Time per request:       450.475 [ms] (mean, across all concurrent requests)
Transfer rate:          3.20 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   450  450   0.0    450     450
Waiting:      450  450   0.0    450     450
Total:        450  450   0.0    450     450

and what Chrome Dev Tools gave me

How I wrote, I’m not sure if there is a problem with my test environment or if I have another error somewhere which causes these different results.

Because of the instantiation of the logger how I did it I have to mention, that I changed the createInstance() method to this

 public function createInstance(): LoggerInterface
    {
        $logger = new Logger('logger');
        $streamhandler = new StreamHandler(__DIR__ . '/../../log/error.log', Logger::DEBUG);
        $fingersCrossed = new FingersCrossedHandler($streamhandler, Logger::DEBUG);
        $logger->pushHandler($fingersCrossed);

        $transporter = new Swift_SmtpTransport($this->settings['mailer']['smtp_server'], $this->settings['mailer']['smtp_port']);
        $transporter->setUsername($this->settings['mailer']['username']);
        $transporter->setPassword($this->settings['mailer']['password']);
        $mailer = new Swift_Mailer($transporter);
        $message = new Swift_Message('Fehlermeldung von domain.ch');
        $message->setFrom(['server@domain.ch' => 'domain.ch']);
        $message->setTo(['philipp@domain.ch' => 'philipp']);
        $message->setContentType('text/html');
        $mailerHandler = new SwiftMailerHandler($mailer, $message, Logger::DEBUG);
        $mailerHandler->setFormatter(new HtmlFormatter());
        $logger->pushHandler($mailerHandler);

        return $logger;
    }

This is the code, which I had in the container definition before.
For sure I would like to create only one instance of the logger. Because I only log errors, the logger is only created in case of an error. If there are multiple errors it could happen, that more than one logger is created (once in ErrorHandlerMiddleware which catches php errors and once in HttpErrorHandler which is my default error handler). I have to think about this…

Thanks a lot again and sorry for my huge post
philipp

According to your response time, it looks like that the Xdebug extension is enabled.

For performance testing, you should (temporarily) disable Xdebug, as it slows down each request for at least one second. Open your php.ini, then comment out the zend_extension and restart the webserver.

[XDebug]
;zend_extension=xdebug

I strongly suspect that SwiftMailer is the problem here. The instantiation of Swift_SmtpTransport takes about 1 second even on my computer. I would therefore try to use another mailer component.

Arrrgh…
You’re absolutely right. I have the XDebug helper extension installed in chrome and assumed, that if i set it on “Disable”, what I did for the tests, it wouldn’t have an impact on performance.
But surely it does. If I disable XDebug in the php.ini I get in Apache ab the same “Time taken for tests:” of 0.010 seconds with or without Logger (in slim4-skeleton).
And astonishingly, like you mentioned, in Chrome DevTools the loading time was under 100ms and sometimes even faster with the Logger enabled.

The same in my application. With Xdebug disabled loading times are comparable from Sim3 to Slim4 also if the Logger is instantiated.
SwiftMailer is slow if an error has to be handled, what makes sense because he has to connect to the SMTP-Server. But the instantiation without handling an error seems to be no problem.
I assume, that the instantiation only slows down Xdebug.

Thanks a lot!

1 Like