Merge pull request #220 from ergebnis/fix/formatter

Fix: Bring duration formatting in line with `phpunit/php-timer`
ergebnis · Feb 11, 2023 · 2a1b56f · 2a1b56f
2 parents 9c256db + 9a2e396
commit 2a1b56f
Show file tree

Hide file tree

Showing 10 changed files with 152 additions and 93 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -13,6 +13,7 @@ For a full diff see [`1.0.0...main`][1.0.0...main].
 - Allowed configuring the maximum duration via `maximum-duration` parameter ([#212]), by [@localheinz]
 - Allowed configuring the maximum count via `maximum-count` parameter ([#217]), by [@localheinz]
 - Marked classes and interfaces as internal ([#219]), by [@localheinz]
+- Brought duration formatting in line with `phpunit/php-timer` ([#220]), by [@localheinz]
 
 ### Fixed
 
@@ -84,5 +85,6 @@ For a full diff see [`7afa59c...1.0.0`][7afa59c...1.0.0].
 [#217]: https://github.com/ergebnis/phpunit-slow-test-detector/pull/217
 [#218]: https://github.com/ergebnis/phpunit-slow-test-detector/pull/218
 [#219]: https://github.com/ergebnis/phpunit-slow-test-detector/pull/219
+[#220]: https://github.com/ergebnis/phpunit-slow-test-detector/pull/220
 
 [@localheinz]: https://github.com/localheinz
diff --git a/README.md b/README.md
@@ -109,26 +109,33 @@ vendor/bin/phpunit
 
 When the extension has detected slow tests, it will report them:
 
-```sh
+```txt
 PHPUnit 10.0.0 by Sebastian Bergmann and contributors.
 
 Runtime:       PHP 8.1.0
-Configuration: test/Example/phpunit.xml
-Random Seed:   1611649366
+Configuration: test/EndToEnd/Default/phpunit.xml
+Random Seed:   1676103726
 
-.....                                                                                                                                                                                                                                                                                                             5 / 5 (100%)
+.............                                                                                                                                                                                                                                                                                                   13 / 13 (100%)
 
-Detected 4 tests that took longer than expected.
+Detected 11 tests that took longer than expected.
 
-1,012 ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\Example\SleeperTest::testSleeperSleepsOneSecond
-  755 ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\Example\SleeperTest::testSleeperSleepsThreeQuartersOfASecond
-  503 ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\Example\SleeperTest::testSleeperSleepsHalfASeconds
+1.605 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#9
+1.505 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#8
+1.401 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#7
+1.301 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#6
+1.200 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#5
+1.105 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#4
+1.000 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#3
+0.903 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#2
+0.802 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#1
+0.703 (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#0
 
 There is one additional slow test that is not listed here.
 
-Time: 00:02.563, Memory: 10.00 MB
+Time: 00:12.601, Memory: 8.00 MB
 
-OK (5 tests, 5 assertions)
+OK (13 tests, 13 assertions)
 ```
 
 ## Changelog

diff --git a/psalm-baseline.xml b/psalm-baseline.xml
@@ -5,6 +5,16 @@
       <code>Extension</code>
     </UnusedClass>
   </file>
+  <file src="src/Formatter/DefaultDurationFormatter.php">
+    <InvalidOperand>
+      <code>$duration-&gt;seconds() * 1000 + $duration-&gt;nanoseconds() / 1000000</code>
+      <code>$durationInMilliseconds - $hoursInMilliseconds</code>
+      <code>$durationInMilliseconds - $hoursInMilliseconds</code>
+      <code>$durationInMilliseconds / 60</code>
+      <code>$durationInMilliseconds / 60</code>
+      <code>($durationInMilliseconds - $hoursInMilliseconds - $minutesInMilliseconds) / 1000</code>
+    </InvalidOperand>
+  </file>
   <file src="src/Subscriber/TestPassedSubscriber.php">
     <InternalClass>
       <code>Metadata\Annotation\Parser\Registry::getInstance()</code>
@@ -76,9 +86,9 @@
       <code>InvalidMaximumDurationTest</code>
     </UnusedClass>
   </file>
-  <file src="test/Unit/Formatter/ToMillisecondsDurationFormatterTest.php">
+  <file src="test/Unit/Formatter/DefaultDurationFormatterTest.php">
     <UnusedClass>
-      <code>ToMillisecondsDurationFormatterTest</code>
+      <code>DefaultDurationFormatterTest</code>
     </UnusedClass>
   </file>
   <file src="test/Unit/MaximumCountTest.php">

diff --git a/src/Extension.php b/src/Extension.php
@@ -38,7 +38,7 @@ public function bootstrap(
         $collector = new Collector\DefaultCollector();
 
         $reporter = new Reporter\DefaultReporter(
-            new Formatter\ToMillisecondsDurationFormatter(),
+            new Formatter\DefaultDurationFormatter(),
             $maximumDuration,
             $maximumCount,
         );

diff --git a/src/Formatter/DefaultDurationFormatter.php b/src/Formatter/DefaultDurationFormatter.php
@@ -0,0 +1,67 @@
+<?php
+
+declare(strict_types=1);
+
+/**
+ * Copyright (c) 2021-2023 Andreas Möller
+ *
+ * For the full copyright and license information, please view
+ * the LICENSE.md file that was distributed with this source code.
+ *
+ * @see https://github.com/ergebnis/phpunit-slow-test-detector
+ */
+
+namespace Ergebnis\PHPUnit\SlowTestDetector\Formatter;
+
+use PHPUnit\Event;
+use SebastianBergmann\Timer;
+
+/**
+ * @psalm-immutable
+ */
+final class DefaultDurationFormatter implements DurationFormatter
+{
+    /**
+     * @see https://github.com/sebastianbergmann/php-timer/blob/6.0.0/src/Duration.php
+     */
+    public function format(Event\Telemetry\Duration $duration): string
+    {
+        $durationInMilliseconds = $duration->seconds() * 1000 + $duration->nanoseconds() / 1000000;
+
+        $hours = (int) \floor($durationInMilliseconds / 60 / 60 / 1000);
+        $hoursInMilliseconds = $hours * 60 * 60 * 1000;
+
+        $minutes = ((int) \floor($durationInMilliseconds / 60 / 1000)) % 60;
+        $minutesInMilliseconds = $minutes * 60 * 1000;
+
+        $seconds = (int) \floor(($durationInMilliseconds - $hoursInMilliseconds - $minutesInMilliseconds) / 1000);
+        $secondsInMilliseconds = $seconds * 1000;
+
+        $milliseconds = (int) ($durationInMilliseconds - $hoursInMilliseconds - $minutesInMilliseconds - $secondsInMilliseconds);
+
+        if (0 < $hours) {
+            return \sprintf(
+                '%d:%02d:%02d.%03d',
+                $hours,
+                $minutes,
+                $seconds,
+                $milliseconds,
+            );
+        }
+
+        if (0 < $minutes) {
+            return \sprintf(
+                '%d:%02d.%03d',
+                $minutes,
+                $seconds,
+                $milliseconds,
+            );
+        }
+
+        return \sprintf(
+            '%d.%03d',
+            $seconds,
+            $milliseconds,
+        );
+    }
+}
diff --git a/src/Formatter/ToMillisecondsDurationFormatter.php b/src/Formatter/ToMillisecondsDurationFormatter.php
diff --git a/test/EndToEnd/Default/test.phpt b/test/EndToEnd/Default/test.phpt
@@ -25,16 +25,16 @@ Random Seed:   %s
 
 Detected 11 tests that took longer than expected.
 
-1,6%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#9
-1,5%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#8
-1,4%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#7
-1,3%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#6
-1,2%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#5
-1,1%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#4
-1,0%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#3
-  9%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#2
-  8%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#1
-  7%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#0
+1.6%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#9
+1.5%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#8
+1.4%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#7
+1.3%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#6
+1.2%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#5
+1.1%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#4
+1.0%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#3
+0.9%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#2
+0.8%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#1
+0.7%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Default\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#0
 
 There is one additional slow test that is not listed here.
 

diff --git a/test/EndToEnd/MaximumCount/Five/test.phpt b/test/EndToEnd/MaximumCount/Five/test.phpt
@@ -25,11 +25,11 @@ Random Seed:   %s
 
 Detected 7 tests that took longer than expected.
 
-1,2%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#5
-1,1%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#4
-1,0%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#3
-  9%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#2
-  8%s ms (500 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#1
+1.2%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#5
+1.1%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#4
+1.0%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#3
+0.9%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#2
+0.8%s (0.500) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumCount\Five\SleeperTest::testSleeperSleepsLongerThanDefaultMaximumDurationWithDataProvider#1
 
 There are 2 additional slow tests that are not listed here.
 

diff --git a/test/EndToEnd/MaximumDuration/Fifty/test.phpt b/test/EndToEnd/MaximumDuration/Fifty/test.phpt
@@ -25,11 +25,11 @@ Random Seed:   %s
 
 Detected 5 tests that took longer than expected.
 
-1%s ms (50 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromSlowThresholdAnnotation
-1%s ms (50 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsWithDocBlockWithSlowThresholdAnnotationWhereValueIsNotAnInt
- 9%s ms (50 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsShorterThanMaximumDurationFromSlowThresholdAnnotation
- 8%s ms (50 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsWithDocBlockWithoutSlowThresholdAnnotation
- 6%s ms (50 ms) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsJustAboveDefaultMaximumDuration
+0.1%s (0.050) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromSlowThresholdAnnotation
+0.1%s (0.050) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsWithDocBlockWithSlowThresholdAnnotationWhereValueIsNotAnInt
+0.0%s (0.050) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsShorterThanMaximumDurationFromSlowThresholdAnnotation
+0.0%s (0.050) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsWithDocBlockWithoutSlowThresholdAnnotation
+0.0%s (0.050) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\MaximumDuration\Fifty\SleeperTest::testSleeperSleepsJustAboveDefaultMaximumDuration
 
 Time: %s, Memory: %s
 

diff --git a/...r/ToMillisecondsDurationFormatterTest.php → ...ormatter/DefaultDurationFormatterTest.php b/...r/ToMillisecondsDurationFormatterTest.php → ...ormatter/DefaultDurationFormatterTest.php
@@ -21,9 +21,9 @@
 /**
  * @internal
  *
- * @covers \Ergebnis\PHPUnit\SlowTestDetector\Formatter\ToMillisecondsDurationFormatter
+ * @covers \Ergebnis\PHPUnit\SlowTestDetector\Formatter\DefaultDurationFormatter
  */
-final class ToMillisecondsDurationFormatterTest extends Framework\TestCase
+final class DefaultDurationFormatterTest extends Framework\TestCase
 {
     use Test\Util\Helper;
 
@@ -34,7 +34,7 @@ public function testFormatFormats(
         Event\Telemetry\Duration $duration,
         string $formattedDuration,
     ): void {
-        $formatter = new Formatter\ToMillisecondsDurationFormatter();
+        $formatter = new Formatter\DefaultDurationFormatter();
 
         self::assertSame($formattedDuration, $formatter->format($duration));
     }
@@ -50,49 +50,56 @@ public static function provideDurationAndFormattedDuration(): array
                     0,
                     0,
                 ),
-                '0 ms',
+                '0.000',
             ],
-            'nanoseconds-rounded-down' => [
+            'milliseconds' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
                     0,
-                    499_999,
+                    123_999_000,
                 ),
-                '0 ms',
+                '0.123',
             ],
-            'nanoseconds-rounded-up' => [
+            'seconds-digits-one' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
-                    0,
-                    500_000,
+                    1,
+                    234_456_789,
                 ),
-                '1 ms',
+                '1.234',
             ],
-            'milliseconds-one' => [
+            'seconds-digits-two' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
-                    0,
-                    1_000_000,
+                    12,
+                    345_678_912,
                 ),
-                '1 ms',
+                '12.345',
             ],
-            'milliseconds-hundreds' => [
+            'minutes-digits-one' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
-                    0,
-                    123 * 1_000_000,
+                    1 * 60 + 23,
+                    456_789_012,
                 ),
-                '123 ms',
+                '1:23.456',
             ],
-            'seconds' => [
+            'minutes-digits-two' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
-                    1,
-                    1_000_000,
+                    12 * 60 + 34,
+                    567_890_123,
                 ),
-                '1,001 ms',
+                '12:34.567',
             ],
-            'thousands-of-seconds' => [
+            'hours-digits-one' => [
                 Event\Telemetry\Duration::fromSecondsAndNanoseconds(
-                    1_234,
+                    60 * 60 + 23 * 60 + 45,
                     567_890_123,
                 ),
-                '1,234,568 ms',
+                '1:23:45.567',
+            ],
+            'hours-digits-two' => [
+                Event\Telemetry\Duration::fromSecondsAndNanoseconds(
+                    12 * 60 * 60 + 34 * 60 + 56,
+                    789_012_345,
+                ),
+                '12:34:56.789',
             ],
         ];
     }