feature #26833 [HttpKernel] Added support for timings in ArgumentValueResolvers (iltar)

This PR was squashed before being merged into the 4.1-dev branch (closes #26833). Discussion ---------- [HttpKernel] Added support for timings in ArgumentValueResolvers | Q | A | ------------- | --- | Branch? | master | Bug fix? | no | New feature? | yes | BC breaks? | no | Deprecations? | no | Tests pass? | yes | Fixed tickets | ~ | License | MIT | Doc PR | ~ This feature provides timings for the supports and resolve methods for each individual argument value resolver. It was already possible to see the `controller.get_arguments` timing, but it was impossible to track a possible performance issue any further without using different tools. I've explicitly added the `supports` method as well, as it might otherwise hide performance issues. The `ServiceValueResolver` for example, does a `container::has`, which in turn might trigger a factory method, which might trigger a query for example. ~~Due to the feature freeze I've already added this to 4.2. If for some reason it's okay to still merge it into 4.1, I can update the upgrade files.~~ - Changed to 4.1 ##### *Without performance issue* ![image](https://user-images.githubusercontent.com/1754678/38416250-6cf45528-3994-11e8-91d4-2472c97c6c50.png) ##### *With performance issue* ![image](https://user-images.githubusercontent.com/1754678/38416266-7966eb7c-3994-11e8-9dc5-a99daa8f9a69.png) Commits ------- 1c0d8928aa [HttpKernel] Added support for timings in ArgumentValueResolvers
2018-04-20 06:27:48 +02:00 · 2018-04-20 06:27:48 +02:00 · 1b1bbd43a3
commit 1b1bbd43a3
parent 028e1e57f0 1c0d8928aa
5 changed files with 200 additions and 1 deletions
--- a/src/Symfony/Component/HttpKernel/CHANGELOG.md
+++ b/src/Symfony/Component/HttpKernel/CHANGELOG.md
@ -7,6 +7,8 @@ CHANGELOG
 * added orphaned events support to `EventDataCollector`
 * `ExceptionListener` now logs and collects exceptions at priority `2048` (previously logged at `-128` and collected at `0`)
 * Deprecated `service:action` syntax with a single colon to reference controllers. Use `service::method` instead.
+ * Added the ability to profile individual argument value resolvers via the
+   `Symfony\Component\HttpKernel\Controller\ArgumentResolver\TraceableValueResolver`

 4.0.0
 -----
--- a/src/Symfony/Component/HttpKernel/Controller/ArgumentResolver/TraceableValueResolver.php
+++ b/src/Symfony/Component/HttpKernel/Controller/ArgumentResolver/TraceableValueResolver.php
@ -0,0 +1,62 @@
+<?php
+
+/*
+ * This file is part of the Symfony package.
+ *
+ * (c) Fabien Potencier <fabien@symfony.com>
+ *
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Symfony\Component\HttpKernel\Controller\ArgumentResolver;
+
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpKernel\Controller\ArgumentValueResolverInterface;
+use Symfony\Component\HttpKernel\ControllerMetadata\ArgumentMetadata;
+use Symfony\Component\Stopwatch\Stopwatch;
+
+/**
+ * Provides timing information via the stopwatch.
+ *
+ * @author Iltar van der Berg <kjarli@gmail.com>
+ */
+final class TraceableValueResolver implements ArgumentValueResolverInterface
+{
+    private $inner;
+    private $stopwatch;
+
+    public function __construct(ArgumentValueResolverInterface $inner, ?Stopwatch $stopwatch = null)
+    {
+        $this->inner = $inner;
+        $this->stopwatch = $stopwatch ?? new Stopwatch();
+    }
+
+    /**
+     * {@inheritdoc}
+     */
+    public function supports(Request $request, ArgumentMetadata $argument): bool
+    {
+        $method = \get_class($this->inner).'::'.__FUNCTION__;
+        $this->stopwatch->start($method);
+
+        $return = $this->inner->supports($request, $argument);
+
+        $this->stopwatch->stop($method);
+
+        return $return;
+    }
+
+    /**
+     * {@inheritdoc}
+     */
+    public function resolve(Request $request, ArgumentMetadata $argument): iterable
+    {
+        $method = \get_class($this->inner).'::'.__FUNCTION__;
+        $this->stopwatch->start($method);
+
+        yield from $this->inner->resolve($request, $argument);
+
+        $this->stopwatch->stop($method);
+    }
+}
--- a/src/Symfony/Component/HttpKernel/DependencyInjection/ControllerArgumentValueResolverPass.php
+++ b/src/Symfony/Component/HttpKernel/DependencyInjection/ControllerArgumentValueResolverPass.php
@ -15,6 +15,10 @@ use Symfony\Component\DependencyInjection\Argument\IteratorArgument;
 use Symfony\Component\DependencyInjection\Compiler\CompilerPassInterface;
 use Symfony\Component\DependencyInjection\Compiler\PriorityTaggedServiceTrait;
 use Symfony\Component\DependencyInjection\ContainerBuilder;
+use Symfony\Component\DependencyInjection\ContainerInterface;
+use Symfony\Component\DependencyInjection\Reference;
+use Symfony\Component\HttpKernel\Controller\ArgumentResolver\TraceableValueResolver;
+use Symfony\Component\Stopwatch\Stopwatch;

 /**
 * Gathers and configures the argument value resolvers.
@ -40,9 +44,20 @@ class ControllerArgumentValueResolverPass implements CompilerPassInterface
            return;
        }

+        $resolvers = $this->findAndSortTaggedServices($this->argumentValueResolverTag, $container);
+
+        if ($container->getParameter('kernel.debug') && class_exists(Stopwatch::class)) {
+            foreach ($resolvers as $resolverReference) {
+                $id = (string) $resolverReference;
+                $container->register("debug.$id", TraceableValueResolver::class)
+                    ->setDecoratedService($id)
+                    ->setArguments(array(new Reference("debug.$id.inner"), new Reference('debug.stopwatch', ContainerInterface::NULL_ON_INVALID_REFERENCE)));
+            }
+        }
+
        $container
            ->getDefinition($this->argumentResolverService)
-            ->replaceArgument(1, new IteratorArgument($this->findAndSortTaggedServices($this->argumentValueResolverTag, $container)))
+            ->replaceArgument(1, new IteratorArgument($resolvers))
        ;
    }
 }
--- a/src/Symfony/Component/HttpKernel/Tests/Controller/ArgumentResolver/TraceableValueResolverTest.php
+++ b/src/Symfony/Component/HttpKernel/Tests/Controller/ArgumentResolver/TraceableValueResolverTest.php
@ -0,0 +1,76 @@
+<?php
+
+/*
+ * This file is part of the Symfony package.
+ *
+ * (c) Fabien Potencier <fabien@symfony.com>
+ *
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Symfony\Component\HttpKernel\Tests\Controller\ArgumentResolver;
+
+use PHPUnit\Framework\TestCase;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpKernel\Controller\ArgumentResolver\TraceableValueResolver;
+use Symfony\Component\HttpKernel\Controller\ArgumentValueResolverInterface;
+use Symfony\Component\HttpKernel\ControllerMetadata\ArgumentMetadata;
+use Symfony\Component\Stopwatch\Stopwatch;
+
+class TraceableValueResolverTest extends TestCase
+{
+    public function testTimingsInSupports()
+    {
+        $stopwatch = new Stopwatch();
+        $resolver = new TraceableValueResolver(new ResolverStub(), $stopwatch);
+        $argument = new ArgumentMetadata('dummy', 'string', false, false, null);
+        $request = new Request();
+
+        $this->assertTrue($resolver->supports($request, $argument));
+
+        $event = $stopwatch->getEvent(ResolverStub::class.'::supports');
+        $this->assertCount(1, $event->getPeriods());
+    }
+
+    public function testTimingsInResolve()
+    {
+        $stopwatch = new Stopwatch();
+        $resolver = new TraceableValueResolver(new ResolverStub(), $stopwatch);
+        $argument = new ArgumentMetadata('dummy', 'string', false, false, null);
+        $request = new Request();
+
+        $iterable = $resolver->resolve($request, $argument);
+
+        foreach ($iterable as $index => $resolved) {
+            $event = $stopwatch->getEvent(ResolverStub::class.'::resolve');
+            $this->assertTrue($event->isStarted());
+            $this->assertEmpty($event->getPeriods());
+            switch ($index) {
+                case 0:
+                    $this->assertEquals('first', $resolved);
+                    break;
+                case 1:
+                    $this->assertEquals('second', $resolved);
+                    break;
+            }
+        }
+
+        $event = $stopwatch->getEvent(ResolverStub::class.'::resolve');
+        $this->assertCount(1, $event->getPeriods());
+    }
+}
+
+class ResolverStub implements ArgumentValueResolverInterface
+{
+    public function supports(Request $request, ArgumentMetadata $argument)
+    {
+        return true;
+    }
+
+    public function resolve(Request $request, ArgumentMetadata $argument)
+    {
+        yield 'first';
+        yield 'second';
+    }
+}
--- a/src/Symfony/Component/HttpKernel/Tests/DependencyInjection/ControllerArgumentValueResolverPassTest.php
+++ b/src/Symfony/Component/HttpKernel/Tests/DependencyInjection/ControllerArgumentValueResolverPassTest.php
@ -42,8 +42,50 @@ class ControllerArgumentValueResolverPassTest extends TestCase
            $container->register($id)->addTag('controller.argument_value_resolver', $tag);
        }

+        $container->setParameter('kernel.debug', false);
+
        (new ControllerArgumentValueResolverPass())->process($container);
        $this->assertEquals($expected, $definition->getArgument(1)->getValues());
+
+        $this->assertFalse($container->hasDefinition('n1.traceable'));
+        $this->assertFalse($container->hasDefinition('n2.traceable'));
+        $this->assertFalse($container->hasDefinition('n3.traceable'));
+    }
+
+    public function testInDebug()
+    {
+        $services = array(
+            'n3' => array(array()),
+            'n1' => array(array('priority' => 200)),
+            'n2' => array(array('priority' => 100)),
+        );
+
+        $expected = array(
+            new Reference('n1'),
+            new Reference('n2'),
+            new Reference('n3'),
+        );
+
+        $definition = new Definition(ArgumentResolver::class, array(null, array()));
+        $container = new ContainerBuilder();
+        $container->setDefinition('argument_resolver', $definition);
+
+        foreach ($services as $id => list($tag)) {
+            $container->register($id)->addTag('controller.argument_value_resolver', $tag);
+        }
+
+        $container->setParameter('kernel.debug', true);
+
+        (new ControllerArgumentValueResolverPass())->process($container);
+        $this->assertEquals($expected, $definition->getArgument(1)->getValues());
+
+        $this->assertTrue($container->hasDefinition('debug.n1'));
+        $this->assertTrue($container->hasDefinition('debug.n2'));
+        $this->assertTrue($container->hasDefinition('debug.n3'));
+
+        $this->assertTrue($container->hasDefinition('n1'));
+        $this->assertTrue($container->hasDefinition('n2'));
+        $this->assertTrue($container->hasDefinition('n3'));
    }

    public function testReturningEmptyArrayWhenNoService()
@ -52,6 +94,8 @@ class ControllerArgumentValueResolverPassTest extends TestCase
        $container = new ContainerBuilder();
        $container->setDefinition('argument_resolver', $definition);

+        $container->setParameter('kernel.debug', false);
+
        (new ControllerArgumentValueResolverPass())->process($container);
        $this->assertEquals(array(), $definition->getArgument(1)->getValues());
    }