Add performance counters to ConsoleSubsriber

deptrac.config.php

@@ -61,6 +61,9 @@
             $file = Layer::withName('File')->collectors(
                 DirectoryConfig::create('src/Supportive/File/.*')
             ),
+            $time = Layer::withName('Time')->collectors(
+                DirectoryConfig::create('src/Supportive/Time/.*')
+            ),
             $supportive = Layer::withName('Supportive')->collectors(
                 BoolConfig::create()
                     ->mustNot(DirectoryConfig::create('src/Supportive/.*/.*'))
@@ -69,7 +72,7 @@
         )
         ->rulesets(
             Ruleset::forLayer($layer)->accesses($ast),
-            Ruleset::forLayer($console)->accesses($analyser, $outputFormatter, $dependencyInjection, $file),
+            Ruleset::forLayer($console)->accesses($analyser, $outputFormatter, $dependencyInjection, $file, $time),
             Ruleset::forLayer($dependency)->accesses($ast),
             Ruleset::forLayer($analyser)->accesses($layer, $dependency, $ast),
             Ruleset::forLayer($outputFormatter)->accesses($console, $dependencyInjection),

deptrac.yaml

@@ -90,6 +90,10 @@ deptrac:
       collectors:
         - type: directory
           value: src/Supportive/File/.*
+    - name: Time
+      collectors:
+        - type: directory
+          value: src/Supportive/Time/.*
     - name: Supportive
       collectors:
         - type: bool
@@ -108,6 +112,7 @@ deptrac:
       - OutputFormatter
       - DependencyInjection
       - File
+      - Time
     Dependency:
       - Ast
     Analyser:

src/Supportive/Console/Command/AnalyseCommand.php

@@ -12,6 +12,7 @@
 use Qossmic\Deptrac\Supportive\OutputFormatter\FormatterProvider;
 use Qossmic\Deptrac\Supportive\OutputFormatter\GithubActionsOutputFormatter;
 use Qossmic\Deptrac\Supportive\OutputFormatter\TableOutputFormatter;
+use Qossmic\Deptrac\Supportive\Time\Stopwatch;
 use Symfony\Component\Console\Command\Command;
 use Symfony\Component\Console\Input\InputInterface;
 use Symfony\Component\Console\Input\InputOption;
@@ -77,7 +78,7 @@ protected function execute(InputInterface $input, OutputInterface $output): int
             (bool) $input->getOption(self::OPTION_FAIL_ON_UNCOVERED)
         );
 
-        $this->dispatcher->addSubscriber(new ConsoleSubscriber($symfonyOutput));
+        $this->dispatcher->addSubscriber(new ConsoleSubscriber($symfonyOutput, new Stopwatch()));
         if (!$options->noProgress) {
             $this->dispatcher->addSubscriber(new ProgressSubscriber($symfonyOutput));
         }

src/Supportive/Console/Subscriber/ConsoleSubscriber.php

@@ -13,12 +13,18 @@
 use Qossmic\Deptrac\Contract\Dependency\PreEmitEvent;
 use Qossmic\Deptrac\Contract\Dependency\PreFlattenEvent;
 use Qossmic\Deptrac\Contract\OutputFormatter\OutputInterface;
+use Qossmic\Deptrac\Supportive\Time\Stopwatch;
+use Qossmic\Deptrac\Supportive\Time\StopwatchException;
 use Symfony\Component\EventDispatcher\EventSubscriberInterface;
 
+use function sprintf;
+
 class ConsoleSubscriber implements EventSubscriberInterface
 {
-    public function __construct(private readonly OutputInterface $output)
-    {
+    public function __construct(
+        private readonly OutputInterface $output,
+        private readonly Stopwatch $stopwatch,
+    ) {
     }
 
     /**
@@ -41,6 +47,8 @@ public static function getSubscribedEvents(): array
     public function onPreCreateAstMapEvent(PreCreateAstMapEvent $preCreateAstMapEvent): void
     {
         if ($this->output->isVerbose()) {
+            $this->stopwatchStart('ast');
+
             $this->output->writeLineFormatted(
                 sprintf(
                     'Start to create an AstMap for <info>%u</info> Files.',
@@ -53,7 +61,11 @@ public function onPreCreateAstMapEvent(PreCreateAstMapEvent $preCreateAstMapEven
     public function onPostCreateAstMapEvent(PostCreateAstMapEvent $postCreateAstMapEvent): void
     {
         if ($this->output->isVerbose()) {
-            $this->output->writeLineFormatted('AstMap created.');
+            $this->printMessageWithTime(
+                'ast',
+                '<info>AstMap created in %01.2f sec.</info>',
+                '<info>AstMap created.</info>'
+            );
         }
     }
 
@@ -76,6 +88,8 @@ public function onAstFileSyntaxErrorEvent(AstFileSyntaxErrorEvent $astFileSyntax
     public function onPreDependencyEmit(PreEmitEvent $event): void
     {
         if ($this->output->isVerbose()) {
+            $this->stopwatchStart('deps');
+
             $this->output->writeLineFormatted(
                 sprintf('start emitting dependencies <info>"%s"</info>', $event->emitterName)
             );
@@ -85,21 +99,58 @@ public function onPreDependencyEmit(PreEmitEvent $event): void
     public function onPostDependencyEmit(PostEmitEvent $event): void
     {
         if ($this->output->isVerbose()) {
-            $this->output->writeLineFormatted('<info>end emitting dependencies</info>');
+            $this->printMessageWithTime(
+                'deps',
+                '<info>Dependencies emitted in %01.f sec.</info>',
+                '<info>Dependencies emitted.</info>'
+            );
         }
     }
 
     public function onPreDependencyFlatten(PreFlattenEvent $event): void
     {
         if ($this->output->isVerbose()) {
-            $this->output->writeLineFormatted('<info>start flatten dependencies</info>');
+            $this->stopwatchStart('flatten');
+
+            $this->output->writeLineFormatted('start flatten dependencies');
         }
     }
 
     public function onPostDependencyFlatten(PostFlattenEvent $event): void
     {
         if ($this->output->isVerbose()) {
-            $this->output->writeLineFormatted('<info>end flatten dependencies</info>');
+            $this->printMessageWithTime(
+                'flatten',
+                '<info>Dependencies flattened in %01.f sec.</info>',
+                '<info>Dependencies flattened.</info>'
+            );
+        }
+    }
+
+    /**
+     * @param non-empty-string $event
+     */
+    private function stopwatchStart(string $event): void
+    {
+        try {
+            $this->stopwatch->start($event);
+        } catch (StopwatchException) {
+        }
+    }
+
+    /**
+     * @param non-empty-string $event
+     * @param non-empty-string $messageWithTime
+     * @param non-empty-string $messageWithoutTime
+     */
+    private function printMessageWithTime(string $event, string $messageWithTime, string $messageWithoutTime): void
+    {
+        try {
+            $period = $this->stopwatch->stop($event);
+
+            $this->output->writeLineFormatted(sprintf($messageWithTime, $period->toSeconds()));
+        } catch (StopwatchException) {
+            $this->output->writeLineFormatted($messageWithoutTime);
         }
     }
 }

src/Supportive/Time/Period.php

@@ -0,0 +1,37 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Qossmic\Deptrac\Supportive\Time;
+
+use function hrtime;
+
+/**
+ * @psalm-immutable
+ */
+final class Period
+{
+    private function __construct(
+        public readonly float|int $startedAt,
+        public readonly float|int $endedAt,
+    ) {
+    }
+
+    /**
+     * @psalm-pure
+     */
+    public static function stop(StartedPeriod $startedPeriod): self
+    {
+        return new self(
+            $startedPeriod->startedAt,
+            hrtime(true),
+        );
+    }
+
+    public function toSeconds(): float
+    {
+        $duration = $this->endedAt - $this->startedAt;
+
+        return $duration / 1e9;
+    }
+}

src/Supportive/Time/StartedPeriod.php

@@ -0,0 +1,28 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Qossmic\Deptrac\Supportive\Time;
+
+/**
+ * @psalm-immutable
+ */
+final class StartedPeriod
+{
+    private function __construct(
+        public readonly float|int $startedAt
+    ) {
+    }
+
+    public static function start(): self
+    {
+        return new self(
+            hrtime(true),
+        );
+    }
+
+    public function stop(): Period
+    {
+        return Period::stop($this);
+    }
+}

src/Supportive/Time/Stopwatch.php

@@ -0,0 +1,65 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Qossmic\Deptrac\Supportive\Time;
+
+use function array_key_exists;
+
+final class Stopwatch
+{
+    /** @var array<non-empty-string, StartedPeriod> */
+    private array $periods = [];
+
+    /**
+     * @param non-empty-string $event
+     *
+     * @throws StopwatchException
+     */
+    public function start(string $event): void
+    {
+        $this->assertPeriodNotStarted($event);
+
+        $this->periods[$event] = StartedPeriod::start();
+    }
+
+    /**
+     * @param non-empty-string $event
+     *
+     * @throws StopwatchException
+     */
+    public function stop(string $event): Period
+    {
+        $this->assertPeriodStarted($event);
+
+        $period = $this->periods[$event]->stop();
+
+        unset($this->periods[$event]);
+
+        return $period;
+    }
+
+    /**
+     * @param non-empty-string $event
+     *
+     * @throws StopwatchException
+     */
+    private function assertPeriodNotStarted(string $event): void
+    {
+        if (array_key_exists($event, $this->periods)) {
+            throw StopwatchException::periodAlreadyStarted($event);
+        }
+    }
+
+    /**
+     * @param non-empty-string $event
+     *
+     * @throws StopwatchException
+     */
+    private function assertPeriodStarted(string $event): void
+    {
+        if (!array_key_exists($event, $this->periods)) {
+            throw StopwatchException::periodNotStarted($event);
+        }
+    }
+}

src/Supportive/Time/StopwatchException.php

@@ -0,0 +1,33 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Qossmic\Deptrac\Supportive\Time;
+
+use Qossmic\Deptrac\Contract\ExceptionInterface;
+use RuntimeException;
+
+use function sprintf;
+
+final class StopwatchException extends RuntimeException implements ExceptionInterface
+{
+    public static function periodAlreadyStarted(string $period): self
+    {
+        return new self(
+            sprintf(
+                'Period "%s" is already started',
+                $period,
+            )
+        );
+    }
+
+    public static function periodNotStarted(string $period): self
+    {
+        return new self(
+            sprintf(
+                'Period "%s" is not started',
+                $period,
+            )
+        );
+    }
+}