Consistently include test setup and teardown in duration measurement

Co-authored-by: Andreas Möller <[email protected]>
Co-authored-by: Michael Voříšek <[email protected]>

Author: mvorisek

CHANGELOG.md

@@ -8,6 +8,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 
 For a full diff see [`2.8.0...main`][2.8.0...main].
 
+### Changed
+
+- Consistently included test setup and teardown in duration measurement ([#380]), by [@localheinz] and [@mvorisek]
+
 ### Fixed
 
 - Required at least `phpunit/phpunit:^7.5.0` ([#448]), by [@localheinz]

README.md

@@ -376,7 +376,7 @@ When using `phpunit/phpunit:^7.5.0`, `phpunit/phpunit:^8.5.19`, or `phpunit/phpu
 
 The hooks event system supports eleven hook methods that `phpunit/phpunit` invokes during the execution of tests.
 
-When the extension uses the hooks event system, it uses the [`PHPUnit\Runner\AfterSuccessfulTestHook`](https://github.com/sebastianbergmann/phpunit/blob/8.5.19/src/Runner/Hook/AfterSuccessfulTestHook.php#L12-L15), which receives the [duration of invoking `PHPUnit\Framework\TestCase::runBare()` and more](https://github.com/sebastianbergmann/phpunit/blob/8.5.19/src/Framework/TestResult.php#L671-L754).
+When the extension uses the hooks event system, it uses the [`PHPUnit\Runner\AfterTestHook`](https://github.com/sebastianbergmann/phpunit/blob/7.5.0/src/Runner/Hook/AfterTestHook.php#L12-L21), which receives the [duration of invoking `PHPUnit\Framework\TestCase::runBare()` and more](https://github.com/sebastianbergmann/phpunit/blob/8.5.19/src/Framework/TestResult.php#L671-L754).
 
 When `phpunit/phpunit` invokes `PHPUnit\Framework\TestCase::runBare()`, it will invoke the following methods before the first test method in the class:
 
@@ -405,7 +405,28 @@ When using `phpunit/phpunit:^10.0.0`, the extension uses the new event system of
 
 The new event system supports a wide range of events that `phpunit/phpunit` emits during the execution of tests.
 
-When the extension uses the new event system, it uses and subscribes to the [`PHPUnit\Event\Test\Prepared`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Event/Events/Test/Lifecycle/Prepared.php#L22-L50) and [`PHPUnit\Event\Test\Passed`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Event/Events/Test/Outcome/Passed.php#L22-L50) events and measures the [duration between the points in time when `phpunit/phpunit` emits the former and the latter](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L614-L666).
+When the extension uses the new event system, it uses and subscribes to the [`PHPUnit\Event\Test\PreparationStarted`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Event/Events/Test/Lifecycle/PreparationStarted.php#L22-L50) and [`PHPUnit\Event\Test\Finished`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Event/Events/Test/Lifecycle/Finished.php#L22-L57) events and measures the duration between the points in time when `phpunit/phpunit` emits the former and the latter.
+
+When `phpunit/phpunit` invokes `PHPUnit\Framework\TestCase::runBare()`, it will invoke the following methods before the first test method in the class:
+
+- [`PHPUnit\Framework\TestCase::setUpBeforeClass()` and methods annotated with `@beforeClass`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L602-L604)
+
+When `phpunit/phpunit` invokes `PHPUnit\Framework\TestCase::runBare()`, it will invoke the following methods before every test method in the class:
+
+- [`PHPUnit\Framework\TestCase::setUp()` and methods annotated with `@before`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L611)
+- [`PHPUnit\Framework\TestCase::assertPreConditions()`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L612)
+
+When `phpunit/phpunit` invokes `PHPUnit\Framework\TestCase::runBare()`, it will invoke the following methods after every test method in the class:
+
+- [`PHPUnit\Framework\TestCase::assertPostConditions()`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L622)
+- [`PHPUnit\Framework\TestCase::tearDown()` and methods annotated with `@after`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L680)
+
+When phpunit/phpunit invokes `PHPUnit\Framework\TestCase::runBare()`, it will invoke the following methods after the last test method in the class:
+
+- [`PHPUnit\Framework\TestCase::tearDownAfterClass()` and methods annotated with `@afterClass`](https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L683)
+
+> [!NOTE]
+> Because of this behavior, the measured test durations can and will vary depending on the order in which `phpunit/phpunit` executes tests.
 
 ## Changelog
 

composer-require-checker.json

@@ -7,10 +7,10 @@
     "int",
     "null",
     "PHPUnit\\Event\\Code\\Test",
-    "PHPUnit\\Event\\Test\\Passed",
-    "PHPUnit\\Event\\Test\\PassedSubscriber",
-    "PHPUnit\\Event\\Test\\Prepared",
-    "PHPUnit\\Event\\Test\\PreparedSubscriber",
+    "PHPUnit\\Event\\Test\\Finished",
+    "PHPUnit\\Event\\Test\\FinishedSubscriber",
+    "PHPUnit\\Event\\Test\\PreparationStarted",
+    "PHPUnit\\Event\\Test\\PreparationStartedSubscriber",
     "PHPUnit\\Event\\TestRunner\\ExecutionFinished",
     "PHPUnit\\Event\\TestRunner\\ExecutionFinishedSubscriber",
     "PHPUnit\\Metadata\\Annotation\\Parser\\Registry",

psalm-baseline.xml

@@ -21,12 +21,12 @@
       <code>($durationInMilliseconds - $hoursInMilliseconds - $minutesInMilliseconds) / 1_000</code>
     </InvalidOperand>
   </file>
-  <file src="src/Subscriber/Test/PassedSubscriber.php">
+  <file src="src/Subscriber/Test/FinishedSubscriber.php">
     <UndefinedClass>
-      <code>Event\Test\PassedSubscriber</code>
+      <code>Event\Test\FinishedSubscriber</code>
     </UndefinedClass>
     <UnusedClass>
-      <code>PassedSubscriber</code>
+      <code>FinishedSubscriber</code>
     </UnusedClass>
     <UnusedParam>
       <code>$collector</code>
@@ -35,12 +35,12 @@
       <code>$timeKeeper</code>
     </UnusedParam>
   </file>
-  <file src="src/Subscriber/Test/PreparedSubscriber.php">
+  <file src="src/Subscriber/Test/PreparationStartedSubscriber.php">
     <UndefinedClass>
-      <code>Event\Test\PreparedSubscriber</code>
+      <code>Event\Test\PreparationStartedSubscriber</code>
     </UndefinedClass>
     <UnusedClass>
-      <code>PreparedSubscriber</code>
+      <code>PreparationStartedSubscriber</code>
     </UnusedClass>
     <UnusedParam>
       <code>$event</code>

src/Extension.php

@@ -33,6 +33,7 @@
     final class Extension implements
         Runner\AfterLastTestHook,
         Runner\AfterSuccessfulTestHook,
+        Runner\AfterTestHook,
         Runner\BeforeFirstTestHook
     {
         private int $suites = 0;
@@ -68,9 +69,21 @@ public function executeBeforeFirstTest(): void
             ++$this->suites;
         }
 
+        /**
+         * @see https://github.com/sebastianbergmann/phpunit/pull/3392#issuecomment-1868311482
+         * @see https://github.com/sebastianbergmann/phpunit/blob/7.5.0/src/TextUI/TestRunner.php#L227-L239
+         * @see https://github.com/sebastianbergmann/phpunit/pull/3762
+         */
         public function executeAfterSuccessfulTest(
             string $test,
             float $time
+        ): void {
+            // intentionally left blank
+        }
+
+        public function executeAfterTest(
+            string $test,
+            float $time
         ): void {
             $seconds = (int) \floor($time);
             $nanoseconds = (int) (($time - $seconds) * 1_000_000_000);
@@ -206,8 +219,8 @@ public function bootstrap(
             );
 
             $facade->registerSubscribers(
-                new Subscriber\Test\PreparedSubscriber($timeKeeper),
-                new Subscriber\Test\PassedSubscriber(
+                new Subscriber\Test\PreparationStartedSubscriber($timeKeeper),
+                new Subscriber\Test\FinishedSubscriber(
                     $maximumDuration,
                     $timeKeeper,
                     $collector,

src/Subscriber/Test/PassedSubscriber.php renamed to src/Subscriber/Test/FinishedSubscriber.php

@@ -27,7 +27,7 @@
 /**
  * @internal
  */
-final class PassedSubscriber implements Event\Test\PassedSubscriber
+final class FinishedSubscriber implements Event\Test\FinishedSubscriber
 {
     private Collector\Collector $collector;
     private TimeKeeper $timeKeeper;
@@ -44,9 +44,10 @@ public function __construct(
     }
 
     /**
-     * @see https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L664-L666
+     * @see https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestRunner.php#L198
+     * @see https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestRunner.php#L238
      */
-    public function notify(Event\Test\Passed $event): void
+    public function notify(Event\Test\Finished $event): void
     {
         $phaseIdentifier = PhaseIdentifier::fromString($event->test()->id());
 

src/Subscriber/Test/PreparedSubscriber.php renamed to src/Subscriber/Test/PreparationStartedSubscriber.php

@@ -21,7 +21,7 @@
 /**
  * @internal
  */
-final class PreparedSubscriber implements Event\Test\PreparedSubscriber
+final class PreparationStartedSubscriber implements Event\Test\PreparationStartedSubscriber
 {
     private TimeKeeper $timeKeeper;
 
@@ -31,9 +31,9 @@ public function __construct(TimeKeeper $timeKeeper)
     }
 
     /**
-     * @see https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L614-L616
+     * @see https://github.com/sebastianbergmann/phpunit/blob/10.0.0/src/Framework/TestCase.php#L585-L587
      */
-    public function notify(Event\Test\Prepared $event): void
+    public function notify(Event\Test\PreparationStarted $event): void
     {
         $time = $event->telemetryInfo()->time();
 

test/EndToEnd/Version10/TestCase/Combination/test.phpt

@@ -24,9 +24,9 @@ Configuration: %s/EndToEnd/Version10/TestCase/Combination/phpunit.xml
 
 Detected 3 tests that took longer than expected.
 
-1. 0.4%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
-2. 0.3%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
-3. 0.1%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLessThanMaximumDurationFromXmlConfiguration
+1. 1.1%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
+2. 1.0%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
+3. 0.8%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\Combination\SleeperTest::testSleeperSleepsLessThanMaximumDurationFromXmlConfiguration
 
 Time: %s, Memory: %s
 

test/EndToEnd/Version10/TestCase/WithAfterAnnotation/test.phpt

@@ -22,10 +22,11 @@ Configuration: %s/EndToEnd/Version10/TestCase/WithAfterAnnotation/phpunit.xml
 
 ...                                                                 3 / 3 (100%)
 
-Detected 2 tests that took longer than expected.
+Detected 3 tests that took longer than expected.
 
-1. 0.3%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAnnotation\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
-2. 0.2%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAnnotation\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
+1. 0.4%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAnnotation\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
+2. 0.3%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAnnotation\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
+3. 0.1%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAnnotation\SleeperTest::testSleeperSleepsLessThanMaximumDurationFromXmlConfiguration
 
 Time: %s, Memory: %s
 

test/EndToEnd/Version10/TestCase/WithAfterAttribute/test.phpt

@@ -22,10 +22,11 @@ Configuration: %s/EndToEnd/Version10/TestCase/WithAfterAttribute/phpunit.xml
 
 ...                                                                 3 / 3 (100%)
 
-Detected 2 tests that took longer than expected.
+Detected 3 tests that took longer than expected.
 
-1. 0.3%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAttribute\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
-2. 0.2%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAttribute\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
+1. 0.4%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAttribute\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#1
+2. 0.3%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAttribute\SleeperTest::testSleeperSleepsLongerThanMaximumDurationFromXmlConfigurationWithDataProvider#0
+3. 0.1%s (0.100) Ergebnis\PHPUnit\SlowTestDetector\Test\EndToEnd\Version10\TestCase\WithAfterAttribute\SleeperTest::testSleeperSleepsLessThanMaximumDurationFromXmlConfiguration
 
 Time: %s, Memory: %s