Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feature for Timer to measure callable performance #6321

Merged
merged 15 commits into from
Aug 5, 2022
12 changes: 9 additions & 3 deletions system/Common.php
Original file line number Diff line number Diff line change
Expand Up @@ -1076,19 +1076,25 @@ function stringify_attributes($attributes, bool $js = false): string
if (! function_exists('timer')) {
/**
* A convenience method for working with the timer.
* If no parameter is passed, it will return the timer instance,
* otherwise will start or stop the timer intelligently.
* If no parameter is passed, it will return the timer instance.
* If callable is passed, it measures time of callable and
* returns its return value if any.
* Otherwise will start or stop the timer intelligently.
*
* @return mixed|Timer
*/
function timer(?string $name = null)
function timer(?string $name = null, ?callable $callable = null)
{
$timer = Services::timer();

if (empty($name)) {
return $timer;
}

if ($callable !== null) {
return $timer->record($name, $callable);
}

if ($timer->has($name)) {
return $timer->stop($name);
}
Expand Down
18 changes: 18 additions & 0 deletions system/Debug/Timer.php
Original file line number Diff line number Diff line change
Expand Up @@ -126,4 +126,22 @@ public function has(string $name): bool
{
return array_key_exists(strtolower($name), $this->timers);
}

/**
* Executes callable and measures its time.
* Returns its return value if any.
*
* @param string $name The name of the timer
* @param callable $callable callable to be executed
*
* @return object|resource|array|string|int|float|bool|null
*/
public function record(string $name, callable $callable)
{
$this->start($name);
$returnValue = $callable();
$this->stop($name);

return $returnValue;
}
}
105 changes: 105 additions & 0 deletions tests/system/Debug/TimerTest.php
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,8 @@
namespace CodeIgniter\Debug;

use CodeIgniter\Test\CIUnitTestCase;
use RuntimeException;
use Throwable;
kenjis marked this conversation as resolved.
Show resolved Hide resolved

/**
* @internal
Expand Down Expand Up @@ -121,4 +123,107 @@ public function testReturnsNullGettingElapsedTimeOfNonTimer()

$this->assertNull($timer->getElapsedTime('test1'));
}

/**
* @timeLimit 1.5
*/
kenjis marked this conversation as resolved.
Show resolved Hide resolved
public function testRecordFunctionNoReturn()
{
$timer = new Timer();
$returnValue = $timer->record('longjohn', static function () { sleep(1); });
paulbalandan marked this conversation as resolved.
Show resolved Hide resolved
kenjis marked this conversation as resolved.
Show resolved Hide resolved

$this->assertGreaterThanOrEqual(1.0, $timer->getElapsedTime('longjohn'));
kenjis marked this conversation as resolved.
Show resolved Hide resolved
$this->assertNull($returnValue);
}

/**
* @timeLimit 1.5
*/
public function testRecordFunctionWithReturn()
{
$timer = new Timer();
$returnValue = $timer->record('longjohn', static function () {
sleep(1);

return 'test';
});

$this->assertGreaterThanOrEqual(1.0, $timer->getElapsedTime('longjohn'));
$this->assertSame('test', $returnValue);
}

public function testRecordArrowFunction()
{
$timer = new Timer();
$returnValue = $timer->record('longjohn', static fn () => strlen('CI4'));

$this->assertLessThanOrEqual(1.0, $timer->getElapsedTime('longjohn'));
kenjis marked this conversation as resolved.
Show resolved Hide resolved
$this->assertSame(3, $returnValue);
}

public function testRecordThrowsException()
{
$this->expectException(RuntimeException::class);

$timer = new Timer();
$timer->record('ex', static function () { throw new RuntimeException(); });
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have a question. If by mistake I made the callable throw an exception, then how can I get the elapsed time since $this->stop($name) will not be called? Should the invocation of the callable be wrapped in a try-finally ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If an exception is thrown and you don't catch it, then I think you might have other problems than worrying about the time stoppage.

But you also have a point. It does not handle the case of purposely catching exceptions for error handling.

try {
    $benchmark->record('test', 'func_that_throws');
} catch (Throwable $e) {
    // stop() isn't called yet
}

@kenjis shall we cover this case as well?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if an exception is thrown after $benchmark->start() or in $iterator->run()?

Copy link
Contributor Author

@rumpfc rumpfc Aug 2, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For $iterator->run(), nothing is caught internally. It would not record anything in the report and would go out of the method, ignoring all follow up Closures.

For $benchmark->start(), you would need to call stop() inside the catch or finally block.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think we need try-finally.

An exception should be thrown in an exceptional case, and not recoverable.
Normally, a developer would modify the code to prevent the exception from occurring.

If a developer really wants to know the elapsed time when an exception is thrown, they can catch and measure it by themselves.

}

public function testRecordThrowsErrorOnCallableWithParams()
{
$this->expectException(Throwable::class);
paulbalandan marked this conversation as resolved.
Show resolved Hide resolved

$timer = new Timer();
$timer->record('error', 'strlen');
}

public function testCommonNoNameExpectTimer()
{
$returnValue = timer();

$this->assertInstanceOf(Timer::class, $returnValue);
}

public function testCommonWithNameExpectTimer()
{
$returnValue = timer('test');

$this->assertInstanceOf(Timer::class, $returnValue);
$this->assertTrue($returnValue->has('test'));
}

public function testCommonNoNameCallableExpectTimer()
{
$returnValue = timer(null, static fn () => strlen('CI4'));

$this->assertInstanceOf(Timer::class, $returnValue);
}

/**
* @timeLimit 1.5
*/
kenjis marked this conversation as resolved.
Show resolved Hide resolved
public function testCommonCallableExpectNoReturn()
{
$returnValue = timer('common', static function () { sleep(1); });

$this->assertNotInstanceOf(Timer::class, $returnValue);
$this->assertNull($returnValue);
$this->assertGreaterThanOrEqual(1.0, timer()->getElapsedTime('common'));
kenjis marked this conversation as resolved.
Show resolved Hide resolved
}

/**
* @timeLimit 1.5
*/
public function testCommonCallableExpectWithReturn()
{
$returnValue = timer('common', static function () {
sleep(1);

return strlen('CI4');
});

$this->assertNotInstanceOf(Timer::class, $returnValue);
$this->assertSame(3, $returnValue);
$this->assertGreaterThanOrEqual(1.0, timer()->getElapsedTime('common'));
}
}
1 change: 1 addition & 0 deletions user_guide_src/source/changelogs/v4.3.0.rst
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,7 @@ Enhancements
- SQLite ``BaseConnection::getIndexData()`` now can return pseudo index named ``PRIMARY`` for `AUTOINCREMENT` column, and each returned index data has ``type`` property.
- Added ``spark filter:check`` command to check the filters for a route. See :ref:`Controller Filters <spark-filter-check>` for the details.
- Now **Encryption** can decrypt data encrypted with CI3's Encryption. See :ref:`encryption-compatible-with-ci3`.
- Added method ``Timer::record()`` to measure performance in a callable. Also enhanced common function ``timer()`` to accept optional callable.
- Now ``spark routes`` command shows route names. See :ref:`URI Routing <routing-spark-routes>`.

Changes
Expand Down
14 changes: 14 additions & 0 deletions user_guide_src/source/testing/benchmark.rst
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,20 @@ and stop timers:

.. literalinclude:: benchmark/003.php

If you use very small code blocks to benchmark, you can also use the ``record()`` method. It accepts
paulbalandan marked this conversation as resolved.
Show resolved Hide resolved
a no-parameter callable and measures its execution time. Methods ``start()`` and ``stop()`` will be called
automatically around the function call.

.. literalinclude:: benchmark/010.php

You can also return the callable's return value for further processing.

.. literalinclude:: benchmark/011.php

The same functionality is also available when passing callable to ``timer()`` as second parameter.

.. literalinclude:: benchmark/012.php

Viewing Your Benchmark Points
=============================

Expand Down
11 changes: 11 additions & 0 deletions user_guide_src/source/testing/benchmark/010.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
<?php

$benchmark->record('slow_function', static function () { slow_function('...'); });

/*
* Same as:
*
* $benchmark->start('slow_function');
* slow_function('...');
* $benchmark->stop('slow_function');
*/
13 changes: 13 additions & 0 deletions user_guide_src/source/testing/benchmark/011.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
<?php

$length = $benchmark->record('string length', static fn () => strlen('CI4'));

/*
* $length = 3
*
* Same as:
*
* $benchmark->start('string length');
* $length = strlen('CI4');
* $benchmark->stop('string length');
*/
13 changes: 13 additions & 0 deletions user_guide_src/source/testing/benchmark/012.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
<?php

$length = timer('string length', static fn () => strlen('CI4'));

/*
* $length = 3
*
* Same as:
*
* timer('string length');
* $length = strlen('CI4');
* timer('string length');
*/