PHPUnit 12 badly evaluates time for very first test

[niconoe-]

Q	A
PHPUnit version	12.0.x
PHP version	8.3.x
Installation Method	Composer

Summary

When running PHPUnit 12, the very first test is reported to have a time-consumption really higher than with PHPUnit 11 on JUnit and cache-files reports. I bet this might be caused by an unwanted including of tests preparations before the very first test plays, but I can't find any location in source code so I wasn't able to provide a PR about it.

Current behavior

The "time" value on JUnit report is currently not the actual execution time for the very first test only.

On PHPUnit 12.0.10 :

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
  <testsuite name="/data/www/phpunit.xml" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
    <testsuite name="myproject" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
      <testsuite name="MyProject\Tests\FooBarTest" file="/data/www/src/Tests/FooBarTest.php" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
        <testsuite name="MyProject\Tests\FooBarTest::testTrue" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
          <testcase name="testTrue with data set &quot;test-case #1&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.445116"/>
          <testcase name="testTrue with data set &quot;test-case #2&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.003829"/>
          <testcase name="testTrue with data set &quot;test-case #3&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.003530"/>
        </testsuite>
      </testsuite>
    </testsuite>
  </testsuite>
</testsuites>

On PHPUnit 11.5.15 :

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
  <testsuite name="/data/www/phpunit.xml" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.074995">
    <testsuite name="myproject" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.074995">
      <testsuite name="MyProject\Tests\FooBarTest" file="/data/www/src/Tests/FooBarTest.php" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.074995">
        <testsuite name="MyProject\Tests\FooBarTest::testTrue" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.074995">
          <testcase name="testTrue with data set &quot;test-case #1&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.066512"/>
          <testcase name="testTrue with data set &quot;test-case #2&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.004285"/>
          <testcase name="testTrue with data set &quot;test-case #3&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.004197"/>
        </testsuite>
      </testsuite>
    </testsuite>
  </testsuite>
</testsuites>

How to reproduce

Simply create a very simple test case and compare the execution time with actual time, or with PHPUnit 11.

PHP Test file used for given stats:

<?php declare(strict_types=1);

namespace MyProject\Tests;

final class FooBarTest extends \PHPUnit\Framework\TestCase
{
    public static function provideTest(): \Generator
    {
        yield 'test-case #1' => ['a'];
        yield 'test-case #2' => ['b'];
        yield 'test-case #3' => ['c'];
    }

    #[\PHPUnit\Framework\Attributes\DataProvider('provideTest')]
    public function testTrue(): void
    {
        self::assertTrue(true);
    }
}

Expected behavior

The "time" value on JUnit report should reflects the actual execution time of the test and not include the data preparation, like for PHPUnit 11

Thank you very much 🙂

[marac19901990]

I'm working on this, will raise a PR soon :)

[marac19901990]

@sebastianbergmann Actually after taking a closer look above both examples include preparation time in the first testcase time. So this is probably an issue in all versions.

What if we add preparationTime as a testsuite attribute?

Something like this:

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
  <testsuite name="/data/www/phpunit.xml" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
    <testsuite name="myproject" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
      <testsuite name="MyProject\Tests\FooBarTest" file="/data/www/src/Tests/FooBarTest.php" tests="3" assertions="3" errors="0" failures="0" skipped="0" ------preparationTime="0.4"------ time="0.452475">
        <testsuite name="MyProject\Tests\FooBarTest::testTrue" tests="3" assertions="3" errors="0" failures="0" skipped="0" time="0.452475">
          <testcase name="testTrue with data set &quot;test-case #1&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.005116"/>
          <testcase name="testTrue with data set &quot;test-case #2&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.003829"/>
          <testcase name="testTrue with data set &quot;test-case #3&quot;" file="/data/www/src/Tests/FooBarTest.php" line="17" class="MyProject\Tests\FooBarTest" classname="MyProject.Tests.FooBarTest" assertions="1" time="0.003530"/>
        </testsuite>
      </testsuite>
    </testsuite>
  </testsuite>
</testsuites>

[sebastianbergmann]

We cannot add additional information to JUnit XML such as the attributes you propose.

[niconoe-]

both examples include preparation time in the first testcase time

That's interesting. I agree that the 1st test on PHPUnit 11 in my example took around 15.7x the expected time (based on the average of the 2 others), so it looks like it actually includes the preparation time, as you said @marac19901990 .

Comparing time for PHPUnit 12 is showing a factor of around 121x the expected time (still based on the average of the 2 others).

I have therefore 2 remarks about this evidence:

• Is there a way to not include the preparation time into the very first testcase, in order not to interfere with QA and stats about unit tests durations some people could do?
• Do you have any idea why on PHPUnit 12, the preparation time seems to be considerably higher than on PHPUnit 11 (at least, the reported value, maybe the actual preparation time doesn't differ that much).

[niconoe-]

We cannot add additional information to JUnit XML such as the attributes you propose.

It follows the schema defined by https://github.com/windyroad/JUnit-Schema/blob/cfa434d4b8e102a8f55b8727b552a0063ee9044e/JUnit.xsd, doesn't it?

One could propose them a PR to add the attribute, a new tag or whatever you feel better to add, as long as this is optional, but I bet they're not going to accept, as it looks like to fully embrace the output of Apache Ant…

Another solution could be to simply ignore the preparation time in the JUnit XML report for consistancy with the other test-cases executions.
If wanted for QA & stats, one could add it into another report out from the JUnit standards, but that would be a new feature and is out of context here, IMO.

[sebastianbergmann]

Following the example of JUnit, PHPUnit will eventually stop to support the generation of "JUnit XML". See https://github.com/ota4j-team/open-test-reporting?tab=readme-ov-file#prior-art for details.

The current plan is add support for Open Test Reporting in PHPUnit 12.2, deprecate JUnit XML support in PHPUnit 13, and remove support for JUnit XML in PHPUnit 14. Aside from bug fixes, no further changes will be implemented for JUnit XML support in PHPUnit.

I will look into this bug as soon as I find the time. I may not get to it before the PHPUnit Code Sprint at the end of this month.

[niconoe-]

Definitly interesting to move on Open Test Reporting format! I'm excited to see that released 😃

No rush for this bug: on my concern, there's nothing preventing to use PHPUnit as I expect to. I already have workarounds for my stats about it.

Happy codding on Code Sprint!

[theseer]

We, as in @sebastianbergmann, @edorian, @sebastianheuer, and I spent some time analyzing this issue during the PHPUnit Code Sprint in Berlin.

We could reproduce the general issue, but it is not related to JUnit XML, logging, or a wrong evaluation. We can see in the telemetry data the first test execution call is measurably slower, consistently.

The reason is PHP's autoloading: The first test triggers the autoloading of the relevant Constraint classes, etc. This is true for any assertion when used for the first time in case it needs additional code that has not yet been loaded.

We thus conclude that not to be a bug in PHPUnit: Any autoloading triggered when running a test will cause this fluctuation to happen.

This issue should also only exist when using a Composer based installation. When using the PHAR distribution of PHPUnit all PHPUnit related code is preloaded. We're considering to enhance PHPUnit's autoloading for Composer based installations, but this is a low priority for now.

[theseer]

For the record: A change in the autoload handling has been implemented with commit dea8cff to address the very side effect of autoloading PHPUnit core classes during test execution.

[niconoe-]

Thank you very much for your analysis about this. This is very complete and I understand entirely the issue here.

To be 100% honest, I still don’t fully get why on PHPUnit 12, the autoloading time is significantly higher than PHPUnit 11, using the exact same PHP version for both. But I think the preloading of the PHPUnit core classes you added will solve lots of troubles anyway. You already did the most you all could so thank you very much, sincerely.

Have a nice day!