Performance regression in 1.9.x-dev after 1.9.2 #8397

ondrejmirtes · 2022-11-20T09:27:13Z

ondrejmirtes
Nov 20, 2022
Maintainer

Hello @rajyan, I just got back home from SymfonyCon, and tried running PHPStan locally, and noticed it's about 50 % slower for me. (it runs in about 29 seconds instead of the usual 17 seconds). I test it with time make phpstan in phpstan-src.

I wasn't able to pin down the cause besides proving it has to be in one of your commits. Unfortunately I can't revert them individually because that way I create a lot of conflicts which I don't know how to solve, but if I revert all of your commits since 1.9.2, the performance problem is solved again:

* 1bb12c2d2 (HEAD -> 1.9.x) Revert "Improve conditionalExpressionTypes"
* ab4fd826f Revert "Fix conditional variable types in global scope"
* 454a7171e Revert "Use ExpressionTypeHolders for conditional expression type"
* 0d083406f Revert "do not invalidate related expressions in ensureNonNullability"
* b4c813e22 Revert "Avoid specifying scalar types and delete string casts"
* d03eb999f Revert "Improve PHPDoc for expression types"
* c0b40c5f6 Revert "Improve create conditional expressions to handle all expressions"
* 9d336112e Revert "Infinite loop regression test"

Can you please investigate it so we're not forced to revert your awesome fixes? :) Thank you very much.

I'll try to do some Blackfire profiles if I get the chance.

rajyan · 2022-11-20T09:50:06Z

rajyan
Nov 20, 2022

Thank you for your information.
I haven’t looked into it yet, but I suspect that this one can be the cause
phpstan/phpstan-src@cb45b58

I'll look into it in a few days!

3 replies

rajyan Nov 21, 2022

@ondrejmirtes
Is it possible to add a simple performance regression test CI like
https://rajyan.github.io/dotfiles/dev/bench/
https://github.com/rajyan/dotfiles/blob/master/.github/workflows/benchmark.yml

I'm using
https://github.com/benchmark-action/github-action-benchmark

ondrejmirtes Nov 21, 2022
Maintainer Author

How does it work and how is it useful? Is it going to fail if it's slower?

In my experience the execution times in CI vary a lot because it's executed on different hardware with different loads often.

I'd much rather observe for example how many times was TypeCombinator::union() executed, that can usually show us that something is wrong...

rajyan Nov 21, 2022

It compares the performance with the latest result, and CI fails if the threshold has exceeded.
For example
rajyan/dotfiles@01c56ad#commitcomment-60980385

In my experience the execution times in CI vary a lot because it's executed on different hardware with different loads often.

Yeah, I agree with this, maybe it is difficult to set a good threshold without looking the AVG and STD.

I'd much rather observe for example how many times was TypeCombinator::union() executed, that can usually show us that something is wrong...

FYI, the value to set for this action can be anything https://github.com/rajyan/dotfiles/blob/213dd5041ece03402e5bceff782be9593122f223/.github/workflows/benchmark.yml#L54
, so TypeCombinator::union() can be tracked for example if it's a better measurement.

Although I think this action might not be the best for it. I was just wondering if there is a good way to track the performance continuously.

rajyan · 2022-11-21T10:14:06Z

rajyan
Nov 21, 2022

Started investigating. Could confirm that phpstan/phpstan-src#2007 caused the performance regression.

7 replies

herndlm Nov 21, 2022

what, did rajyan break your computer? xD but without a real fire, right? god

herndlm Nov 24, 2022

btw how's your computer? looks like I'm starting to get phpstan PR review/update/merge withdrawal symptoms 😅

ondrejmirtes Nov 24, 2022
Maintainer Author

Trust me, I already have a pile of todos and more than 120 emails to process. It's usually bad after a vacation but now the queue gets longer and longer. I just learnt it's not going to be repaired this week, but hopefully the next one.

herndlm Nov 24, 2022

oh no, that sounds actually stressful. sorry to hear. I hoped you get a bit of an extended vacation :)

ondrejmirtes Nov 24, 2022
Maintainer Author

And now my espresso machine broke too. The universe is really testing me this week :) I don't even know who I am anymore...

rajyan · 2022-11-22T04:34:14Z

rajyan
Nov 22, 2022

Timing for each commit between 1.9.2 to 1.9.x
https://gist.github.com/rajyan/e68f07b65b6e333a9f0d91a2b0b384c2
Could confirm that both
phpstan/phpstan-src#1950
and
phpstan/phpstan-src#2007
is causing a regression...

1 reply

rajyan Nov 26, 2022

I think there are several causes that made the regression.

Number of conditionalExpressions has increased
getType is needed to evaluate the conditionals https://github.com/phpstan/phpstan-src/pull/1950/files#diff-dc817f2bab8672057a95375a542e68599164f6ab2380e4cccd1b50583e295d85R3757 (increases time complexity)
Invalidating conditonalExpression types in each loop https://github.com/phpstan/phpstan-src/pull/2007/files#diff-dc817f2bab8672057a95375a542e68599164f6ab2380e4cccd1b50583e295d85R3734 to avoid infinite loop (increases time complexity)

What I think the best way to solve this problem is to change $conditionalExpressions to quit looping through all conditionalExpressions in filterBySpecifiedTypes and only resolve the conditional expression that are needed in resolveType. This is almost what LateResolveTypes is doing, and could be another step toward merging conditionalExpressions.

ondrejmirtes · 2022-12-05T09:45:48Z

ondrejmirtes
Dec 5, 2022
Maintainer Author

So right now it's still 17.5 seconds on my computer on 1.9.2 and around 20 seconds on 1.9.x. I'll run Blackfire and let you know if we can improve something.

7 replies

ondrejmirtes Dec 5, 2022
Maintainer Author

All the additional time is spent in MutatingScope::shouldInvalidateExpression. Or maybe not, if it was created only by extracting the code that was already in MutatingScope::invalidateExpression.

rajyan Dec 5, 2022

Thank you very much for your profiling!

All the additional time is spent in MutatingScope::shouldInvalidateExpression

Yeah, that is something I expected...

As explained in
phpstan/phpstan-src#2018
to make this kind of invalidation work correctly, we need to invalidate the conditional types if the condition includes the invalidating expression.
For example if we have
conditional type foo($a)=true => $b is 'foo'
we need to invalidate this when foo($a) is invalidated, and also when $a is invalidated.
The additional code is here
https://github.com/phpstan/phpstan-src/blob/ec31e4148ca334dc0317307523c890a1301f72a6/src/Analyser/MutatingScope.php#L3498-L3501
and this increases the time complexity of invalidating.

ondrejmirtes Dec 5, 2022
Maintainer Author

Since then I found out something weird. TypeCombinator::union is called:

1.9.2: 469k times and takes 1m9s
1.9.x: 439k times and takes 2m5s

So it's called less times but takes more time?

And inside this method the private method compareTypesInUnion:

1.9.2: 1.5M times and takes 33s
1.9.x: 1.75M times and takes 1m33s

Which would explain why TypeCombinator::union is slower. Additionally, ObjectType::isSuperTypeOf:

1.9.2: 3.3M times and takes 28s
1.9.x: 5.6M times and takes 1m14s

So it'd probably be helpful to see why is this happening. Everything can be seen from the Blackfire profiles.

staabm Dec 6, 2022
Collaborator

in case its more helpful, I created a blackfire profile with our corporate account (which contains more details, because its a paid account).

recorded on windows11

 php -v
PHP 8.1.2 (cli) (built: Jan 19 2022 10:13:52) (NTS Visual C++ 2019 x64)
Copyright (c) The PHP Group
Zend Engine v4.1.2, Copyright (c) Zend Technologies
    with blackfire v1.76.0~win-x64-non_zts81, https://blackfire.io, by Blackfire

phpstan 1.9.2
https://blackfire.io/profiles/0ca35926-58ab-4db1-956b-179a357d8612/graph

phpstan 1.9.x @ 024e98e
https://blackfire.io/profiles/7b50616b-6329-4b73-966b-93e6b57fff4d/graph

comparison
https://blackfire.io/profiles/compare/88c70e00-31c2-42c9-92f1-f47ff2d458bd/graph

I think within this graph we can see what ondrej already mentioned:

staabm Dec 9, 2022
Collaborator

based on the profiles I found some file/IO related optimzations

ondrejmirtes · 2022-12-08T15:12:40Z

ondrejmirtes
Dec 8, 2022
Maintainer Author

Alright, I'm tackling the problem head-on. What I did was to debug why is compareTypesInUnion called so many times more than before. I added this line to TypeCombinator::compareTypesInUnion():

echo sprintf('%s vs. %s' . PHP_EOL, $a->describe(VerbosityLevel::precise()), $b->describe(VerbosityLevel::precise()));

And I ran this on both 1.9.2 and 1.9.x (just analysing two biggest files to give us an idea):

bin/phpstan analyse src/Analyser/NodeScopeResolver.php src/Analyser/MutatingScope.php  -vvv --debug

The Blackfire profile comparison is here: https://blackfire.io/profiles/compare/bb9237de-d7a6-4d37-aea7-eb7660f822a1/graph

And the debug log between these two versions is 26 MB vs. 76 MB! And if I diff these logs, the most common difference is that types are subtracted more often and compareTypesInUnion is called with these subtractions:

Details

-PhpParser\Node\Stmt\Class_ vs. PhpParser\Node\Stmt\ClassLike
-PhpParser\Node\Stmt\Class_ vs. PhpParser\Node\Stmt\ClassLike
+PhpParser\Node\Stmt\Class_~PhpParser\Node\Stmt\Break_|PhpParser\Node\Stmt\ClassMethod|PhpParser\Node\Stmt\Continue_|PhpParser\Node\Stmt\Declare_|PhpParser\Node\Stmt\Echo_|PhpParser\Node\Stmt\Expression|PhpParser\Node\Stmt\Function_|PhpParser\Node\Stmt\Namespace_|PhpParser\Node\Stmt\Return_|PhpParser\Node\Stmt\Trait_ vs. PhpParser\Node\Stmt\ClassLike~PhpParser\Node\Stmt\Break_|PhpParser\Node\Stmt\ClassMethod|PhpParser\Node\Stmt\Continue_|PhpParser\Node\Stmt\Declare_|PhpParser\Node\Stmt\Echo_|PhpParser\Node\Stmt\Expression|PhpParser\Node\Stmt\Function_|PhpParser\Node\Stmt\Namespace_|PhpParser\Node\Stmt\Return_|PhpParser\Node\Stmt\Trait_
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+PhpParser\Node\Stmt\Break_ vs. *NEVER*
+*NEVER* vs. PhpParser\Node\Stmt\ClassMethod
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+PhpParser\Node\Stmt\ClassMethod vs. *NEVER*
+*NEVER* vs. *NEVER*
+*NEVER* vs. PhpParser\Node\Stmt\Continue_
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*
+PhpParser\Node\Stmt\Continue_ vs. *NEVER*

I'll continue to debug why it happens and how to make it faster. Anyone, feel free to look into this too :)

4 replies

rajyan Dec 8, 2022

Thank you for the debugging! I'm continuously looking into this issue.

rajyan Dec 8, 2022

Looks like this line is the cause?
https://github.com/phpstan/phpstan-src/blob/ee86dda7d1131d883152698f8c2c4cab09b7bd32/src/Analyser/MutatingScope.php#L3998

rajyan Dec 8, 2022

I assume that number of calls of TypeCombinator::union have increased, because the conditional type improvements made more situation $this->getType()->equals($other->getType()) == false

ondrejmirtes Dec 9, 2022
Maintainer Author

The number of TypeCombinator::union calls have decreased, but inside compareTypesInUnion have increased. That's because there's a lot more subtracted types.

staabm · 2022-12-12T12:21:08Z

staabm
Dec 12, 2022
Collaborator

just a small summary after some perf related work which landed in 1.9.x

I have profilled all snippets available in issues labeled "performance". everything which stood out was optimzed.
the only thing left, which I don't have an idea on how it could become faster is the TypeTraverser.

also left are algorithmic improvements, especially within TypeCombinator. working more efficiently with big unions is the next big quest.

1 reply

ondrejmirtes Dec 12, 2022
Maintainer Author

Yeah, 1.9.x is now the same or faster than 1.9.2, which is nice :)

Uh oh!

Performance regression in 1.9.x-dev after 1.9.2 #8397

Uh oh!

ondrejmirtes Nov 20, 2022 Maintainer

Replies: 6 comments · 23 replies

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ondrejmirtes Nov 21, 2022 Maintainer Author

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ondrejmirtes Nov 24, 2022 Maintainer Author

Uh oh!

Uh oh!

ondrejmirtes Nov 24, 2022 Maintainer Author

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ondrejmirtes Dec 5, 2022 Maintainer Author

Uh oh!

Uh oh!

ondrejmirtes Dec 5, 2022 Maintainer Author

Uh oh!

Uh oh!

ondrejmirtes Dec 5, 2022 Maintainer Author

Uh oh!

Uh oh!

staabm Dec 6, 2022 Collaborator

Uh oh!

Uh oh!

staabm Dec 9, 2022 Collaborator

Uh oh!

ondrejmirtes Dec 8, 2022 Maintainer Author

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ondrejmirtes Dec 9, 2022 Maintainer Author

Uh oh!

Uh oh!

staabm Dec 12, 2022 Collaborator

Uh oh!

ondrejmirtes Dec 12, 2022 Maintainer Author

ondrejmirtes
Nov 20, 2022
Maintainer

Replies: 6 comments 23 replies

ondrejmirtes Nov 21, 2022
Maintainer Author

ondrejmirtes Nov 24, 2022
Maintainer Author

ondrejmirtes Nov 24, 2022
Maintainer Author

ondrejmirtes
Dec 5, 2022
Maintainer Author

ondrejmirtes Dec 5, 2022
Maintainer Author

ondrejmirtes Dec 5, 2022
Maintainer Author

staabm Dec 6, 2022
Collaborator

staabm Dec 9, 2022
Collaborator

ondrejmirtes
Dec 8, 2022
Maintainer Author

ondrejmirtes Dec 9, 2022
Maintainer Author

staabm
Dec 12, 2022
Collaborator

ondrejmirtes Dec 12, 2022
Maintainer Author