Skip to content

Commit

Permalink
feat: implemented support for listening to ticks
Browse files Browse the repository at this point in the history
  • Loading branch information
petrknap committed Oct 12, 2024
1 parent 8d84225 commit bfe4bb1
Show file tree
Hide file tree
Showing 6 changed files with 105 additions and 18 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 tick.
This will result in **very detailed code tracking**, which can degrade the performance of the monitored application.

```php
declare(ticks=1); // this declaration is important

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
33 changes: 31 additions & 2 deletions src/Profile.php
Original file line number Diff line number Diff line change
Expand Up @@ -18,13 +18,19 @@
*/
final class Profile implements ProcessableProfileInterface, ProfileWithOutputInterface
{
public const DO_NOT_LISTEN_TO_TICKS = false;

private const MICROTIME_FORMAT = '%.6f';

private ProfileState $state;
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 @@ -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();
Expand All @@ -54,6 +61,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->startTicker();
}

/**
Expand All @@ -63,11 +71,31 @@ public function finish(): void
{
Exception\ProfileCouldNotBeFinished::throwIf($this->state !== ProfileState::Started);

$this->stopTicker();
$this->state = ProfileState::Finished;
$this->timeAfter = OptionalFloat::of(microtime(as_float: true));
$this->memoryUsageAfter = OptionalInt::of(memory_get_usage(real_usage: true));
}

public function stopTicker(): void
{
if ($this->listenToTicks) {
unregister_tick_function([$this, 'tick']);
}
}

public function startTicker(): void
{
if ($this->listenToTicks) {
register_tick_function([$this, 'tick']);
}
}

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

/**
* @throws Exception\ProfileCouldNotBeProcessed
*/
Expand Down Expand Up @@ -120,6 +148,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(
Expand Down
24 changes: 17 additions & 7 deletions src/Profiler.php
Original file line number Diff line number Diff line change
Expand Up @@ -11,16 +11,26 @@
*/
protected Profile|null $parentProfile = null;

public function __construct(
private readonly bool $listenToTicks = Profile::DO_NOT_LISTEN_TO_TICKS,
) {
}

public function profile(callable $callable): ProcessableProfileInterface & ProfileWithOutputInterface
{
$profiling = Profiling::start();
$output = $callable($profiling->createNestedProfiler());
/** @var Profile<mixed> $profile */
$profile = $profiling->finish();
$profile->setOutput($output);
$this->parentProfile?->stopTicker();
try {
$profiling = Profiling::start($this->listenToTicks);
$output = $callable($profiling->createNestedProfiler());
/** @var Profile<mixed> $profile */
$profile = $profiling->finish();
$profile->setOutput($output);

$this->parentProfile?->addChild($profile);
$this->parentProfile?->addChild($profile);

return $profile; // @phpstan-ignore return.type
return $profile; // @phpstan-ignore return.type
} finally {
$this->parentProfile?->startTicker();
}
}
}
16 changes: 11 additions & 5 deletions src/Profiling.php
Original file line number Diff line number Diff line change
Expand Up @@ -13,15 +13,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 @@ -44,13 +46,17 @@ public function createNestedProfiler(): ProfilerInterface
{
Exception\ProfilingHasBeenAlreadyFinished::throwIf($this->wasFinished);

return new class ($this->profile) extends Profiler {
return new class ($this->listenToTicks, $this->profile) extends Profiler {
/**
* @param Profile<mixed> $parentProfile
*/
public function __construct(
bool $listenToTicks,
Profile $parentProfile,
) {
parent::__construct(
listenToTicks: $listenToTicks,
);
$this->parentProfile = $parentProfile;
}
};
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 4 memory usage records.',
];
}
}

0 comments on commit bfe4bb1

Please sign in to comment.