Poor performance in recent versions

[adnweedon]

Bug report

Our team has been using PHPStan version 1.4.10 - I've been working hard to get people using in their workflows, because it's great! However, I updated to v1.8.0 today, and immediately had much worse performance. I've done some benchmarking (that has taken most of the afternoon...), but with the same config on the same files (clearing the cache inbetween), I've seen the following performance:

v1.4.10 - 0.34s user 0.22s system 0% cpu 4:21.61 total
v1.5.0 - 0.36s user 0.36s system 0% cpu 7:48.78 total
v1.6.0 - 0.43s user 0.95s system 0% cpu 17:15.50 total
v1.7.0 - 0.58s user 1.78s system 0% cpu 35:55.40 total
v1.8.0 - 0.57s user 1.57s system 0% cpu 33:14.82 total

This was tested running inside Docker (as we have been doing for a long time), on our codebase of 2590 files. Docker has 6 cores available, the processTimeout setting is set to 300s, and the command we're using to run it is
../../vendor/bin/phpstan analyse --memory-limit=4G

Code snippet that reproduces the problem

No one file in particular!

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

PHPStan is amazing and has really helped us in lots of ways; as I mentioned further up, I'm trying to get my colleagues using it (and installing it in a pipeline)! Until I can get it running quickly, though, I'll struggle!

[mergeable]

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

It will most likely be closed after manual review.

[ondrejmirtes]

Hi, these sub-second measurements aren't really useful. I don't mind waiting an extra 0.3s and so shouldn't you either 😊

If you have something more like "before analysing the project took a minute, now it takes two minutes", that's something more actionable.

But even in these small cases, feel free to create profiles using Blackfire.io, and share the comparisons. That should show what got slower.

You can also use Xdebug to create Kcachegrind profiles.

Right now there isn't anything actionable in this report.

[adnweedon]

Hi, sorry that my timings weren't clear - it's the totals at the end of the line! The time has gone from 4m21s to 33mins - hence feeling that it might be worth raising!

[mad-briller]

@adnweedon a simple thing that has helped me begin debugging performance issues in the past is the --debug flag:
https://phpstan.org/user-guide/command-line-usage#--debug

this prints out each filepath as it is analysed, and from there you can see which files might be tripping phpstan up and taking a while, then you can start your investigation there

[ondrejmirtes]

@adnweedon Please follow these steps:

1. Definitely run with --debug. This will make PHPStan run in a single thread, making it possible to find the differences in benchmark profiles.
2. Find a subset of your codebase that's slow on 1.8.0, and it's possible to benchmark it. Because if you analyse the whole project, the PHPStan run will not fit in RAM or the profile will be absolutely huge (like hundreds of GBs). So the subset of your codebase must be analysed in a minute or so at maximum so that it's feasible to profile it.
3. Run the same subset of the codebase on 1.4 - it should be faster.
4. Provide us with benchmarking profiles from 2) and 3). We should see something that runs much slower on 1.8.0, or is executed many more times, and we should be able to optimize that.

[adnweedon]

I've not done this before, so hopefully I've done the right thing!

I ran PHPStan on a subset of code, with command "phpstan --debug --memory-limit=2G", and used xdebug to profile it on both versions. They look pretty similar to my untrained eye, but hopefully they will be useful to you!

On v1.4.10 the subset took 42s to run, and on v1.8.0 it took 54s.

profiles.zip

[herndlm]

unfortunately the profiles seem to only show some phpstan symfony console command that opens/closes a process. the actual phpstan analyse part seems to be completely missing.

just adding this in case somebody else or Ondrej, who can't check the profiles right now, know what the problem is based on this and have a solution :)

[ondrejmirtes]

It means it wasn't run with --debug. Also you might have to use --xdebug additionally if it's enabled 😊

[adnweedon]

Ah, fab - I had missed the existence of the --xdebug flag.

Here are the two profiles:

v1.4.10 - https://ufile.io/lf65tsa7
v1.8.0 - https://ufile.io/ezfg0cig

I hope this is useful - let me know how I can help further! Thanks for your help so far!

[schlndh]

First, I would recommend trying this (set nodesByStringCountMax: 0).

I also compared the runtime of multiple versions of phpstan on a subset of mediawiki. I first tried with 8 threads and got these results:

Command	Mean [s]	Min [s]	Max [s]	Relative
1.8.1	81.935 ± 0.683	81.170	82.769	2.20 ± 0.02
1.7.0	83.333 ± 0.369	82.974	83.906	2.24 ± 0.01
1.6.0	81.056 ± 0.230	80.842	81.402	2.18 ± 0.01
1.5.7	78.159 ± 0.147	77.956	78.365	2.10 ± 0.01
1.5.1	80.406 ± 0.228	80.207	80.774	2.16 ± 0.01
1.4.3	41.608 ± 0.103	41.492	41.728	1.12 ± 0.01
1.3.0	41.299 ± 0.232	41.124	41.659	1.11 ± 0.01
1.2.0	37.623 ± 0.119	37.518	37.815	1.01 ± 0.01
1.1.2	37.250 ± 0.144	37.086	37.413	1.00

The jump actually happens between versions 1.4.10 and 1.5.0:

Command	Mean [s]	Min [s]	Max [s]	Relative
1.5.0	80.292 ± 0.605	79.815	81.272	1.91 ± 0.02
1.4.10	42.135 ± 0.185	41.846	42.295	1.00

However, these numbers obscure the fact that the user time also increased even among versions where the real time is almost the same. So I re-run the benchmark with --debug and I got these results:

Command	Mean [s]	Min [s]	Max [s]	Relative
1.8.1	289.260 ± 0.454	288.832	289.737	1.72 ± 0.01
1.7.0	297.056 ± 0.399	296.745	297.506	1.77 ± 0.01
1.6.0	309.516 ± 0.449	309.257	310.035	1.84 ± 0.01
1.5.7	238.796 ± 0.491	238.493	239.363	1.42 ± 0.01
1.5.1	240.184 ± 0.720	239.766	241.015	1.43 ± 0.01
1.4.3	195.746 ± 1.076	194.506	196.412	1.16 ± 0.01
1.3.0	192.353 ± 2.183	189.864	193.943	1.14 ± 0.01
1.2.0	171.972 ± 1.361	170.607	173.330	1.02 ± 0.01
1.1.2	168.073 ± 0.890	167.084	168.809	1.00

So in reality unevenness of job scheduling (e.g. some thread gets unlucky with a very big file and it takes significantly longer than the rest of the threads) makes it a bit worse than in the single-threaded case.

I also compared these results to results from the proprietary code base that I work on (with 12 threads and less versions because the older versions didn't work in that case):

Command	Mean [s]	Min [s]	Max [s]	Relative
1.8.1	59.449 ± 1.763	56.606	60.940	1.46 ± 0.05
1.7.0	56.499 ± 0.555	55.899	57.026	1.39 ± 0.03
1.6.0	55.064 ± 2.223	52.678	57.321	1.35 ± 0.06
1.5.7	49.817 ± 1.926	47.796	51.912	1.22 ± 0.05
1.5.1	44.487 ± 1.751	42.721	47.056	1.09 ± 0.05
1.4.3	42.542 ± 0.851	41.592	43.661	1.04 ± 0.03
1.3.0	40.780 ± 0.888	40.004	41.886	1.00

The upward trend is similar, even though the differences are a bit smaller. So hopefully this should give you a way to reproduce the performance issues yourself on an open source code base (IMO that's better than a profile).

---

Details: I ran all the tests on the same machine equipped with Intel 12700K, 32GB of RAM, running Linux and php 8.1.8. The mediawiki tests are based on commit b19a8272953eeb6464350cc3c09284840c787faf. I analyzed extensions, includes and tests. All tests were made with phpstan-src for easy switching between versions.

I started by trying out different parameters with 1.8.1 to give it the best possible result. With default nodesByStringCountMax and 4 threads it took 4m 48s to analyze. Just setting nodesByStringCountMax: 0 changed it to 1m 38s.

Here is the config that I used for the benchmark:

parameters:
        level: 9
        cache:
                nodesByStringCountMax: 0
        parallel:
                maximumNumberOfProcesses: 8
        paths:
                # analysing the whole directory is pretty slow and thas A LOT of memory.
                - /mnt/d/external-devel/mediawiki/extensions
                - /mnt/d/external-devel/mediawiki/includes
                - /mnt/d/external-devel/mediawiki/tests

Here is the script that I used for the benchmark:

suffix="wiki"$(date +%s)
tags="1.8.1,1.7.0,1.6.0,1.5.7,1.5.1,1.4.3,1.3.0,1.2.0,1.1.2"

hyperfine -L tag "$tags" \
        --runs 5 \
        --setup 'git checkout tags/{tag}; composer install -n;' \
        --prepare 'rm -rf /tmp/phpstan; sleep 60;' \
        --ignore-failure \
        --export-markdown bench_result_$suffix.md \
        --export-json bench_result_$suffix.json \
        'echo {tag}; php bin/phpstan analyse --memory-limit=-1 -c phpstan-wiki.neon'

Note that for the single-threaded tests I changed it to just 3 runs with 5s of sleep between them to speed things up. And OFC I added --debug.

[schlndh]

I looked a bit more into the mediawiki performance and I found that this file (and that specific method) is what triggers the slowdown between 1.4.10 and 1.5.0.

In 1.4.10 it takes 18s to analyze the file, but in 1.5.0 it takes 55s (i.e. the difference between the two versions is almost entirely explained by this file alone). For contrast in 1.8.1 it takes 51s (i.e. the performance issue still persists).

I further narrowed it down to use-cases generated by this script:

<?php

$n = $argv[1];

$code = <<<'CODE'
<?php
function parse(array $parsed) {
    $data = [];

    foreach ($parsed as $tag => $val):
        switch ($tag):
CODE;

for ($i = 0; $i < $n; $i++) {
    $code .= <<<CODE

            case 'A$i':
                \$data['A$i'] = '';
                break;
CODE;
}

$code .= <<<'CODE'

        endswitch;
    endforeach;
}
CODE;

echo $code;

Here are the results for various sizes:

N	1.4.10	1.5.0
25	3s	9.6s
30	6.2s	21.8s
33	9.5s	34s
35	12.2s	45s
37	15.6s	58.5s

[ondrejmirtes]

@schlndh Perfect, thank you for nailing this down, I can now get to optimizing this :)

[ondrejmirtes]

I bisected it and this is the first bad commit: phpstan/phpstan-src@99951ac

I'm now running Blackfire to compare the performance profiles.

[ondrejmirtes]

Profile before: https://blackfire.io/profiles/4af6c16c-9db2-4eb4-9f97-c184a61dcc64/graph

Profile after: https://blackfire.io/profiles/106f812a-62ee-4612-b10f-cc3107b8d78a/graph

I'd say this performance problem would be fixed by reverting these lines phpstan/phpstan-src@99951ac#diff-fef252fe8071200a31b3d282d1442135d62297098c9b20fd731f3888398ee973L381-R383 but the "before" profile is already pretty bad so we might have to rethink this approach from the ground up.

[ondrejmirtes]

See #7666

[allan-simon]

I don't know if it's worth adding

but yes we've also seen bad performance when using a Enum class with a lot of possibles values, we have one with 60 possible case and phpstan chock on it (and generating a profile file use all my remaining space, 80go and counting ^^' , so I can't even attach a profile ... )

Is this related to this performance issue ?

[ondrejmirtes]

@allan-simon It's not related, and I fixed it yesterday.

Try composer require --dev phpstan/phpstan:1.8.x-dev.

[ondrejmirtes]

Fixed by: phpstan/phpstan-src@0cc87f3

[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.