feature #47416 [Console][FrameworkBundle][HttpKernel][WebProfilerBundle] Enable profiling commands (HeahDude)

nicolas-grekas · nicolas-grekas · commit 11de26ca18d1 · 2023-10-17T15:25:58.000+02:00
This PR was merged into the 6.4 branch. Discussion ---------- [Console][FrameworkBundle][HttpKernel][WebProfilerBundle] Enable profiling commands | Q | A | ------------- | --- | Branch? | 6.4 | Bug fix? | no | New feature? | yes | Deprecations? | no | Tickets | Fix #45241 | License | MIT | Doc PR | ~ TLDR; I've shown a POC of this feature at the Symfony Live Paris last April to some of the core team members (ping `@nicolas`-grekas, `@stof`, `@lyrixx`, `@chalasr`, `@GromNaN`). I propose here a new work from scratch addressing the comments I already got and based on Javier's profiler redesign (#47148). Reviews should better be done by commits. Summary --------- This PR aims to leverage the profiler and its collectors by using a `VirtualRequestStack` to aggregate data on virtual requests. Such requests are obfuscated by default to avoid side effects. It can feel like a hack... or a pragmatic way to get, without much complexity, tons of useful feedback on what's going on during console execution, from basic info about the command, time/memory metrics, to every existing features already available in HTTP context: events, message dispatching, http requests, emails, serialization, validation, cache, database queries... and so on, all that just out of the box! Previous work -------------- There were some work to extract the Profiler logic in a dedicated component, that proved to require a lot of complexity and BC breaks in the API: * #10374 * #14809 (see symfony/symfony#14809 (comment)) * #20502 Screenshots ------------ For now I've focused only on the functional parts. <details><summary>Search view</summary> <img width="1221" alt="Screenshot 2022-08-28 at 11 29 25 PM" src="https://user-images.githubusercontent.com/10107633/187095381-851f6be5-cf8c-4fec-aa7b-9f9f80bf8404.png"> </details> <details><summary>Command panel</summary> <img width="1210" alt="Screenshot 2022-08-28 at 11 30 54 PM" src="https://user-images.githubusercontent.com/10107633/187095971-de8f9b85-eeb4-48cf-aff7-fdac0c6f9264.png"> <img width="974" alt="Screenshot 2022-08-28 at 11 31 08 PM" src="https://user-images.githubusercontent.com/10107633/187095980-337f4373-ebe5-4de5-bfb4-3715be868274.png"> <img width="962" alt="Screenshot 2022-08-28 at 11 31 21 PM" src="https://user-images.githubusercontent.com/10107633/187096022-ab18f70a-704a-4c75-81a6-43ca5b66eb9a.png"> <img width="964" alt="Screenshot 2022-08-28 at 11 31 34 PM" src="https://user-images.githubusercontent.com/10107633/187096037-cc45805e-ba65-447f-bca6-2d2ea38239b8.png"> If the command is signal-able the following panel will be available: <img width="961" alt="Screenshot 2022-08-28 at 11 31 46 PM" src="https://user-images.githubusercontent.com/10107633/187096084-2f6a39be-a780-411b-9000-b9ae3407e82b.png"> If sub commands are run using `$this->getApplication()->run()` sub profiles will be shown as for requests: <img width="696" alt="Screenshot 2022-08-28 at 11 31 56 PM" src="https://user-images.githubusercontent.com/10107633/187096105-bb7e4a84-42bc-47ed-9f58-527a771c48cc.png"> </details> The server tab is the same as in the request panel. <details><summary>Performance panel</summary> <img width="977" alt="Screenshot 2022-08-28 at 11 32 23 PM" src="https://user-images.githubusercontent.com/10107633/187096138-3ff3f347-61c7-4ade-8c73-b48d5b504c04.png"> <img width="969" alt="Screenshot 2022-08-28 at 11 32 32 PM" src="https://user-images.githubusercontent.com/10107633/187096168-35be4773-4941-4e5e-8dd4-f6cc009e5d48.png"> </details> <details> <summary>Failing command</summary> The exception panel is shown by default as for requests: <img width="1217" alt="Screenshot 2022-08-28 at 11 33 42 PM" src="https://user-images.githubusercontent.com/10107633/187096210-7b206c72-c2e4-4eb3-9978-916cd3dd6cd6.png"> </details> <details> <summary>Sub command</summary> <img width="1217" alt="Screenshot 2022-08-28 at 11 33 19 PM" src="https://user-images.githubusercontent.com/10107633/187096188-a090fb91-b7b8-4f98-a1d7-99b3605bf48b.png"> </details> <details> <summary>Profile token when verbose</summary> (clickable links with compatible terminals) <img width="534" alt="Screenshot 2022-08-28 at 11 26 51 PM" src="https://user-images.githubusercontent.com/10107633/187096349-8f7619b2-feb4-427c-a315-f4a844536316.png"> </details> <details> <summary>Command interrupted by signal</summary> <img width="1246" alt="Screenshot 2022-10-22 at 4 16 37 PM" src="https://user-images.githubusercontent.com/10107633/197344164-50d72a25-a6e7-4e77-ad87-2d5f54b29b93.png"> </details> Opt-in profiling --------------- Use the new global option `--profile` (in debug only) to profile a command. Future scopes -------------- * When I've discussed the limitation of profiling long running processes such as `messenger:consume` with `@GromNaN` (one of the reasons why I've added an `excludes` option), he told that it would be nice it we could find a way to profile consumers as well. So I've added ~an abstract `VirtualRequest`~ a `_virtual_type` request attribute and a `virtualType` property to profiles, that will allow to create a `MessengerWorkerRequest` and a new type of profile with ease in a follow-up PR if the current implementation is accepted. * We could add some dedicated casters for input and output in the `VarDumper` component (/cc `@nicolas`-grekas) * It could be interesting to decorate and collect traces from some helpers (i.e. when running processes) * ~Add a global option in debug to enable/disable the profiler on the fly when running commands (e.g. a negatable `--profile` flag)~ **[update] implemented in current scope in replacement of semantic config.** * Extract profiling to a new component. Limitations ----------- * ~No sub profiles are created when using `$this->getApplication()->find(...)->run()` because events (needed by the profiler to hook into) are dispatched from `Application::run()`, not from `Command::run()`.~ **[update] The docs has been updated in symfony/symfony-docs#18741 * ~No profiles are created when killing the command process (i.e. using `ctrl-C`, should we add a handler to some signals to force saving profiles?~ **[update] I've added support for this.** * ~Signals as int may not be as useful as they could in the profiler pages, does it worth trying to add a label to some (knowing that some signals can have different constants (labels) with the same int value)?~ **[update] done thanks to symfony/symfony#50663 * ~Long running processes should be excluded via configuration to avoid memory leaks~ **[update] profiling is now opt-in using the `--profile` option.** * Profiling `messenger:consume` does not work since the kernel is reset after handling a message. __________________ TODO ------ * [x] I've left some todos inside the code for reviewers to share they thought before I try going further * [x] Add a few tests * [ ] Get help for the UI (new top nav, ~svg for the command panel~) /cc `@javiereguiluz` * ~PR on `symfony/recipes` to add the new `framework.profiler.cli` node~ Commits ------- 82914bab0d [Console][FrameworkBundle][HttpKernel][WebProfilerBundle] Enable profiling commands
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -33,6 +33,7 @@ CHANGELOG
  * Add parameters deprecations to the output of `debug:container` command
  * Change `framework.asset_mapper.importmap_polyfill` from a URL to the name of an item in the importmap
  * Provide `$buildDir` when running `CacheWarmer` to build read-only resources
+ * Add the global `--profile` option to the console to enable profiling commands
 
 6.3
 ---
diff --git a/Console/Application.php b/Console/Application.php
@@ -14,6 +14,8 @@
 use Symfony\Component\Console\Application as BaseApplication;
 use Symfony\Component\Console\Command\Command;
 use Symfony\Component\Console\Command\ListCommand;
+use Symfony\Component\Console\Command\TraceableCommand;
+use Symfony\Component\Console\Debug\CliRequest;
 use Symfony\Component\Console\Input\InputInterface;
 use Symfony\Component\Console\Input\InputOption;
 use Symfony\Component\Console\Output\ConsoleOutputInterface;
@@ -42,6 +44,7 @@ public function __construct(KernelInterface $kernel)
         $inputDefinition = $this->getDefinition();
         $inputDefinition->addOption(new InputOption('--env', '-e', InputOption::VALUE_REQUIRED, 'The Environment name.', $kernel->getEnvironment()));
         $inputDefinition->addOption(new InputOption('--no-debug', null, InputOption::VALUE_NONE, 'Switch off debug mode.'));
+        $inputDefinition->addOption(new InputOption('--profile', null, InputOption::VALUE_NONE, 'Enables profiling (requires debug).'));
     }
 
     /**
@@ -79,18 +82,47 @@ public function doRun(InputInterface $input, OutputInterface $output): int
 
     protected function doRunCommand(Command $command, InputInterface $input, OutputInterface $output): int
     {
+        $requestStack = null;
+        $renderRegistrationErrors = true;
+
         if (!$command instanceof ListCommand) {
             if ($this->registrationErrors) {
                 $this->renderRegistrationErrors($input, $output);
                 $this->registrationErrors = [];
+                $renderRegistrationErrors = false;
             }
+        }
+
+        if ($input->hasParameterOption('--profile')) {
+            $container = $this->kernel->getContainer();
 
-            return parent::doRunCommand($command, $input, $output);
+            if (!$this->kernel->isDebug()) {
+                if ($output instanceof ConsoleOutputInterface) {
+                    $output = $output->getErrorOutput();
+                }
+
+                (new SymfonyStyle($input, $output))->warning('Debug mode should be enabled when the "--profile" option is used.');
+            } elseif (!$container->has('debug.stopwatch')) {
+                if ($output instanceof ConsoleOutputInterface) {
+                    $output = $output->getErrorOutput();
+                }
+
+                (new SymfonyStyle($input, $output))->warning('The "--profile" option needs the Stopwatch component. Try running "composer require symfony/stopwatch".');
+            } else {
+                $command = new TraceableCommand($command, $container->get('debug.stopwatch'));
+
+                $requestStack = $container->get('.virtual_request_stack');
+                $requestStack->push(new CliRequest($command));
+            }
         }
 
-        $returnCode = parent::doRunCommand($command, $input, $output);
+        try {
+            $returnCode = parent::doRunCommand($command, $input, $output);
+        } finally {
+            $requestStack?->pop();
+        }
 
-        if ($this->registrationErrors) {
+        if ($renderRegistrationErrors && $this->registrationErrors) {
             $this->renderRegistrationErrors($input, $output);
             $this->registrationErrors = [];
         }
diff --git a/DependencyInjection/FrameworkExtension.php b/DependencyInjection/FrameworkExtension.php
@@ -50,6 +50,7 @@
 use Symfony\Component\Config\ResourceCheckerInterface;
 use Symfony\Component\Console\Application;
 use Symfony\Component\Console\Command\Command;
+use Symfony\Component\Console\Debug\CliRequest;
 use Symfony\Component\Console\Messenger\RunCommandMessageHandler;
 use Symfony\Component\DependencyInjection\Alias;
 use Symfony\Component\DependencyInjection\Argument\ServiceClosureArgument;
@@ -912,6 +913,10 @@ private function registerProfilerConfiguration(array $config, ContainerBuilder $
 
         $container->getDefinition('profiler_listener')
             ->addArgument($config['collect_parameter']);
+
+        if (!$container->getParameter('kernel.debug') || !class_exists(CliRequest::class) || !$container->has('debug.stopwatch')) {
+            $container->removeDefinition('console_profiler_listener');
+        }
     }
 
     private function registerWorkflowConfiguration(array $config, ContainerBuilder $container, PhpFileLoader $loader): void
@@ -1134,15 +1139,16 @@ private function registerDebugConfiguration(array $config, ContainerBuilder $con
     {
         $loader->load('debug_prod.php');
 
+        $debug = $container->getParameter('kernel.debug');
+
         if (class_exists(Stopwatch::class)) {
             $container->register('debug.stopwatch', Stopwatch::class)
                 ->addArgument(true)
+                ->setPublic($debug)
                 ->addTag('kernel.reset', ['method' => 'reset']);
             $container->setAlias(Stopwatch::class, new Alias('debug.stopwatch', false));
         }
 
-        $debug = $container->getParameter('kernel.debug');
-
         if ($debug && !$container->hasParameter('debug.container.dump')) {
             $container->setParameter('debug.container.dump', '%kernel.build_dir%/%kernel.container_class%.xml');
         }
@@ -1165,7 +1171,7 @@ private function registerDebugConfiguration(array $config, ContainerBuilder $con
 
         if ($debug && class_exists(DebugProcessor::class)) {
             $definition = new Definition(DebugProcessor::class);
-            $definition->addArgument(new Reference('request_stack'));
+            $definition->addArgument(new Reference('.virtual_request_stack'));
             $definition->addTag('kernel.reset', ['method' => 'reset']);
             $container->setDefinition('debug.log_processor', $definition);
 
diff --git a/EventListener/ConsoleProfilerListener.php b/EventListener/ConsoleProfilerListener.php
@@ -0,0 +1,144 @@
+<?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\Bundle\FrameworkBundle\EventListener;
+
+use Symfony\Component\Console\ConsoleEvents;
+use Symfony\Component\Console\Debug\CliRequest;
+use Symfony\Component\Console\Event\ConsoleCommandEvent;
+use Symfony\Component\Console\Event\ConsoleErrorEvent;
+use Symfony\Component\Console\Event\ConsoleTerminateEvent;
+use Symfony\Component\Console\Output\ConsoleOutputInterface;
+use Symfony\Component\EventDispatcher\EventSubscriberInterface;
+use Symfony\Component\HttpFoundation\Request;
+use Symfony\Component\HttpFoundation\RequestStack;
+use Symfony\Component\HttpKernel\Profiler\Profile;
+use Symfony\Component\HttpKernel\Profiler\Profiler;
+use Symfony\Component\Routing\Generator\UrlGeneratorInterface;
+use Symfony\Component\Stopwatch\Stopwatch;
+
+/**
+ * @internal
+ *
+ * @author Jules Pietri <jules@heahprod.com>
+ */
+final class ConsoleProfilerListener implements EventSubscriberInterface
+{
+    private ?\Throwable $error = null;
+    /** @var \SplObjectStorage<Request, Profile> */
+    private \SplObjectStorage $profiles;
+    /** @var \SplObjectStorage<Request, ?Request> */
+    private \SplObjectStorage $parents;
+
+    public function __construct(
+        private readonly Profiler $profiler,
+        private readonly RequestStack $requestStack,
+        private readonly Stopwatch $stopwatch,
+        private readonly UrlGeneratorInterface $urlGenerator,
+    ) {
+        $this->profiles = new \SplObjectStorage();
+        $this->parents = new \SplObjectStorage();
+    }
+
+    public static function getSubscribedEvents(): array
+    {
+        return [
+            ConsoleEvents::COMMAND => ['initialize', 4096],
+            ConsoleEvents::ERROR => ['catch', -2048],
+            ConsoleEvents::TERMINATE => ['profile', -4096],
+        ];
+    }
+
+    public function initialize(ConsoleCommandEvent $event): void
+    {
+        if (!$event->getInput()->getOption('profile')) {
+            $this->profiler->disable();
+
+            return;
+        }
+
+        $request = $this->requestStack->getCurrentRequest();
+
+        if (!$request instanceof CliRequest || $request->command !== $event->getCommand()) {
+            return;
+        }
+
+        $request->attributes->set('_stopwatch_token', substr(hash('sha256', uniqid(mt_rand(), true)), 0, 6));
+        $this->stopwatch->openSection();
+    }
+
+    public function catch(ConsoleErrorEvent $event): void
+    {
+        $this->error = $event->getError();
+    }
+
+    public function profile(ConsoleTerminateEvent $event): void
+    {
+        if (!$this->profiler->isEnabled()) {
+            return;
+        }
+
+        $request = $this->requestStack->getCurrentRequest();
+
+        if (!$request instanceof CliRequest || $request->command !== $event->getCommand()) {
+            return;
+        }
+
+        if (null !== $sectionId = $request->attributes->get('_stopwatch_token')) {
+            // we must close the section before saving the profile to allow late collect
+            try {
+                $this->stopwatch->stopSection($sectionId);
+            } catch (\LogicException) {
+                // noop
+            }
+        }
+
+        $request->command->exitCode = $event->getExitCode();
+        $request->command->interruptedBySignal = $event->getInterruptingSignal();
+
+        $profile = $this->profiler->collect($request, $request->getResponse(), $this->error);
+        $this->error = null;
+        $this->profiles[$request] = $profile;
+
+        if ($this->parents[$request] = $this->requestStack->getParentRequest()) {
+            // do not save on sub commands
+            return;
+        }
+
+        // attach children to parents
+        foreach ($this->profiles as $request) {
+            if (null !== $parentRequest = $this->parents[$request]) {
+                if (isset($this->profiles[$parentRequest])) {
+                    $this->profiles[$parentRequest]->addChild($this->profiles[$request]);
+                }
+            }
+        }
+
+        $output = $event->getOutput();
+        $output = $output instanceof ConsoleOutputInterface && $output->isVerbose() ? $output->getErrorOutput() : null;
+
+        // save profiles
+        foreach ($this->profiles as $r) {
+            $p = $this->profiles[$r];
+            $this->profiler->saveProfile($p);
+
+            $token = $p->getToken();
+            $output?->writeln(sprintf(
+                'See profile <href=%s>%s</>',
+                $this->urlGenerator->generate('_profiler', ['token' => $token], UrlGeneratorInterface::ABSOLUTE_URL),
+                $token
+            ));
+        }
+
+        $this->profiles = new \SplObjectStorage();
+        $this->parents = new \SplObjectStorage();
+    }
+}
diff --git a/Resources/config/collectors.php b/Resources/config/collectors.php
@@ -12,6 +12,7 @@
 namespace Symfony\Component\DependencyInjection\Loader\Configurator;
 
 use Symfony\Bundle\FrameworkBundle\DataCollector\RouterDataCollector;
+use Symfony\Component\Console\DataCollector\CommandDataCollector;
 use Symfony\Component\HttpKernel\DataCollector\AjaxDataCollector;
 use Symfony\Component\HttpKernel\DataCollector\ConfigDataCollector;
 use Symfony\Component\HttpKernel\DataCollector\EventDataCollector;
@@ -30,7 +31,7 @@
 
         ->set('data_collector.request', RequestDataCollector::class)
             ->args([
-                service('request_stack')->ignoreOnInvalid(),
+                service('.virtual_request_stack')->ignoreOnInvalid(),
             ])
             ->tag('kernel.event_subscriber')
             ->tag('data_collector', ['template' => '@WebProfiler/Collector/request.html.twig', 'id' => 'request', 'priority' => 335])
@@ -48,15 +49,15 @@
         ->set('data_collector.events', EventDataCollector::class)
             ->args([
                 tagged_iterator('event_dispatcher.dispatcher', 'name'),
-                service('request_stack')->ignoreOnInvalid(),
+                service('.virtual_request_stack')->ignoreOnInvalid(),
             ])
             ->tag('data_collector', ['template' => '@WebProfiler/Collector/events.html.twig', 'id' => 'events', 'priority' => 290])
 
         ->set('data_collector.logger', LoggerDataCollector::class)
             ->args([
                 service('logger')->ignoreOnInvalid(),
                 sprintf('%s/%s', param('kernel.build_dir'), param('kernel.container_class')),
-                service('request_stack')->ignoreOnInvalid(),
+                service('.virtual_request_stack')->ignoreOnInvalid(),
             ])
             ->tag('monolog.logger', ['channel' => 'profiler'])
             ->tag('data_collector', ['template' => '@WebProfiler/Collector/logger.html.twig', 'id' => 'logger', 'priority' => 300])
@@ -74,5 +75,8 @@
         ->set('data_collector.router', RouterDataCollector::class)
             ->tag('kernel.event_listener', ['event' => KernelEvents::CONTROLLER, 'method' => 'onKernelController'])
             ->tag('data_collector', ['template' => '@WebProfiler/Collector/router.html.twig', 'id' => 'router', 'priority' => 285])
+
+        ->set('.data_collector.command', CommandDataCollector::class)
+            ->tag('data_collector', ['template' => '@WebProfiler/Collector/command.html.twig', 'id' => 'command', 'priority' => 335])
     ;
 };
diff --git a/Resources/config/debug.php b/Resources/config/debug.php
@@ -15,6 +15,7 @@
 use Symfony\Component\HttpKernel\Controller\TraceableArgumentResolver;
 use Symfony\Component\HttpKernel\Controller\TraceableControllerResolver;
 use Symfony\Component\HttpKernel\Debug\TraceableEventDispatcher;
+use Symfony\Component\HttpKernel\Debug\VirtualRequestStack;
 
 return static function (ContainerConfigurator $container) {
     $container->services()
@@ -24,7 +25,7 @@
                 service('debug.event_dispatcher.inner'),
                 service('debug.stopwatch'),
                 service('logger')->nullOnInvalid(),
-                service('request_stack')->nullOnInvalid(),
+                service('.virtual_request_stack')->nullOnInvalid(),
             ])
             ->tag('monolog.logger', ['channel' => 'event'])
             ->tag('kernel.reset', ['method' => 'reset'])
@@ -46,5 +47,9 @@
         ->set('argument_resolver.not_tagged_controller', NotTaggedControllerValueResolver::class)
             ->args([abstract_arg('Controller argument, set in FrameworkExtension')])
             ->tag('controller.argument_value_resolver', ['priority' => -200])
+
+        ->set('.virtual_request_stack', VirtualRequestStack::class)
+            ->args([service('request_stack')])
+            ->public()
     ;
 };
diff --git a/Resources/config/profiling.php b/Resources/config/profiling.php
@@ -11,6 +11,7 @@
 
 namespace Symfony\Component\DependencyInjection\Loader\Configurator;
 
+use Symfony\Bundle\FrameworkBundle\EventListener\ConsoleProfilerListener;
 use Symfony\Component\HttpKernel\EventListener\ProfilerListener;
 use Symfony\Component\HttpKernel\Profiler\FileProfilerStorage;
 use Symfony\Component\HttpKernel\Profiler\Profiler;
@@ -35,5 +36,14 @@
                 param('profiler_listener.only_main_requests'),
             ])
             ->tag('kernel.event_subscriber')
+
+        ->set('console_profiler_listener', ConsoleProfilerListener::class)
+            ->args([
+                service('profiler'),
+                service('.virtual_request_stack'),
+                service('debug.stopwatch'),
+                service('router'),
+            ])
+            ->tag('kernel.event_subscriber')
     ;
 };
diff --git a/Tests/Console/ApplicationTest.php b/Tests/Console/ApplicationTest.php
@@ -26,6 +26,7 @@
 use Symfony\Component\DependencyInjection\ContainerInterface;
 use Symfony\Component\EventDispatcher\EventDispatcher;
 use Symfony\Component\EventDispatcher\EventDispatcherInterface;
+use Symfony\Component\HttpFoundation\RequestStack;
 use Symfony\Component\HttpKernel\Bundle\Bundle;
 use Symfony\Component\HttpKernel\Bundle\BundleInterface;
 use Symfony\Component\HttpKernel\KernelInterface;
@@ -242,17 +243,25 @@ private function getKernel(array $bundles, $useDispatcher = false)
     {
         $container = $this->createMock(ContainerInterface::class);
 
+        $requestStack = $this->createMock(RequestStack::class);
+        $requestStack->expects($this->any())
+            ->method('push')
+        ;
+
         if ($useDispatcher) {
             $dispatcher = $this->createMock(EventDispatcherInterface::class);
             $dispatcher
                 ->expects($this->atLeastOnce())
                 ->method('dispatch')
             ;
-            $container
-                ->expects($this->atLeastOnce())
+
+            $container->expects($this->atLeastOnce())
                 ->method('get')
-                ->with($this->equalTo('event_dispatcher'))
-                ->willReturn($dispatcher);
+                ->willReturnMap([
+                    ['.virtual_request_stack', 2, $requestStack],
+                    ['event_dispatcher', 1, $dispatcher],
+                ])
+            ;
         }
 
         $container
