inanzzz | Calculation the response time of a request with an event listener in Symfony

User sends a request to your application and your application responds to it. This is the classic flow but how long does whole process take? If you want to find out, you can use example below.

AuditControllerInterface

declare(strict_types=1);

namespace AppBundle\Controller;

interface AuditControllerInterface
{
}

DefaultController

declare(strict_types=1);

namespace AppBundle\Controller;

use Sensio\Bundle\FrameworkExtraBundle\Configuration\Method;
use Symfony\Component\HttpFoundation\Response;

class DefaultController implements AuditControllerInterface
{
    /**
     * @Method({"GET"})
     * @Route("")
     */
    public function indexAction(): Response
    {
        sleep(2);

        $template = $this->templating->render('AppBundle:default:index.html.twig', []);

        return (new Response())->setContent($template);
    }
}

KernelResponseListener

declare(strict_types=1);

namespace AppBundle\Event\Listener;

use AppBundle\Controller\AuditControllerInterface;
use Symfony\Component\HttpKernel\Controller\ControllerResolver;
use Symfony\Component\HttpKernel\Event\FilterResponseEvent;

class KernelResponseListener
{
    private $controllerResolver;

    public function __construct(ControllerResolver $controllerResolver)
    {
        $this->controllerResolver = $controllerResolver;
    }

    public function onKernelResponse(FilterResponseEvent $event)
    {
        if ($event->isMasterRequest()) {
            $request = $event->getRequest();

            $controllers = $this->controllerResolver->getController($request);
            if ($controllers[0] instanceof AuditControllerInterface) {
                $this->audit($request->server->get('REQUEST_TIME_FLOAT'), microtime(true));
            }
        }
    }

    private function audit(float $reqTime, float $resTime): void
    {
        $reqMilliSecond = (int) ($reqTime * 1000);
        $resMilliSecond = (int) ($resTime * 1000);
        $reqMicroSecond = (int) ($reqTime * 1000000);
        $resMicroSecond = (int) ($resTime * 1000000);

        $audit = [
            'milliseconds' => [
                'req' => $reqMilliSecond,
                'res' => $resMilliSecond,
                'elapsed' => $resMilliSecond - $reqMilliSecond,
            ],
            'microseconds' => [
                'req' => $reqMicroSecond,
                'res' => $resMicroSecond,
                'elapsed' => $resMicroSecond - $reqMicroSecond,
            ]
        ];

        print_r($audit);
    }
}

services:
    AppBundle\Event\Listener\KernelResponseListener:
        arguments:
            - '@debug.controller_resolver.inner'
        tags:
            - { name: kernel.event_listener, event: kernel.response, method: onKernelResponse }

Test

If you go to http://symfony.dev/app_dev.php/ you will see result below. The time shown at the bottom of the page within the Symfony's profiler uses "millisecond" so your milliseconds->elapsed (2565) would be very close to it.

Array
(
    [milliseconds] => Array
        (
            [req] => 1523099189672
            [res] => 1523099192237
            [elapsed] => 2565
        )

    [microseconds] => Array
        (
            [req] => 1523099189672000
            [res] => 1523099192237378
            [elapsed] => 2565378
        )

)