Friday, March 04, 2016

Save Symfony's Stopwatch data to log — Aleksander Cyrkulewski — To Get You Started

Save Symfony's Stopwatch data to log — Aleksander Cyrkulewski — To Get You Started

In one of our services we use a lot of API calls. At certain point I realised the need of speed-tracking for those API calls. On the dev environment it's pretty easy to do with @debug.stopwatch. But I wanted to measure the speed on production and save data to log file. To solve it I wrapped original stopwatch service with logger functionality. It's pretty much of configuration + small service class. I also have done it in the way when I can turn service on/off via configuration parameter stopwatch_enable: true or stopwatch_enable: false
As a result log file (the name could be, you can specify any name you want inconfig_{env}.yml) will contain entries like following
[2014-11-26 18:56:53] api.DEBUG: API_getSomething, 1938 {"extraParamIfNeeded":"value"}
So, lets start with adding the parameter to environment we want to have stopwatch enabled:app/config/parameters_prod.yml.
stopwatch_enable: true
Next is service by self. Simple class, dependent on:
  1. Symfony Stopwatch,
  2. Logger,
  3. turn on/off parameter.
 * Wrapper for basic Symfony's Stopwatch service
 * It add logging functionality for basic one
namespace CompanyName\CompanyBundle\Service;

use Symfony\Component\HttpKernel\Log\LoggerInterface;
use Symfony\Component\Stopwatch\Stopwatch;
use Symfony\Component\Stopwatch\StopwatchEvent;

class StopwatchService
     * @var Stopwatch
    private $stopwatch;

     * @var LoggerInterface
    private $logger;

     * @var bool
    private $stopwatchEnabled;

     * @param Stopwatch $stopwatch
     * @param LoggerInterface $logger
     * @param bool $stopwatchEnabled
    public function __construct(
        Stopwatch $stopwatch, 
        LoggerInterface $logger, 
        $stopwatchEnabled = false
    ) {
        $this->stopwatch = $stopwatch;
        $this->logger = $logger;
        $this->stopwatchEnabled = $stopwatchEnabled;

     * @see Stopwatch::start
     * @param string $eventName
     * @return false|StopwatchEvent
    public function start($eventName)
        return ($this->stopwatchEnabled) ? $this->stopwatch->start($eventName) : false;

     * @see Stopwatch::stop
     * @param string $eventName
     * @param array $extraParams
     * @return false|StopwatchEvent
    public function stop($eventName, array $extraParams = array())
        if (! $this->stopwatchEnabled) {
            return false;
        $event = $this->stopwatch->stop($eventName);
        $this->logEvent($event, $eventName, $extraParams);
        return $event;

     * Save event data to the log
     * @param StopwatchEvent $event
     * @param string $eventName
     * @param array $params
    private function logEvent(StopwatchEvent $event, $eventName, array $params)
        $this->logger->debug($eventName . ', ' . $event->getDuration(), $params);
Now we need to specify StopwatchService in service config
    class: Symfony\Component\Stopwatch\Stopwatch

    class: CompanyName\CompanyBundle\Service\StopwatchService
    arguments: [ @symfony.stopwatch.service, @logger, %stopwatch_enable% ]
        - { name: monolog.logger, channel: api }
And configure new logger. You need to do this in config_{env}.yml file.
    type:         fingers_crossed
    action_level: error
    handler:      nested
    channels:     [!api]
    type: stream
    path: %kernel.logs_dir%/
    level: debug
    channels: [api]
And finally call the service from the place where you want to measure execution time. Here I give the example of how to call stopwatch in controller. In real life you probably make an API calls from withing other services or models. In this case you need to inject stopwatch service to your model.
$stopwatch = $this->container->get('api.stopwatch'); 

// ... API call or some other code you need to measure ...

$stopwatch->stop('API_getSomething', array('extraParamIfNeeded' => 'value'));

No comments: