Skip to content
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

Version 9 (used with PHPUnit 9.3) is slower than Version 8 (used with PHPUnit 9.2) #789

Closed
Slamdunk opened this issue Aug 7, 2020 · 42 comments

Comments

@Slamdunk
Copy link
Contributor

Slamdunk commented Aug 7, 2020

Q A
PHPUnit version 9.3
PHP version 7.4
Installation Method Composer

Summary

After upgrading to PHPUnit 9.3, code coverage generation slowed down a lot.

How to reproduce

I've experienced this on most of my business repos; I'm sorry I can't provide a useful test set right now, but I can assure PHPUnit is the only upgraded package here

Until PHPUnit 9.2 (best of 5 runs):

$ /usr/local/bin/php '-d' 'pcov.enabled=1' '/var/www/html/vendor/phpunit/phpunit/phpunit' -v '--coverage-php' '/tmp/CV_ItLP7c' '--configuration' '/var/www/html/phpunit.xml' '--log-junit' '/tmp/PT_uMW9cK'
PHPUnit 9.2.6 by Sebastian Bergmann and contributors.

Runtime:       PHP 7.4.9 with PCOV 1.0.6
Configuration: /var/www/html/phpunit.xml

.....................................................             53 / 53 (100%)

Time: 00:10.480, Memory: 74.50 MB

OK (53 tests, 259 assertions)

Generating code coverage report in PHP format ... done [00:00.023]

From PHPUnit 9.3 (best of 5 runs):

$ /usr/local/bin/php '-d' 'pcov.enabled=1' '/var/www/html/vendor/phpunit/phpunit/phpunit' -v '--coverage-php' '/tmp/CV_ItLP7c' '--configuration' '/var/www/html/phpunit.xml' '--log-junit' '/tmp/PT_uMW9cK'
PHPUnit 9.3.2 by Sebastian Bergmann and contributors.

Runtime:       PHP 7.4.9 with PCOV 1.0.6
Configuration: /var/www/html/phpunit.xml
Warning:       Your XML configuration validates against a deprecated schema.
Suggestion:    Migrate your XML configuration using "--migrate-configuration"!

.....................................................             53 / 53 (100%)

Time: 00:17.054, Memory: 96.50 MB

OK (53 tests, 259 assertions)

Generating code coverage report in PHP format ... done [00:00.008]
@sebastianbergmann sebastianbergmann transferred this issue from sebastianbergmann/phpunit Aug 7, 2020
@sebastianbergmann sebastianbergmann changed the title Slow Code Coverage from PHPUnit 9.3 Version 9 (used with PHPUnit 9.3) is slower than Version 8 (used with PHPUnit 9.2) Aug 7, 2020
@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

This is, to some degree at least, expected as we now perform static code analysis using PHP-Parser where alternative and unreliable means were used before. Any help with profile-guided optimizations etc. would be greatly appreciated.

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

I can't reproduce the issue in any FOSS. May I ask you how to produce the information you'd need?

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

Do you see a similar slowdown with Xdebug?

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

Yes, with narrower gap between the two versions:

Before (best of 5 runs):

/usr/local/bin/php '-d' 'zend_extension=/usr/local/lib/php/extensions/no-debug-non-zts-20190902/xdebug.so' '/var/www/html/vendor/phpunit/phpunit/phpunit' -v '--coverage-php' '/tmp/CV_ItLP7c' '--configuration' '/var/www/html/phpunit.xml' '--log-junit' '/tmp/PT_uMW9cK'
PHPUnit 9.2.6 by Sebastian Bergmann and contributors.

Runtime:       PHP 7.4.9 with Xdebug 2.9.6
Configuration: /var/www/html/phpunit.xml

.....................................................             53 / 53 (100%)

Time: 00:32.638, Memory: 76.50 MB

OK (53 tests, 259 assertions)

Generating code coverage report in PHP format ... done [00:00.018]

After (best of 5 runs):

/usr/local/bin/php '-d' 'zend_extension=/usr/local/lib/php/extensions/no-debug-non-zts-20190902/xdebug.so' '/var/www/html/vendor/phpunit/phpunit/phpunit' -v '--coverage-php' '/tmp/CV_ItLP7c' '--configuration' '/var/www/html/phpunit.xml' '--log-junit' '/tmp/PT_uMW9cK'
PHPUnit 9.3.2 by Sebastian Bergmann and contributors.

Runtime:       PHP 7.4.9 with Xdebug 2.9.6
Configuration: /var/www/html/phpunit.xml
Warning:       Your XML configuration validates against a deprecated schema.
Suggestion:    Migrate your XML configuration using "--migrate-configuration"!

.....................................................             53 / 53 (100%)

Time: 00:37.995, Memory: 94.50 MB

OK (53 tests, 259 assertions)

Generating code coverage report in PHP format ... done [00:00.010]

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

With xDebug I run the profiler, produced the 2 cachegrind files (363MB with 9.2, 567M with 9.3) and here are the results:

Istantanea_2020-08-07_15-29-37

May you help me on where to look for useful info?

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

A screenshot of the profiling data rendered in KCachegrind is not useful. I would need to raw data so that I can navigate it myself. I cannot do this, however, for profiling data generated from non-FOSS software, sorry.

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

I understand.

I read the article https://doug.codes/php-code-coverage and I have to say I found myself not much interested in it because we adopt a coding standard fixer that puts new lines between each code branch, so we already have precise code-coverage reports.

Is any chance to have an opt-out of the new static analysis?

I understand you can't help on the topic with a proper test case, still we got bitten in our main business repo that slowed down by a factor of 10, from 3 minutes to 30 minutes to run the code-coverage analysis, so I'm searching for a pragmatic and simple solution.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

We now use PHP-Parser instead of php-token-stream (see #776 for details) to perform the static analysis required for many of this library's (and PHPUnit's) features. The information gained from this is required for traditional line coverage as well as the newly introduced branch and path coverage. The latter are disabled by default and must be explicitly turned on.

@dvdoug
Copy link
Contributor

dvdoug commented Aug 7, 2020

@sebastianbergmann Taking a quick look, each file is put through the parser multiple times? lines of code, executable lines, ignored lines, complexity and the reporting all look like they instantiate new parsers and don't share data. Or does PHP-Parser have a built in cache?

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

@dvdoug I am likely not using PHP-Parser yet as efficiently as it could be used.

Maybe we can reduce the number of traversals. Maybe we can cache the ASTs, thus parsing each file only once.

Where it was obvious, I am already using multiple visitors in a single traversal. Also note that not all visitors need to be applied for every file. For instance, ExecutableLinesFindingVisitor is only needed for files that are not covered.

@dvdoug
Copy link
Contributor

dvdoug commented Aug 7, 2020

👍

Eyeballing that screenshot, it does look like a very large amount of execution time is taken up by the various PHP-Parser classes. @Slamdunk do you have any particularly large source code files in your codebase? Wondering if you're hitting GC problems, see https://github.com/nikic/PHP-Parser/blob/master/doc/component/Performance.markdown

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

do you have any particularly large source code files in your codebase?

No, all below 100K, 95% below 16K.

Also note that not all visitors need to be applied for every file.

We massively use @covers annotation. Asking just to be sure: when a test with @covers runs, only the covered file is traversed, right?

Maybe we can cache the ASTs, thus parsing each file only once.

Off-Topic: for parallel runs, that would help a lot. And of course, for consecutive runs too, I guess.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

We massively use @covers annotation. Asking just to be sure: when a test with @covers runs, only the covered file is traversed, right?

No. Code coverage is collected for all files. If @covers is used, collected code coverage for code units not listed using @covers is discarded.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

Maybe we can cache the ASTs, thus parsing each file only once.
Off-Topic: for parallel runs, that would help a lot. And of course, for consecutive runs too, I guess.

I am only thinking about in-memory caching for now.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

@Slamdunk Can you check whether 7888a1a has an effect for you? Thanks!

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 7, 2020

Can you check whether 7888a1a has an effect for you?

Same bad results, unfortunately.

OT: now I have to go away from keyboard for a week, sorry

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

Node\File and IgnoredLinesFinder both use the AST once for each file that is executed. ExecutableLinesFinder uses the AST once for each file that is not executed. We can only get cache hits for the files processed by Node\File and IgnoredLinesFinder, not for files processed by ExecutableLinesFinder.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 7, 2020

I do not think that using a CachingParser as implemented in 7888a1a will be useful. Instead, we should try to group the AST processing performed by Node\File and IgnoredLinesFinder in one place so that each file that is executed is parsed only once into an AST node graph which in turn is traversed only once.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

I have implemented what I outlined in #789 (comment) in 5015613.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

Quick profiling (with Xdebug and gprof2dot) using php-code-coverage's own test suite.

master

master

PDF

performance-improvements

branch

PDF

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 8, 2020

It got even worse by another 15%. How could I produce such PDF?

In the meantime, here's the two KCaheGrind, left is latest release, right is performance-improvements:

immagine

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

It got even worse by another 15%. How could I produce such PDF?

Use gprof2dot to process the callgrind output from Xdebug, then use GraphViz/DOT to render the DOT file to PNG, PDF, etc.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

It got even worse by another 15%.

This is weird because now no duplicated work is happening. Or rather: no duplicated work should be happening. Maybe I should stop working on this now, take a break, and have a fresh look at it next week.

I am open for suggestions, pull requests, etc. to improve performance. However, I will not revert the change from php-token-stream to PHP-Parser. php-token-stream was a nightmare to maintain, a nightmare to work with, and lead to wrong information. PHP-Parser is nice to work with and provides accurate information.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

@dvdoug Not really related to this (at least I think so), but anyways: do you think we could change the code to not call applyIgnoredLinesFilter() after each test?

@GrahamCampbell
Copy link
Contributor

GrahamCampbell commented Aug 8, 2020

This is weird because now no duplicated work is happening

However, you have created more work for the garbage collector. Maybe this is the cause of the slow down?

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

However, I will not revert the change from php-token-stream to PHP-Parser. php-token-stream was a nightmare to maintain, a nightmare to work with, and lead to wrong information. PHP-Parser is nice to work with and provides accurate information.

This is too strong a statement. While I do not want to go back to php-token-stream, I am -- of course -- open to an alternative to using PHP-Parser if it yields the same results and its implementation is as clean as what we have right now.

@derickr
Copy link
Contributor

derickr commented Aug 8, 2020

@GrahamCampbell That hypothesis can be easily tested by turning the Garbage Collector off with zend.enable_gc=0 in php.ini.

@dvdoug
Copy link
Contributor

dvdoug commented Aug 8, 2020

@dvdoug Not really related to this (at least I think so), but anyways: do you think we could change the code to not call applyIgnoredLinesFilter() after each test?

Conceptually I think operating on the raw data makes more sense, but if benchmarks show an improvement in moving it then I agree it would be safe to do so.

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 8, 2020

Good news: I can now definitively "blame" the new PhpParser for the slowness.

I've implemented the trivial file cache as coded in Slamdunk@3c185b7 and the results are:

php-code-coverage avg. elapsed time
8.0 10s
9.0 17s
performance-improvements 20s
performance-improvements w/o GC 18s
file_cache 1° run 20s
file_cache next runs 6s

So when the code tokens are already analyzed, PHP-CC 9.0 performs even better than PHP-CC 8.0.

I am only thinking about in-memory caching for now.

I can understand that persistent caching is a big jump, but if no other solutions are found, at least we should provide an opt-in configuration for it.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

Good news: I can now definitively "blame" the new PhpParser for the slowness.

No surprise there :)

I can understand that persistent caching is a big jump, but if no other solutions are found, at least we should provide an opt-in configuration for it.

Sure. I'll work on this, but probably only after the weekend.

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 8, 2020

May I ask you to consider an API solely to initialize the cache?
It will help on parallelization contexts (first fill the cache, then run) and in memory restrained environments (cache fill and CC run executed separetly)

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

May I ask you to consider an API solely to initialize the cache?

I do not understand what you are asking for. My current plan is to add the option to use a filesystem-backed cache for the information that is gathered using PHP-Parser. The initial work on that can be seen in afdca58.

Currently the /tmp/cache directory is hard-coded for testing. Obviously this will be configurable from PHPUnit, both from phpunit.xml and from CLI options. There also needs to be some refactoring/cleanup to get rid of the Singleton(s).

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

May I ask you to consider an API solely to initialize the cache?

I do not understand what you are asking for.

It just occured to me that you may be asking for an API to initialize a cache directory with data for a given directory / set of files. That would make sense for the scenarios you refer to, I agree.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 8, 2020

The initial work on that can be seen in afdca58

First run

2.82user 0.18system 0:03.02elapsed 99%CPU (0avgtext+0avgdata 70644maxresident)k
0inputs+8072outputs (0major+21427minor)pagefaults 0swaps

first

PDF

Second run

0.66user 0.15system 0:00.83elapsed 99%CPU (0avgtext+0avgdata 61768maxresident)k
0inputs+8072outputs (0major+14604minor)pagefaults 0swaps

second

PDF

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 8, 2020

It just occured to me that you may be asking for an API to initialize a cache directory with data for a given directory / set of files.

Yes, I imagine something like:

./phpunit --initialize-cache
./phpunit --coverage-html ./cc

Both the command read the same configuration from phpunit.xml.
In Paratest we will call the corresponding API internally before executing phpunit in the sub-processes of the parallel execution task.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

I have merged the changes I made so far to master, bumped the version to 9.1, and pushed sebastianbergmann/phpunit@b4f0a21 to PHPUnit's 9.3 branch. This should make testing these improvements easier.

PHPUnit now has

  • --coverage-cache <directory>: CLI option for enabling a cache for static analysis results; it will write its files to <directory>
  • <coverage cacheDirectory="directory">: XML configuration attribute for enabling a cache for static analysis results; it will write its files to directory
  • --warm-coverage-cache: CLI option for warming the cache for static analysis results; the cache must be configured for this to work

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

No Cache

2.29user 0.07system 0:02.38elapsed 99%CPU (0avgtext+0avgdata 81640maxresident)k
0inputs+8072outputs (0major+26041minor)pagefaults 0swaps

no-cache

Cache: First Run

2.32user 0.09system 0:02.42elapsed 99%CPU (0avgtext+0avgdata 81940maxresident)k
0inputs+8072outputs (0major+25817minor)pagefaults 0swaps

cache-1

Cache: Second Run

1.32user 0.09system 0:01.43elapsed 99%CPU (0avgtext+0avgdata 77844maxresident)k
0inputs+8072outputs (0major+18844minor)pagefaults 0swaps

cache-2

Cache Warming

1.98user 0.04system 0:02.03elapsed 99%CPU (0avgtext+0avgdata 74240maxresident)k
0inputs+0outputs (0major+15218minor)pagefaults 0swaps

warm-cache

@Slamdunk
Copy link
Contributor Author

Slamdunk commented Aug 9, 2020

I have merged the changes I made so far to master, bumped the version to 9.1, and pushed sebastianbergmann/phpunit@b4f0a21 to PHPUnit's 9.3 branch.

Here the results for my heaviest business repo and PCOV:

PHPUnit version Timings
9.2.6 w/o CC Time: 05:13.353, Memory: 1.15 GB
9.2.6 w CC Time: 10:35.579, Memory: 1.17 GB
9.3 w CC > 1h, manually stopped
sebastianbergmann/phpunit@a0c0ebd w/o CC Time: 05:09.191, Memory: 1.15 GB
vendor/bin/phpunit --warm-coverage-cache 0m25,875s
sebastianbergmann/phpunit@a0c0ebd w CC a6fd014 Time: 12:36.342, Memory: 1.18 GB

So I think we can close this issue as the performances are comparable and the issue not blocking anymore.

@sebastianbergmann Running vendor/bin/phpunit --warm-coverage-cache without a CC driver tells Warning: No code coverage driver available and then proceed to run the tests as normal.

Considering the purpose of --warm-coverage-cache, I think the behavior without a CC driver should be to warn the user (ok, already done) and then exit with an exit-code greater than zero, instead of running the tests.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

@sebastianbergmann Running vendor/bin/phpunit --warm-coverage-cache without a CC driver tells Warning: No code coverage driver available and then proceed to run the tests as normal.

Considering the purpose of --warm-coverage-cache, I think the behavior without a CC driver should be to warn the user (ok, already done) and then exit with an exit-code greater than zero, instead of running the tests.

Of course. I have simply not gotten around to implement proper error handling there.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

So I think we can close this issue as the performances are comparable and the issue not blocking anymore.

Thank you for bringing this to my attention and for testing the various iterations!

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

warm-cache

The code for --warm-coverage-cache is currently run after the tests have been loaded and sorted. This work is not necessary and we should try to avoid it.

@sebastianbergmann
Copy link
Owner

sebastianbergmann commented Aug 9, 2020

@sebastianbergmann Running vendor/bin/phpunit --warm-coverage-cache without a CC driver tells Warning: No code coverage driver available and then proceed to run the tests as normal.
Considering the purpose of --warm-coverage-cache, I think the behavior without a CC driver should be to warn the user (ok, already done) and then exit with an exit-code greater than zero, instead of running the tests.

Of course. I have simply not gotten around to implement proper error handling there.

I refactored the cache warming in 572a688 to not require CodeCoverage and/or Driver objects.

I have implemented proper error handling for --warm-coverage-cache in sebastianbergmann/phpunit@e251bb2.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants