Skip to content

Show total slow and fast test time in output #87

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

Open
wants to merge 5 commits into
base: master
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions .gitignore
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
/phpunit.xml
/vendor
/composer.lock
/.phpunit.result.cache
37 changes: 35 additions & 2 deletions src/SpeedTrapListener.php
Original file line number Diff line number Diff line change
Expand Up @@ -63,6 +63,12 @@ class SpeedTrapListener implements TestListener
*/
protected $slow = [];

/**
* Total test execution time so far, in milliseconds
* @var int
*/
protected $totalTime = 0;

public function __construct(array $options = [])
{
$this->enabled = getenv('PHPUNIT_SPEEDTRAP') === 'disabled' ? false : true;
Expand All @@ -87,6 +93,8 @@ public function endTest(Test $test, float $time): void
if ($this->isSlow($timeInMilliseconds, $threshold)) {
$this->addSlowTest($test, $timeInMilliseconds);
}

$this->totalTime += $timeInMilliseconds;
}

/**
Expand Down Expand Up @@ -117,7 +125,8 @@ public function endTestSuite(TestSuite $suite): void

$this->renderHeader();
$this->renderBody();
$this->renderFooter();
$this->renderAnyHiddenSlowTest();
$this->renderStats();
}
}

Expand Down Expand Up @@ -225,7 +234,7 @@ protected function renderBody()
/**
* Renders slowness report footer.
*/
protected function renderFooter()
protected function renderAnyHiddenSlowTest()
{
if ($hidden = $this->getHiddenCount()) {
printf("...and there %s %s more above your threshold hidden from view\n", $hidden == 1 ? 'is' : 'are', $hidden);
Expand Down Expand Up @@ -264,4 +273,28 @@ protected function getSlowThreshold(TestCase $test): int

return isset($ann['method']['slowThreshold'][0]) ? (int) $ann['method']['slowThreshold'][0] : $this->slowThreshold;
}

private function renderStats(): void
{

$totalSlowTimeMs = array_sum($this->slow);
$totalFastTimeMs = $this->totalTime - $totalSlowTimeMs;

$totalFastTimeSeconds = $totalFastTimeMs / 1000;
$totalSlowTimeSeconds = $totalSlowTimeMs / 1000;

echo PHP_EOL;

printf(
" Fast tests: %.1f seconds (%.2f%%)\n",
$totalFastTimeSeconds,
100 * $totalFastTimeMs / $this->totalTime
);

printf(
" Slow tests: %.1f seconds (%.2f%%)\n",
$totalSlowTimeSeconds,
100 * $totalSlowTimeMs / $this->totalTime
);
}
}
132 changes: 132 additions & 0 deletions tests/SpeedTrapListenerTest.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,132 @@
<?php

declare(strict_types=1);

namespace JohnKary\PHPUnit\Listener\Tests;

use JohnKary\PHPUnit\Listener\SpeedTrapListener;
use PHPUnit\Framework\TestCase;
use PHPUnit\Framework\TestListener;
use PHPUnit\Framework\TestSuite;

final class SpeedTrapListenerTest extends TestCase
{
/** @var TestListener */
private $speedTrapListener;

public function setUp(): void
{
parent::setUp();

$this->speedTrapListener = new SpeedTrapListener(['slowThreshold' => 444]);
}

public function testItPrintsSpeedData(): void
{
$testSuite = new TestSuite();
$this->speedTrapListener->startTestSuite($testSuite);
$this->speedTrapListener->startTest($this);

$this->speedTrapListener->endTest($this, 1 /*second*/);

$output = $this->captureOutput(function () use ($testSuite) {
$this->speedTrapListener->endTestSuite($testSuite);
});

self::assertSame(
'

You should really speed up these slow tests (>444ms)...
1. 1000ms to run JohnKary\\\\PHPUnit\\\\Listener\\\\Tests\\\\SpeedTrapListenerTest::testItPrintsSpeedData

Fast tests: 0.0 seconds (0.00%)
Slow tests: 1.0 seconds (100.00%)
Comment on lines +42 to +43
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
Fast tests: 0.0 seconds (0.00%)
Slow tests: 1.0 seconds (100.00%)
Total slow tests duration: 1.0 seconds (100.00%)

I prefer to keep the output minimal and optimized to it's purpose :)

Copy link
Author

Choose a reason for hiding this comment

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

That makes sense. I'll adjust it in a couple of days when I some time, or if you prefer feel free to merge and edit. Thanks.

'
,
$output
);
}


public function testItDisplaysTotalSlowTestTime(): void
{
$testSuite = new TestSuite();

$test1 = new self('test one');
$test2 = new self('test two');

$this->speedTrapListener->startTestSuite($testSuite);
$this->speedTrapListener->startTest($test1);
$this->speedTrapListener->endTest($test1, 2);

$this->speedTrapListener->startTest($test2);
$this->speedTrapListener->endTest($test2, 1.5);

$output = $this->captureOutput(function () use ($testSuite) {
$this->speedTrapListener->endTestSuite($testSuite);
});

self::assertSame(
'

You should really speed up these slow tests (>444ms)...
1. 2000ms to run JohnKary\\\\PHPUnit\\\\Listener\\\\Tests\\\\SpeedTrapListenerTest::test one
2. 1500ms to run JohnKary\\\\PHPUnit\\\\Listener\\\\Tests\\\\SpeedTrapListenerTest::test two

Fast tests: 0.0 seconds (0.00%)
Slow tests: 3.5 seconds (100.00%)
'
,
$output
);
}

public function testItDisplaysTotalSlowAndFastTestTime(): void
{
$testSuite = new TestSuite();

$test1 = new self('slow test one');
$test2 = new self('slow test two');

$fastTest = new self('this one is fast');

$this->speedTrapListener->startTestSuite($testSuite);
$this->speedTrapListener->startTest($test1);
$this->speedTrapListener->endTest($test1, 2 /* duration in seconds */);


$this->speedTrapListener->startTest($test2);
$this->speedTrapListener->endTest($test2, 1.5);

$this->speedTrapListener->startTest($fastTest);
$this->speedTrapListener->endTest($fastTest, 0.4);

$output = $this->captureOutput(function () use ($testSuite) {
$this->speedTrapListener->endTestSuite($testSuite);
});

self::assertSame(
'

You should really speed up these slow tests (>444ms)...
1. 2000ms to run JohnKary\\\\PHPUnit\\\\Listener\\\\Tests\\\\SpeedTrapListenerTest::slow test one
2. 1500ms to run JohnKary\\\\PHPUnit\\\\Listener\\\\Tests\\\\SpeedTrapListenerTest::slow test two

Fast tests: 0.4 seconds (10.26%)
Slow tests: 3.5 seconds (89.74%)
'
,
$output
);

self::assertEqualsWithDelta(10.26, 100*0.4/(0.4+3.5), 0.01);
self::assertEqualsWithDelta(89.74, 100*3.5/(0.4+3.5), 0.01);
}

private function captureOutput(\Closure $closure): string
{
ob_start();
$closure();
return ob_get_clean();
}
}