Skip to content

Commit

Permalink
Merge pull request #3 from petrknap/ticker
Browse files Browse the repository at this point in the history
Implemented support for listening to ticks
  • Loading branch information
petrknap authored Oct 14, 2024
2 parents 7e55165 + 7afe0a3 commit 8e845bd
Show file tree
Hide file tree
Showing 7 changed files with 130 additions and 15 deletions.
25 changes: 21 additions & 4 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -59,14 +59,31 @@ 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(),
count($profile->getChildren()),
));
```

### 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.
Expand Down
14 changes: 14 additions & 0 deletions src/Exception/ProfileCouldNotRegisterTickHandler.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
<?php

declare(strict_types=1);

namespace PetrKnap\Profiler\Exception;

use LogicException;

/**
* @internal exception should never be thrown out
*/
final class ProfileCouldNotRegisterTickHandler extends LogicException implements ProfileException
{
}
47 changes: 45 additions & 2 deletions src/Profile.php
Original file line number Diff line number Diff line change
Expand Up @@ -18,14 +18,21 @@
*/
final class Profile implements ProcessableProfileInterface, ProfileWithOutputInterface
{
public const DO_NOT_LISTEN_TO_TICKS = false;

private const MICROTIME_FORMAT = '%.6f';
private const SORTED_BY_TIME = true;

private ProfileState $state;
private bool|null $isListeningToTicks;
private OptionalFloat $timeBefore;
private OptionalInt $memoryUsageBefore;
private OptionalFloat $timeAfter;
private OptionalInt $memoryUsageAfter;
/**
* @var array<numeric-string, int>
*/
private array $memoryUsages = [];
/**
* @var array<ProfileInterface>
*/
Expand All @@ -35,16 +42,23 @@ final class Profile implements ProcessableProfileInterface, ProfileWithOutputInt
*/
private Optional $outputOption;

public function __construct()
{
public function __construct(
bool $listenToTicks = self::DO_NOT_LISTEN_TO_TICKS,
) {
$this->state = ProfileState::Created;
$this->isListeningToTicks = $listenToTicks ? false : null;
$this->timeBefore = OptionalFloat::empty();
$this->memoryUsageBefore = OptionalInt::empty();
$this->timeAfter = OptionalFloat::empty();
$this->memoryUsageAfter = OptionalInt::empty();
$this->outputOption = Optional::empty();
}

public function __destruct()
{
$this->unregisterTickHandler();
}

public function getState(): ProfileState
{
return $this->state;
Expand All @@ -62,13 +76,17 @@ 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();
}

/**
* @throws Exception\ProfileCouldNotBeFinished
*/
public function finish(): void
{
$this->unregisterTickHandler();

if ($this->state !== ProfileState::Started) {
throw new Exception\ProfileCouldNotBeFinished();
}
Expand All @@ -78,6 +96,30 @@ public function finish(): void
$this->memoryUsageAfter = OptionalInt::of(memory_get_usage(real_usage: true));
}

/**
* @throws Exception\ProfileCouldNotRegisterTickHandler
*/
public function registerTickHandler(): void
{
if ($this->isListeningToTicks === false) {
register_tick_function([$this, 'tickHandler']) or throw new Exception\ProfileCouldNotRegisterTickHandler();
$this->isListeningToTicks = true;
}
}

public function unregisterTickHandler(): void
{
if ($this->isListeningToTicks === true) {
unregister_tick_function([$this, 'tickHandler']);
$this->isListeningToTicks = false;
}
}

public function tickHandler(): void
{
$this->memoryUsages[sprintf(self::MICROTIME_FORMAT, microtime(as_float: true))] = memory_get_usage(real_usage: true);
}

/**
* @throws Exception\ProfileCouldNotBeProcessed
*/
Expand Down Expand Up @@ -132,6 +174,7 @@ public function getMemoryUsages(bool $sortedByTime = self::SORTED_BY_TIME): arra
return self::expandRecords(
[
sprintf(self::MICROTIME_FORMAT, $this->timeBefore->orElseThrow()) => $this->memoryUsageBefore->orElseThrow(),
...$this->memoryUsages,
sprintf(self::MICROTIME_FORMAT, $this->timeAfter->orElseThrow()) => $this->memoryUsageAfter->orElseThrow(),
],
$this->children,
Expand Down
7 changes: 6 additions & 1 deletion src/Profiler.php
Original file line number Diff line number Diff line change
Expand Up @@ -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<mixed> $profile */
$profile = $profiling->finish();
Expand Down
27 changes: 19 additions & 8 deletions src/Profiling.php
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

/**
Expand All @@ -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<mixed> $parentProfile
*/
public function __construct(
private readonly Profile $parentProfile,
bool $listenToTicks,
) {
parent::__construct(
listenToTicks: $listenToTicks,
);
}

public function profile(callable $callable): ProcessableProfileInterface & ProfileWithOutputInterface
Expand All @@ -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();
}
}
};
}
Expand Down
24 changes: 24 additions & 0 deletions tests/ProfileTest.php
Original file line number Diff line number Diff line change
@@ -1,9 +1,11 @@
<?php

declare(strict_types=1);
declare(ticks=1);

namespace PetrKnap\Profiler;

use PHPUnit\Framework\Attributes\DataProvider;
use PHPUnit\Framework\TestCase;

final class ProfileTest extends TestCase
Expand All @@ -23,4 +25,26 @@ public function testAddsChildren(): void

self::assertSame([$child1, $child2], $parent->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],
];
}
}
1 change: 1 addition & 0 deletions tests/ReadmeTest.php
Original file line number Diff line number Diff line change
Expand Up @@ -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.',
];
}
}

0 comments on commit 8e845bd

Please sign in to comment.