Page MenuHomePhabricator

Investigate if we can log more information with Quibble when running unit tests
Closed, InvalidPublicSpike

Description

Debugging when running unit tests in parallel is one of the most challenging tasks. In our current PHPUnit test setup, the test splitter mixes tests from all projects (Core and gated extensions) into split groups for load balancing. The logged information does not indicate which repo the running tests in each split group come from. This makes it challenging to know exactly which tests are running in each group, and in particular, makes it difficult to debug the tests. Sample logs are attached below (Full output at P90599), and as indicated, it is difficult to distinguish which repo the tests running in each split group belong to:

13:22:06 INFO:quibble.commands:>>> Start: PHPUnit extensions suite (without database or standalone) parallel run (Composer)
13:22:07 > MediaWiki\Composer\ComposerLaunchParallel::launchTestsDatabaseless
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_0' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_0_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_1' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_1_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_4' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_4_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_2' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_2_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_5' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_5_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_3' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_3_databaseless.result.cache'' ...
13:22:07 Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_6' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_6_databaseless.result.cache'' ...
13:22:15 > Composer\Config::disableProcessTimeout
13:22:15 > @php tests/phpunit/generatePHPUnitConfig.php '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_3' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_3_databaseless.result.cache'

Acceptance Criteria:

  • Check if there's more information we can log from Quible when running unit tests.
  • If there is more information to be logged, create a patch.

Event Timeline

Restricted Application changed the subtype of this task from "Task" to "Spike". · View Herald TranscriptApr 12 2026, 8:34 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript

With a bit of tinkering locally, I am able to extract some information indicating the number of loaded test files per repo and their distribution across the various split groups. A sample output at the beginning of the tests:

> Composer\Config::disableProcessTimeout
Using PHP 8.3.30
Generating PHPUnit config
Config already up-to-date.
Using PHP 8.3.30
Running with MediaWiki settings because there might be integration tests
PHPUnit 9.6.34 by Sebastian Bergmann and contributors.

Wrote list of tests that would have been run to tests-list-default.xml
> MediaWiki\Composer\PhpUnitSplitter\PhpUnitXmlManager::splitTestsListDefault
No results cache file found at /tmp/phpunit-results-cache.json

No results cache file found at /tmp/phpunit-results-cache.json

INFO:quibble.util:Copying /workspace/src/phpunit-database.xml to /workspace/log/phpunit-parallel-database.xml
INFO:quibble.util:Copying /workspace/src/phpunit-databaseless.xml to /workspace/log/phpunit-parallel-databaseless.xml
INFO:quibble.commands:<<< Finish: PHPUnit Prepare Parallel Run (Composer), in 6.099 s
INFO:quibble.commands:>>> Start: PHPUnit default suite (without database or standalone) parallel run (Composer)
INFO:quibble.commands:Parallel databaseless — 1580 test files across 8 split groups
INFO:quibble.commands:Parallel databaseless — projects: 'mediawiki/core' (1434 test files), 'mediawiki/extensions/AbuseFilter' (116 test files), 'mediawiki/extensions/AntiSpoof' (4 test files), 'mediawiki/skins/Vector' (26 test files)
INFO:quibble.commands:Parallel databaseless — split_group_0: 226 test files [mediawiki/core (80), mediawiki/extensions/AbuseFilter (116), mediawiki/extensions/AntiSpoof (4), mediawiki/skins/Vector (26)]
INFO:quibble.commands:Parallel databaseless — split_group_1: 226 test files [mediawiki/core (226)]
INFO:quibble.commands:Parallel databaseless — split_group_2: 226 test files [mediawiki/core (226)]
INFO:quibble.commands:Parallel databaseless — split_group_3: 226 test files [mediawiki/core (226)]
INFO:quibble.commands:Parallel databaseless — split_group_4: 226 test files [mediawiki/core (226)]
INFO:quibble.commands:Parallel databaseless — split_group_5: 226 test files [mediawiki/core (226)]
INFO:quibble.commands:Parallel databaseless — split_group_6: 223 test files [mediawiki/core (223)]
INFO:quibble.commands:Parallel databaseless — split_group_7: 1 test files [mediawiki/core (1)]
> MediaWiki\Composer\ComposerLaunchParallel::launchTestsDatabaseless
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_0' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_0_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_1' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_1_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_2' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_2_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_3' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_3_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_4' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_4_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_6' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_6_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_5' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_5_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_7' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_7_databaseless.result.cache'' ...
Running command ''composer' 'run' '--timeout=0' 'phpunit:entrypoint' '--' '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_8' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_8_databaseless.result.cache'' ...
> Composer\Config::disableProcessTimeout
> @php tests/phpunit/generatePHPUnitConfig.php '--configuration' '/workspace/src/phpunit-databaseless.xml' '--testsuite' 'split_group_8' '--exclude-group' 'Broken,Standalone,Database' '--cache-result-file=/workspace/log/phpunit_group_8_databaseless.result.cache'
Using PHP 8.3.30
Generating PHPUnit config
Config already up-to-date.

Sample summary once the tests finish:

OK, but incomplete, skipped, or risky tests!
Tests: 3638, Assertions: 30993, Incomplete: 1.
Worker exited with status 0
INFO:quibble.commands:Split group timings for database:
INFO:quibble.commands:  PHPUnit database split_group 2: 136.0s
INFO:quibble.commands:  PHPUnit database split_group 3: 134.5s
INFO:quibble.commands:  PHPUnit database split_group 0: 130.0s
INFO:quibble.commands:  PHPUnit database split_group 4: 119.0s
INFO:quibble.commands:  PHPUnit database split_group 1: 77.9s
INFO:quibble.commands:  PHPUnit database split_group 6: 3.2s
INFO:quibble.commands:  PHPUnit database split_group 5: 3.0s
INFO:quibble.commands:  PHPUnit database split_group 7: 2.6s
INFO:quibble.commands:  PHPUnit database split_group 8: 2.6s
INFO:quibble.commands:  PHPUnit database split_group 9: 2.6s
INFO:quibble.commands:<<< Finish: PHPUnit default suite (with database) parallel run (Composer), in 136.860 s
INFO:quibble.commands:>>> Start: PHPUnit Parallel Notice
INFO:quibble.commands:NOTICE: These tests have been executed with PHPUnit Parallel enabled.

Change #1272025 had a related patch set uploaded (by Pwangai; author: Pwangai):

[integration/quibble@master] phpunit: log project breakdown and split-group timings

https://gerrit.wikimedia.org/r/1272025

@pwangai do I understand that the splitting do not work good at all since some groups are really fast? One thing I was thinking was that since Wikibase tests is so in dominance, maybe we could hack so we run the tests in two steps: first all PHP for all others and then after they are finished the same with Wikibase. That way it would be easy to show the cost of the Wikibase tests. And maybe the split groups will work better if its Wikibase that takes the time?

@pwangai do I understand that the splitting do not work good at all since some groups are really fast? One thing I was thinking was that since Wikibase tests is so in dominance, maybe we could hack so we run the tests in two steps: first all PHP for all others and then after they are finished the same with Wikibase. That way it would be easy to show the cost of the Wikibase tests. And maybe the split groups will work better if its Wikibase that takes the time?

We can explore this and try it out. It may probably maximize the available resources more effectively

Just a note about test distribution. The test splitting uses the PHPUnit Results Cache toolforge tool to store information from previous runs about how long the tests take to run. When the splitting runs, it tries to download information from the cache to use in distributing the tests.

In the logs above, the message:

No results cache file found at /tmp/phpunit-results-cache.json

Suggests that the step that would download the timing information is not being run. Downloading this data from the server (or running this step in composer) should greatly improve the distribution of times for the different buckets. And if it doesn't, that's a bug.

I've also written a tool to help analyse data from previous runs to try and understand why tests have been split in the way they've been split - that might be useful for your research.

Change #1272025 abandoned by Pwangai:

[integration/quibble@master] phpunit: log project breakdown and split-group timings

Reason:

Closing this in favor of moving this implementation to Core.

https://gerrit.wikimedia.org/r/1272025

@ArthurTaylor I eventually landed on the PHPUnit Results Cache tool and factored in the cached results when running the tests locally using Quibble, I had just forgotten to update the paste. The tool has also been very helpful with some other tasks we are working on as a team. I had done the logging implementation in Quibble, but was recommended to implement this in Core, so I am going to try that instead. I was not aware of the jenkins-run-analysis tool, thanks for the link. I will have a look at it :)

@pwangai is there anything more that we should do here or can it be closed?

We are migrating to upstream parallelization, so I do not think we need to put much effort into this.