From 932580e30f600f0e0de22c5a8041fa595af88d7a Mon Sep 17 00:00:00 2001 From: Petr Knap <8299754+petrknap@users.noreply.github.com> Date: Thu, 10 Oct 2024 18:15:07 +0200 Subject: [PATCH] feat: implemented support for listening to ticks --- README.md | 25 +++++++++++++++++++++---- src/Profile.php | 34 ++++++++++++++++++++++++++++++++-- src/Profiler.php | 7 ++++++- src/Profiling.php | 27 +++++++++++++++++++-------- tests/ProfileTest.php | 24 ++++++++++++++++++++++++ tests/ReadmeTest.php | 1 + 6 files changed, 103 insertions(+), 15 deletions(-) diff --git a/README.md b/README.md index 47d113d..1407d26 100644 --- a/README.md +++ b/README.md @@ -27,7 +27,7 @@ Request a [profiler](./src/ProfilerInterface.php) as a dependency and call a `pr ```php namespace PetrKnap\Profiler; -function something(ProfilerInterface $profiler): string { +function doSomething(ProfilerInterface $profiler): string { // do something without profiling return $profiler->profile(function (): string { // do something @@ -46,8 +46,8 @@ It can be easily enabled, or disabled **through the DI**, which provides either ```php namespace PetrKnap\Profiler; -echo something(new Profiler()); -echo something(new NullProfiler()); +echo doSomething(new Profiler()); +echo doSomething(new NullProfiler()); ``` ### Cascade profiling @@ -59,7 +59,7 @@ namespace PetrKnap\Profiler; echo (new Profiler())->profile(function (ProfilerInterface $profiler): string { // do something before something - return something($profiler); + return doSomething($profiler); })->process(fn (ProfileInterface $profile) => printf( 'It took %.1f s to do something before something and something, there are %d children profiles.', $profile->getDuration(), @@ -67,6 +67,23 @@ echo (new Profiler())->profile(function (ProfilerInterface $profiler): string { )); ``` +### Tick listening + +For greater precision, you can use measurements at each `N` tick. +This will result in **very detailed code tracking**, which can degrade the performance of the monitored application. + +```php +declare(ticks=3); // this declaration is important (N=3) + +namespace PetrKnap\Profiler; + +$profiling = Profiling::start(listenToTicks: true); +doSomething(new NullProfiler()); +$profile = $profiling->finish(); + +printf('There are %d memory usage records.', count($profile->getMemoryUsages())); +``` + --- Run `composer require petrknap/profiler` to install it. diff --git a/src/Profile.php b/src/Profile.php index 6bd2cd6..5d437db 100644 --- a/src/Profile.php +++ b/src/Profile.php @@ -18,6 +18,8 @@ */ final class Profile implements ProcessableProfileInterface, ProfileWithOutputInterface { + public const DO_NOT_LISTEN_TO_TICKS = false; + private const MICROTIME_FORMAT = '%.6f'; private ProfileState $state; @@ -25,6 +27,10 @@ final class Profile implements ProcessableProfileInterface, ProfileWithOutputInt private OptionalInt $memoryUsageBefore; private OptionalFloat $timeAfter; private OptionalInt $memoryUsageAfter; + /** + * @var array + */ + private array $memoryUsages = []; /** * @var array */ @@ -34,8 +40,9 @@ final class Profile implements ProcessableProfileInterface, ProfileWithOutputInt */ private Optional $outputOption; - public function __construct() - { + public function __construct( + private readonly bool $listenToTicks = self::DO_NOT_LISTEN_TO_TICKS, + ) { $this->state = ProfileState::Created; $this->timeBefore = OptionalFloat::empty(); $this->memoryUsageBefore = OptionalInt::empty(); @@ -61,6 +68,7 @@ public function start(): void $this->state = ProfileState::Started; $this->timeBefore = OptionalFloat::of(microtime(as_float: true)); $this->memoryUsageBefore = OptionalInt::of(memory_get_usage(real_usage: true)); + $this->registerTickHandler(); } /** @@ -68,6 +76,8 @@ public function start(): void */ public function finish(): void { + $this->unregisterTickHandler(); + if ($this->state !== ProfileState::Started) { throw new Exception\ProfileCouldNotBeFinished(); } @@ -77,6 +87,25 @@ public function finish(): void $this->memoryUsageAfter = OptionalInt::of(memory_get_usage(real_usage: true)); } + public function registerTickHandler(): void + { + if ($this->listenToTicks) { + register_tick_function([$this, 'tickHandler']); + } + } + + public function unregisterTickHandler(): void + { + if ($this->listenToTicks) { + unregister_tick_function([$this, 'tickHandler']); + } + } + + public function tickHandler(): void + { + $this->memoryUsages[sprintf(self::MICROTIME_FORMAT, microtime(as_float: true))] = memory_get_usage(real_usage: true); + } + /** * @throws Exception\ProfileCouldNotBeProcessed */ @@ -131,6 +160,7 @@ public function getMemoryUsages(): array $memoryUsages = [ sprintf(self::MICROTIME_FORMAT, $this->timeBefore->orElseThrow()) => $this->memoryUsageBefore->orElseThrow(), sprintf(self::MICROTIME_FORMAT, $this->timeAfter->orElseThrow()) => $this->memoryUsageAfter->orElseThrow(), + ...$this->memoryUsages, ]; foreach ($this->children as $child) { $memoryUsages = array_merge( diff --git a/src/Profiler.php b/src/Profiler.php index ad05ac8..815a7af 100644 --- a/src/Profiler.php +++ b/src/Profiler.php @@ -6,9 +6,14 @@ /* final */class Profiler implements ProfilerInterface { + public function __construct( + private readonly bool $listenToTicks = Profile::DO_NOT_LISTEN_TO_TICKS, + ) { + } + public function profile(callable $callable): ProcessableProfileInterface & ProfileWithOutputInterface { - $profiling = Profiling::start(); + $profiling = Profiling::start($this->listenToTicks); $output = $callable(Profiling::createNestedProfiler($profiling)); /** @var Profile $profile */ $profile = $profiling->finish(); diff --git a/src/Profiling.php b/src/Profiling.php index 6664ab0..3a55e63 100644 --- a/src/Profiling.php +++ b/src/Profiling.php @@ -11,15 +11,17 @@ final class Profiling */ private function __construct( private readonly Profile $profile, + private readonly bool $listenToTicks, ) { } - public static function start(): self - { - $profile = new Profile(); + public static function start( + bool $listenToTicks = Profile::DO_NOT_LISTEN_TO_TICKS, + ): self { + $profile = new Profile($listenToTicks); $profile->start(); - return new self($profile); + return new self($profile, $listenToTicks); } /** @@ -41,13 +43,17 @@ public function finish(): ProfileInterface */ public static function createNestedProfiler(Profiling $profiling): ProfilerInterface { - return new class ($profiling->profile) extends Profiler { + return new class ($profiling->profile, $profiling->listenToTicks) extends Profiler { /** * @param Profile $parentProfile */ public function __construct( private readonly Profile $parentProfile, + bool $listenToTicks, ) { + parent::__construct( + listenToTicks: $listenToTicks, + ); } public function profile(callable $callable): ProcessableProfileInterface & ProfileWithOutputInterface @@ -56,10 +62,15 @@ public function profile(callable $callable): ProcessableProfileInterface & Profi throw new Exception\ParentProfileIsNotStarted(); } - $profile = parent::profile($callable); - $this->parentProfile->addChild($profile); + $this->parentProfile->unregisterTickHandler(); + try { + $profile = parent::profile($callable); + $this->parentProfile->addChild($profile); - return $profile; + return $profile; + } finally { + $this->parentProfile->registerTickHandler(); + } } }; } diff --git a/tests/ProfileTest.php b/tests/ProfileTest.php index 62df1d7..e1c7584 100644 --- a/tests/ProfileTest.php +++ b/tests/ProfileTest.php @@ -1,9 +1,11 @@ getChildren()); } + + #[DataProvider('dataListensToTicks')] + public function testListensToTicks(bool|null $shouldItListen): void + { + $profile = $shouldItListen === null ? new Profile() : new Profile(listenToTicks: $shouldItListen); + $profile->start(); + for ($i = 0; $i < 5; $i++) { + $i = (fn (int $i): int => $i)($i); + } + $profile->finish(); + + self::assertCount($shouldItListen === true ? 9 : 2, $profile->getMemoryUsages()); + } + + public static function dataListensToTicks(): array + { + return [ + 'default' => [null], + 'yes' => [true], + 'no' => [false], + ]; + } } diff --git a/tests/ReadmeTest.php b/tests/ReadmeTest.php index 87897ba..d26f0f1 100644 --- a/tests/ReadmeTest.php +++ b/tests/ReadmeTest.php @@ -24,6 +24,7 @@ public static function getExpectedOutputsOfPhpExamples(): iterable 'long-term-profiling' => '', 'how-to-enable-disable-it' => 'It took 0.0 s to do something.' . 'something' . 'something', 'cascade-profiling' => 'It took 0.0 s to do something.' . 'It took 0.0 s to do something before something and something, there are 1 children profiles.' . 'something', + 'tick-listening' => 'There are 3 memory usage records.', ]; } }