Slow processing type hint of Class::*

[neclimdul]

Bug report

When updating an internal project from 1.3 to 1.7 phpstan ground to a halt. What used to take a second was taking minutes and on a constrained build server timing out after an hour just running phpstan. The later is extreme and maybe more a problem with the ci runner but I was suddenly blocked. I've generalized and open sourced the relevant parts of the project so it can be reviewed as part of this bug.

After a ton of profiling and bisecting and some red herrings the entire processing was on one line.
With the line:

./vendor/bin/phpstan  244.17s user 0.19s system 99% cpu 4:05.73 total

Without the line:

./vendor/bin/phpstan  1.15s user 0.12s system 92% cpu 1.376 total

What is this terrible line of code? This simple if statement: https://github.com/neclimdul/netsuite-search-iterator/blob/5714f4eac537930b9e55d7c7e1b82bd2d826bd00/src/Exception/StatusFailure.php#L70

The problem seems to be the type of that property. The relevant definition is
https://github.com/netsuitephp/netsuite-php/blob/3c2a5b19c1ab9879a8fc470076261359269098f9/src/Classes/StatusDetail.php#L21-L24
and the referenced types here https://github.com/netsuitephp/netsuite-php/blob/master/src/Classes/StatusDetailCodeType.php

There's something really weird going on here so I'm going to dump everything I've found.

1. The profile of this line single line is massive. Without the line line the profile of phpstan running on the project is <1 G. With it is over 13 G.
2. Removing the type from the property also fixes the performance.
3. The profile signature is a bit hard to narrow down because if the size of the profile and how kcachegrind seems to process it but its clear the time is almost entirely spent in TypeCombinator::create -> TypeCombinator::remove -> TypeCombinator::intersect -> php::usort . There are 128 calls to ::remove but 499k calls to ::intersect. Kcachegrind and xdebug seem to be unhappy with the trace so some of the time numbers don't make sense but its clear almost all the time seems to be in ::itersect and usort.
4. there is also a noticable amount of time spent in isSuperTypeOf calls from ::intersect with 998k calls.

Code snippet that reproduces the problem

https://github.com/neclimdul/netsuite-search-iterator/blob/5714f4eac537930b9e55d7c7e1b82bd2d826bd00/src/Exception/StatusFailure.php#L70

Expected output

Shorter scan of project.

Did PHPStan help you today? Did it make you happy in any way?

This was obviously frustrating taking a lot of time to narrow down and blocking development on this project but in the process of trying to narrow this down I tested it on a lot of vendor projects and found several issues that can be fixed. Also pushed me to finish open sourcing that library. There's always a silver lining if you look for it. 😄

[mergeable]

This bug report is missing a link to reproduction at phpstan.org/try.

It will most likely be closed after manual review.

[neclimdul]

Additional note, this does seem similar to #6948 which I initially landed on but it seemed different enough to open its own issue. Specifically I suspect the same code is dying trying to process a massive calculated union type so it might be a case for an optimization that can help both cases.

[ondrejmirtes]

This is hitting a bad case scenario on these lines: https://github.com/phpstan/phpstan-src/blob/4f810ffc19dc20af932e5a1e9caff3b7d26a3c3c/src/Type/TypeCombinator.php#L634-L643 Not sure what we can do about it.

With around 500 constants instead of the original 1420, the application finishes in around 10 seconds on my machine. So if someone wants to debug and optimize that (and don't want to wait an eternity each time), I recommend reducing the number of constants in vendor/ryanwinchester/netsuite-php/src/Classes/StatusDetailCodeType.php in the test project.

Here's a Blackfire profile: https://blackfire.io/profiles/f6caa0b4-0e2f-4c6a-95be-09ecc320a834/graph

[neclimdul]

Spent some time on this and I need to step back for a sec so capturing some details for later me or someone else looking at this.

First, there is an obvious micro optimization on these lines of extracting the array_slice out of the loop. Its probably worth optimizing but is the definition of a micro optimization and in this context is not helpful. It only shaves a tiny fraction of a percent of the cost of calculating the intersection. Its "expensive" to put in a loop but cheap compared to everything else going on.

Second, the bad case mentioned isn't clear from those lines alone. You might need to setup a way to step through the code with xdebug but I'll try to provide details of the expensive code path. Intersect is actually called a number of times on the constants during analysis. The specific bad case is triggered by this code in TypeSpecifier::specifyTypesInCondition() https://github.com/phpstan/phpstan-src/blob/4f810ffc19dc20af932e5a1e9caff3b7d26a3c3c/src/Analyser/TypeSpecifier.php#L343-L347 specifically the create call on line 345, not the direct call to intersect.

Looking at the triggering code and following along:

if ($detail->code == $code) {

The first line of TypeSpecifier intersects the left and right types. The left type is the union of the ConstantStringTypes and the right is StringType. In this specific case, this means $types gets assigned a new union that is just the ConstantStringTypes from the left type. This is quite cheap and doesn't even register on the trace but its fed to our expensive code.

The second line is where things explode. We create a specifier using the left type(constants) and the new union from the previous step. ::create does this by calling ::intersect to calculate the effective type. But in this case its the left type intersected with itself. This where we run into the loop in TypeCombinator and we can follow along there.

In the call to ::intersect the loops sees two unions. The first iteration of the loop iterates each entry in the first union it recurses something like intersect($constant, $constants). Luckily this returns and we don't repeat for the second union.

In the 1st recursive calls, we skip the first iteraction of the loop(constant) and then loop over each constant in the second union type. Again recursing to intersect each constant with each other constant in the list. n-1 of these second recursions are worst case calls to ::intersect because they have to do all checks and fail returning NeverType.

Back in the 1sr recursion we then call ::union to simplify the constant and all the NeverTypes and the Constant to just the Constant, returning.

Back in the outer intersect call we then union all the constants back together(again into effectively the original list) and return.

[neclimdul]

I also played with optimizing the type going into TypeSpecifier::create as well in phpstan/phpstan-src#1471.

The idea was that since we know one side of the expression and since ::create is going intersects the expression type with the provided type, we shouldn't intersect both types before calling. Seems like it might even cause incorrect values? This unfortunately causes some test failures though. The failing assertions don't completely make sense though so either I'm not understanding the method or maybe they where asserting the theoretical bug.

The code in the merge request is very effective though. It dropped the time to analyse the file from 244s to 7.5s. Still slower then I'd expect but much faster.

[ondrejmirtes]

I think this is optimized enough now, thank you very much :) Of course you're welcome to come up with more optimizations, but I think that 244s to 7.5s is good enough :)

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.