artprima / prometheus-metrics-bundle

Symfony 5/6 Prometheus Metrics Bundle
MIT License
129 stars 29 forks source link

RequestCounter: raise priority to trigger earlier #18

Closed luca-nardelli closed 4 years ago

luca-nardelli commented 4 years ago

Hi again,

I've noticed that the RequestCounterListener has a default priority of 0 for the kernel.request handler. As an example, this is the number of listeners for my application that uses Api Platform.

 ------- ---------------------------------------------------------------------------------------------- ---------- 
  Order   Callable                                                                                       Priority  
 ------- ---------------------------------------------------------------------------------------------- ---------- 
  #1      Symfony\Component\HttpKernel\EventListener\DebugHandlersListener::configure()                  2048      
  #2      Symfony\Component\HttpKernel\EventListener\ValidateRequestListener::onKernelRequest()          256       
  #3      Nelmio\CorsBundle\EventListener\CorsListener::onKernelRequest()                                250       
  #4      Symfony\Component\HttpKernel\EventListener\SessionListener::onKernelRequest()                  128       
  #5      Symfony\Component\HttpKernel\EventListener\LocaleListener::setDefaultLocale()                  100       
  #6      App\EventSubscriber\ContextSubscriber::initializeContext()                             90        
  #7      Symfony\Component\HttpKernel\EventListener\RouterListener::onKernelRequest()                   32        
  #8      ApiPlatform\Core\Filter\QueryParameterValidateListener::onKernelRequest()                      16        
  #9      Symfony\Component\HttpKernel\EventListener\LocaleListener::onKernelRequest()                   16        
  #10     Symfony\Component\HttpKernel\EventListener\LocaleAwareListener::onKernelRequest()              15        
  #11     Symfony\Bundle\SecurityBundle\Debug\TraceableFirewallListener::configureLogoutUrlGenerator()   8         
  #12     Symfony\Bundle\SecurityBundle\Debug\TraceableFirewallListener::onKernelRequest()               8         
  #13     ApiPlatform\Core\EventListener\AddFormatListener::onKernelRequest()                            7         
  #14     App\EventSubscriber\CacheEventSubscriber::preRead()                                            5         
  #15     App\EventSubscriber\MainEventSubscriber::preRead()                                             5         
  #16     ApiPlatform\Core\EventListener\ReadListener::onKernelRequest()                                 4         
  #17     ApiPlatform\Core\Security\EventListener\DenyAccessListener::onSecurity()                       3         
  #18     App\EventSubscriber\MainEventSubscriber::postRead()                                            3         
  #19     ApiPlatform\Core\EventListener\DeserializeListener::onKernelRequest()                          2         
  #20     ApiPlatform\Core\Security\EventListener\DenyAccessListener::onSecurityPostDenormalize()        1         
  #21     ApiPlatform\Core\Bridge\Symfony\Bundle\EventListener\SwaggerUiListener::onKernelRequest()      0         
  #22     Artprima\PrometheusMetricsBundle\EventListener\RequestCounterListener::onKernelRequest()       0         
 ------- ---------------------------------------------------------------------------------------------- ---------- 

 ------- ---------------------------------------------------------------------------------------------- ---------- 

As you can see, there is quite a lot going on even before the stopwatch is started (this now happens because the stopwatch is not started in the init method as per my previous PR). Because of this, the time measurement is not as accurate as it could be. Moreover, in my specific case I was also losing some timing of requests because one of my listeners set the response at this stage (from a cache).

Thus, I suggest raising the priority of the handler to 1024 so that it is basically fired as the first event (apart from the debug ones).

luca-nardelli commented 4 years ago

Actually, now that I think about it, raising the priority this much would make the listener run before the route name is event determined, giving an incomplete request object to the MetricsGenerators.

What do you think about moving the stopwatch initialization to a different, dedicated, event listener with a higher priority?

EDIT: Instead of moving only this to a higher priority listener, we could add a handler to the RequestCounter with priority 1024 and a new optional method collectStart to the MetricsGenerator which is called at the beginning of the metrics collection (i.e. when all the other listeners have not fired yet)

luca-nardelli commented 4 years ago

I've edited the PR with the proposed collectStart additional method and a new listener that calls it at the beginning of the kernel.request series of events