diff --git a/deptrac.config.php b/deptrac.config.php index e4f366942..ef8eae9b2 100755 --- a/deptrac.config.php +++ b/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), diff --git a/deptrac.yaml b/deptrac.yaml index 4afdc891c..d3e2c1152 100644 --- a/deptrac.yaml +++ b/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: diff --git a/src/Supportive/Console/Command/AnalyseCommand.php b/src/Supportive/Console/Command/AnalyseCommand.php index 8c8365ee7..e306b2376 100644 --- a/src/Supportive/Console/Command/AnalyseCommand.php +++ b/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)); } diff --git a/src/Supportive/Console/Subscriber/ConsoleSubscriber.php b/src/Supportive/Console/Subscriber/ConsoleSubscriber.php index b697291a1..287e89e74 100644 --- a/src/Supportive/Console/Subscriber/ConsoleSubscriber.php +++ b/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 %u 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', + 'AstMap created in %01.2f sec.', + 'AstMap created.' + ); } } @@ -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 "%s"', $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('end emitting dependencies'); + $this->printMessageWithTime( + 'deps', + 'Dependencies emitted in %01.f sec.', + 'Dependencies emitted.' + ); } } public function onPreDependencyFlatten(PreFlattenEvent $event): void { if ($this->output->isVerbose()) { - $this->output->writeLineFormatted('start flatten dependencies'); + $this->stopwatchStart('flatten'); + + $this->output->writeLineFormatted('start flatten dependencies'); } } public function onPostDependencyFlatten(PostFlattenEvent $event): void { if ($this->output->isVerbose()) { - $this->output->writeLineFormatted('end flatten dependencies'); + $this->printMessageWithTime( + 'flatten', + 'Dependencies flattened in %01.f sec.', + 'Dependencies flattened.' + ); + } + } + + /** + * @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); } } } diff --git a/src/Supportive/Time/Period.php b/src/Supportive/Time/Period.php new file mode 100644 index 000000000..2a1666c62 --- /dev/null +++ b/src/Supportive/Time/Period.php @@ -0,0 +1,37 @@ +startedAt, + hrtime(true), + ); + } + + public function toSeconds(): float + { + $duration = $this->endedAt - $this->startedAt; + + return $duration / 1e9; + } +} diff --git a/src/Supportive/Time/StartedPeriod.php b/src/Supportive/Time/StartedPeriod.php new file mode 100644 index 000000000..e01d672c0 --- /dev/null +++ b/src/Supportive/Time/StartedPeriod.php @@ -0,0 +1,28 @@ + */ + 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); + } + } +} diff --git a/src/Supportive/Time/StopwatchException.php b/src/Supportive/Time/StopwatchException.php new file mode 100644 index 000000000..3c6cfd3c8 --- /dev/null +++ b/src/Supportive/Time/StopwatchException.php @@ -0,0 +1,33 @@ +onPreCreateAstMapEvent(new PreCreateAstMapEvent(9999999)); self::assertSame('Start to create an AstMap for 9999999 Files.'.PHP_EOL, $symfonyOutput->fetch()); } - public function testOnPostCreateAstMapEventWithVerboseVerbosity(): void + public function testOnPreCreateAstMapEventWithStopwatchAlreadyStartedVerboseVerbosity(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $stopwatch = new Stopwatch(); + $stopwatch->start('ast'); + + $subscriber = new ConsoleSubscriber($output, $stopwatch); + $subscriber->onPreCreateAstMapEvent(new PreCreateAstMapEvent(9999999)); + + self::assertSame('Start to create an AstMap for 9999999 Files.'.PHP_EOL, $symfonyOutput->fetch()); + } + + public function testOnPostCreateAstMapEventWithVerboseVerbosityWithNoStopwatchStarted(): void { $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); $subscriber->onPostCreateAstMapEvent(new PostCreateAstMapEvent()); self::assertSame('AstMap created.'.PHP_EOL, $symfonyOutput->fetch()); } + public function testOnPostCreateAstMapEventWithVerboseVerbosity(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPreCreateAstMapEvent(new PreCreateAstMapEvent(9999999)); + $subscriber->onPostCreateAstMapEvent(new PostCreateAstMapEvent()); + + self::assertMatchesRegularExpression( + '/AstMap created in \d+\.\d+ sec\.'.PHP_EOL.'/', + $symfonyOutput->fetch() + ); + } + public function testOnAstFileAnalysedEventWithVerboseVerbosity(): void { $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); $subscriber->onAstFileAnalysedEvent(new AstFileAnalysedEvent('foo.php')); self::assertSame('Parsing File foo.php'.PHP_EOL, $symfonyOutput->fetch()); @@ -80,7 +110,7 @@ public function testOnAstFileSyntaxErrorEvent(): void $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); $subscriber->onAstFileSyntaxErrorEvent( new AstFileSyntaxErrorEvent('foo.php', 'Invalid') ); @@ -93,21 +123,50 @@ public function testOnPreDependencyEmit(): void $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPreDependencyEmit(new PreEmitEvent('emitter-name')); + + self::assertSame('start emitting dependencies "emitter-name"'.PHP_EOL, $symfonyOutput->fetch()); + } + + public function testOnPreDependencyEmitWithStopwatchAlreadyStarted(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $stopwatch = new Stopwatch(); + $stopwatch->start('deps'); + + $subscriber = new ConsoleSubscriber($output, $stopwatch); $subscriber->onPreDependencyEmit(new PreEmitEvent('emitter-name')); self::assertSame('start emitting dependencies "emitter-name"'.PHP_EOL, $symfonyOutput->fetch()); } + public function testOnPostDependencyEmitWithNoStopwatchStarted(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPostDependencyEmit(new PostEmitEvent()); + + self::assertSame('Dependencies emitted.'.PHP_EOL, $symfonyOutput->fetch()); + } + public function testOnPostDependencyEmit(): void { $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPreDependencyEmit(new PreEmitEvent('emitter-name')); $subscriber->onPostDependencyEmit(new PostEmitEvent()); - self::assertSame('end emitting dependencies'.PHP_EOL, $symfonyOutput->fetch()); + self::assertMatchesRegularExpression( + '/Dependencies emitted in \d+\.\d+ sec\.'.PHP_EOL.'/', + $symfonyOutput->fetch() + ); } public function testOnPreDependencyFlatten(): void @@ -115,20 +174,49 @@ public function testOnPreDependencyFlatten(): void $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); $subscriber->onPreDependencyFlatten(new PreFlattenEvent()); self::assertSame('start flatten dependencies'.PHP_EOL, $symfonyOutput->fetch()); } + public function testOnPreDependencyFlattenWithStopwatchStarted(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $stopwatch = new Stopwatch(); + $stopwatch->start('flatten'); + + $subscriber = new ConsoleSubscriber($output, $stopwatch); + $subscriber->onPreDependencyFlatten(new PreFlattenEvent()); + + self::assertSame('start flatten dependencies'.PHP_EOL, $symfonyOutput->fetch()); + } + + public function testOnPostDependencyFlattenWithNoStopwatchStarted(): void + { + $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); + $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); + + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPostDependencyFlatten(new PostFlattenEvent()); + + self::assertSame('Dependencies flattened.'.PHP_EOL, $symfonyOutput->fetch()); + } + public function testOnPostDependencyFlatten(): void { $symfonyOutput = new BufferedOutput(OutputInterface::VERBOSITY_VERBOSE); $output = new SymfonyOutput($symfonyOutput, new Style(new SymfonyStyle(new ArrayInput([]), $symfonyOutput))); - $subscriber = new ConsoleSubscriber($output); + $subscriber = new ConsoleSubscriber($output, new Stopwatch()); + $subscriber->onPreDependencyFlatten(new PreFlattenEvent()); $subscriber->onPostDependencyFlatten(new PostFlattenEvent()); - self::assertSame('end flatten dependencies'.PHP_EOL, $symfonyOutput->fetch()); + self::assertMatchesRegularExpression( + '/Dependencies flattened in \d+\.\d+ sec\.'.PHP_EOL.'/', + $symfonyOutput->fetch() + ); } } diff --git a/tests/Supportive/Time/StopwatchTest.php b/tests/Supportive/Time/StopwatchTest.php new file mode 100644 index 000000000..61d9b5b33 --- /dev/null +++ b/tests/Supportive/Time/StopwatchTest.php @@ -0,0 +1,45 @@ +stopwatch = new Stopwatch(); + } + + public function testEventCanNotBeStartedTwice(): void + { + $this->expectException(StopwatchException::class); + $this->expectExceptionMessage('Period "test" is already started'); + + $this->stopwatch->start('test'); + $this->stopwatch->start('test'); + } + + public function testEventCanNotBeStoppedWithoutBeingStarted(): void + { + $this->expectException(StopwatchException::class); + $this->expectExceptionMessage('Period "test" is not started'); + + $this->stopwatch->stop('test'); + } + + public function testEventFlowAndEventCanBeStartedAgain(): void + { + $this->stopwatch->start('test'); + $this->stopwatch->stop('test'); + $this->stopwatch->start('test'); + + $this->expectNotToPerformAssertions(); + } +}