phpstan-dba
phpstan-dba copied to clipboard
staabm
Enabling `staabm/phpstan-dba` significantly increases garbage collection activity
We noticed that since we enabled staabm/phpstan-dba in our project, a full PHPStan run without cache takes significantly longer than without it.
Running it with the extension
php ./vendor/bin/phpstan --debug 537.54s user 3.92s system 97% cpu 9:13.27 total
Running it without the extension
php ./bin/phpstan --debug 230.65s user 3.89s system 97% cpu 3:59.47 total
I triggered a trace with Tideways to see why this suddenly takes so much longer and it turns out that about 6min of the run is spent on garbage collection. Turning garbage collection off results in a significant performance boost.
Running it with the extension
php -d zend.enable_gc=0 ./vendor/bin/phpstan --debug 176.72s user 4.04s system 96% cpu 3:06.44 total
Running it without the extension
php -d zend.enable_gc=0 ./vendor/bin/phpstan --debug 153.03s user 3.25s system 98% cpu 2:39.39 total
Is there any chance you encountered similar effects and already have an idea what could cause this? Otherwise, I'll look into some memory profiling in the next days to see if I can find a cause for this. Happy to share additional info but not really sure what might actually be helpful here.
Thanks for the report.
Is the problem reproducible in a minimal repo or similat?
As of right now, I haven't been able to reproduce this on smaller repositories. For instance, running PHPStan just on certain subfolders where we have our SQL queries, runs through in a few seconds and garbage collection activity is similar with and without the extension enabled.
which phpstan-dba config options do you use?
maybe you can use tideways to look into where most memory consumption happens, so we can get an idea where all the memory trash is generated.
it might also make sense to disable rules and extensions to narrow it down further
The config is more or less the default. Setting debug false/true doesn't make a difference
<?php declare(strict_types=1);
use staabm\PHPStanDba\QueryReflection\PdoPgSqlQueryReflector;
use staabm\PHPStanDba\QueryReflection\QueryReflection;
use staabm\PHPStanDba\QueryReflection\RecordingQueryReflector;
use staabm\PHPStanDba\QueryReflection\ReflectionCache;
use staabm\PHPStanDba\QueryReflection\RuntimeConfiguration;
QueryReflection::setupReflector(
new RecordingQueryReflector(
ReflectionCache::create(
__DIR__ . '/../.phpstan-dba.cache',
),
new PdoPgSqlQueryReflector(
new \PDO('pgsql:host=localhost;port=5432;dbname=database'),
),
),
(new RuntimeConfiguration())->debugMode(true),
);
I try to pinpoint this to specific rules/extensions but this might take a while as every run takes a few minutes. Will report back once I have more info.
Alright, I figured out what is causing this. If I fully remove
includes:
- vendor/staabm/phpstan-dba/config/dba.neon
and only configure this one service
services:
-
class: staabm\PHPStanDba\Ast\PreviousConnectingVisitor
tags:
- phpstan.parser.richParserNodeVisitor
then the run is suddenly 6min longer. The bigger the repository to analyze the bigger the impact.
Thanks for looking into it. I guess its the same problem as https://phpstan.org/blog/preprocessing-ast-for-custom-rules
could you please try whether https://github.com/staabm/phpstan-dba/pull/670 at least helps a bit to reduce your pain?
and please also try https://github.com/staabm/phpstan-dba/pull/671
at best also give your project a try with both PRs applied at the same time, so we know about the impact of each in isolation and also the combination
Apologies, somehow I missed the second PR this morning. Unfortunately, no improvements.
| php ./bin/phpstan | php -d zend.enable_gc=0 ./bin/phpstan | |
|---|---|---|
| 0.2.8.1 | 9:04.60 | 3:01.07 |
| less-parents | 13:31.71 | 2:57.27 |
| less-previous | 9:20.37 | 3:00.74 |
| less-both | 14:04.19 | 2:56.77 |
So, I have been looking into this a bit. Looks like most profilers just tell you which method/function leaks the memory but not which objects are leaked. The one profiler which provides that kind of info is php-meminfo.
I was able to generate a profile with our regular setup and one where I disabled the PreviousConnectingVisitor as this seems to be the cause of the leak. The dump was triggered as part of staabm\PHPStanDba\QueryReflection\RuntimeConfiguration::__destruct which only gets called at the very end of the PHPStan run. Below you find the top 50 entries as shown by the summary command of php-meminfo for both runs. Happy to run any further analysis/commands on those profiles.
There are definitely some types where the instances count multiplies by a lot like
PhpParser\Node\Expr\Variable
PhpParser\Node\Arg
With PreviousConnectingVisitor enabled
+-----------------------------------------------------------------------------------------------------+-----------------+-----------------------------+
| Type | Instances Count | Cumulated Self Size (bytes) |
+-----------------------------------------------------------------------------------------------------+-----------------+-----------------------------+
| int | 9144770 | 146316320 |
| string | 3252423 | 170329668 |
| array | 3179860 | 228949920 |
| bool | 2205655 | 35290480 |
| null | 1594589 | 25513424 |
| PHPStan\BetterReflection\Reflection\ReflectionNamedType | 328327 | 23639544 |
| PHPStan\BetterReflection\Reflection\ReflectionMethod | 293457 | 21128904 |
| PhpParser\Node\Identifier | 197649 | 14230728 |
| PhpParser\Node\Expr\Variable | 153849 | 11077128 |
| PhpParser\Node\Name | 125680 | 9048960 |
| PhpParser\Node\Arg | 103414 | 7445808 |
| (null) | 86718 | 1387488 |
| PhpParser\Node\Name\FullyQualified | 79121 | 5696712 |
| PhpParser\Node\Scalar\String_ | 74724 | 5380128 |
| PhpParser\Node\Expr\MethodCall | 71594 | 5154768 |
| PhpParser\Node\Stmt\Expression | 45340 | 3264480 |
| PHPStan\Type\Generic\TemplateTypeMap | 45078 | 3245616 |
| PHPStan\BetterReflection\Reflection\ReflectionParameter | 37262 | 2682864 |
| PhpParser\Node\Expr\ArrayItem | 37151 | 2674872 |
| PHPStan\Reflection\Php\NativeBuiltinMethodReflection | 28804 | 2073888 |
| PHPStan\BetterReflection\Reflection\Adapter\ReflectionMethod | 28804 | 2073888 |
| PHPStan\Reflection\Php\PhpMethodReflection | 28370 | 2042640 |
| PHPStan\Type\ObjectType | 27857 | 2005704 |
| PhpParser\Node\Expr\PropertyFetch | 27221 | 1959912 |
| PHPStan\Type\MixedType | 26552 | 1911744 |
| PhpParser\Node\Expr\Assign | 23687 | 1705464 |
| PhpParser\Node\Param | 21319 | 1534968 |
| PHPStan\Analyser\NameScope | 20351 | 1465272 |
| PhpParser\Node\Expr\Array_ | 20151 | 1450872 |
| PhpParser\Node\Stmt\Use_ | 19153 | 1379016 |
| PhpParser\Node\Stmt\UseUse | 19153 | 1379016 |
| PhpParser\Node\Stmt\ClassMethod | 16830 | 1211760 |
| PHPStan\Type\StringType | 15727 | 1132344 |
| PHPStan\Reflection\Php\PhpParameterReflection | 15611 | 1123992 |
| PHPStan\BetterReflection\Reflection\Adapter\ReflectionParameter | 15611 | 1123992 |
| PhpParser\Node\Expr\ConstFetch | 13848 | 997056 |
| PhpParser\Node\Expr\ClassConstFetch | 13453 | 968616 |
| PhpParser\Node\Scalar\LNumber | 13289 | 956808 |
| PHPStan\Type\UnionType | 11788 | 848736 |
| PHPStan\Reflection\FunctionVariantWithPhpDocs | 11264 | 811008 |
| PhpParser\Node\Stmt\Return_ | 10221 | 735912 |
| PHPStan\BetterReflection\Reflection\ReflectionUnionType | 10164 | 731808 |
| PHPStan\BetterReflection\Reflection\ReflectionProperty | 9987 | 719064 |
| PHPStan\Symfony\Service | 9970 | 717840 |
| PhpParser\Comment\Doc | 9434 | 679248 |
| PHPStan\PhpDocParser\Ast\Type\IdentifierTypeNode | 9018 | 649296 |
| PHPStan\Reflection\ClassReflection | 8292 | 597024 |
| PHPStan\Type\NullType | 8214 | 591408 |
| PhpParser\Node\Expr\ArrayDimFetch | 8213 | 591336 |
| PHPStan\Type\Constant\ConstantStringType | 8164 | 587808 |
Without PreviousConnectingVisitor
+-----------------------------------------------------------------------------------------------------+-----------------+-----------------------------+
| Type | Instances Count | Cumulated Self Size (bytes) |
+-----------------------------------------------------------------------------------------------------+-----------------+-----------------------------+
| int | 3281557 | 52504912 |
| string | 1906218 | 119637386 |
| bool | 1904472 | 30471552 |
| array | 1720931 | 123907032 |
| null | 1363310 | 21812960 |
| PHPStan\BetterReflection\Reflection\ReflectionNamedType | 328327 | 23639544 |
| PHPStan\BetterReflection\Reflection\ReflectionMethod | 293457 | 21128904 |
| (null) | 86718 | 1387488 |
| PhpParser\Node\Identifier | 56294 | 4053168 |
| PHPStan\Type\Generic\TemplateTypeMap | 45072 | 3245184 |
| PhpParser\Node\Name | 41610 | 2995920 |
| PHPStan\BetterReflection\Reflection\ReflectionParameter | 37262 | 2682864 |
| PhpParser\Node\Name\FullyQualified | 34978 | 2518416 |
| PHPStan\Reflection\Php\NativeBuiltinMethodReflection | 28804 | 2073888 |
| PHPStan\BetterReflection\Reflection\Adapter\ReflectionMethod | 28804 | 2073888 |
| PHPStan\Reflection\Php\PhpMethodReflection | 28370 | 2042640 |
| PhpParser\Node\Scalar\String_ | 27309 | 1966248 |
| PHPStan\Type\MixedType | 26425 | 1902600 |
| PHPStan\Type\ObjectType | 24932 | 1795104 |
| PHPStan\Analyser\NameScope | 20351 | 1465272 |
| PhpParser\Node\Expr\ArrayItem | 15969 | 1149768 |
| PHPStan\Reflection\Php\PhpParameterReflection | 15611 | 1123992 |
| PHPStan\BetterReflection\Reflection\Adapter\ReflectionParameter | 15611 | 1123992 |
| PHPStan\Type\StringType | 15509 | 1116648 |
| PHPStan\Type\UnionType | 11645 | 838440 |
| PHPStan\Reflection\FunctionVariantWithPhpDocs | 11264 | 811008 |
| PHPStan\BetterReflection\Reflection\ReflectionUnionType | 10164 | 731808 |
| PHPStan\BetterReflection\Reflection\ReflectionProperty | 9987 | 719064 |
| PHPStan\Symfony\Service | 9970 | 717840 |
| PHPStan\PhpDocParser\Ast\Type\IdentifierTypeNode | 9018 | 649296 |
| PhpParser\Node\Expr\Array_ | 8584 | 618048 |
| PHPStan\Reflection\ClassReflection | 8289 | 596808 |
| PHPStan\Type\NullType | 8173 | 588456 |
| PHPStan\Type\Constant\ConstantStringType | 7955 | 572760 |
| PhpParser\Node\Expr\Variable | 7253 | 522216 |
| PHPStan\Type\ArrayType | 7130 | 513360 |
| PHPStan\Type\VoidType | 6719 | 483768 |
| PhpParser\Node\Expr\ConstFetch | 5952 | 428544 |
| PHPStan\PhpDocParser\Ast\PhpDoc\PhpDocTagNode | 5908 | 425376 |
| PhpParser\Node\Arg | 5785 | 416520 |
| PhpParser\Comment\Doc | 5558 | 400176 |
| PHPStan\Type\IntegerType | 5531 | 398232 |
| PhpParser\Node\Param | 5265 | 379080 |
| PHPStan\BetterReflection\Reflection\ReflectionClass | 4990 | 359280 |
| PHPStan\BetterReflection\SourceLocator\Located\LocatedSource | 4960 | 357120 |
| PHPStan\BetterReflection\Reflection\Adapter\ReflectionClass | 4744 | 341568 |
| PHPStan\Type\Generic\TemplateTypeParameterStrategy | 4686 | 337392 |
| PHPStan\BetterReflection\Reflection\ReflectionAttribute | 4632 | 333504 |
| PhpParser\Node\Scalar\LNumber | 4399 | 316728 |
| PHPStan\Type\Generic\TemplateTypeVarianceMap | 4353 | 313416 |
and could you please try https://github.com/staabm/phpstan-dba/pull/729 which is a new attempt to less references between AST nodes
I confirm this is still an issue with PHPStan 2.x. The changes in #729 definitely help quite a bit and reduce the overhead by more than 50%
| php ./bin/phpstan | php -d zend.enable_gc=0 ./bin/phpstan | |
|---|---|---|
| 0.3.1 | 6min32s | 2min45s |
| dev-prev 464b327 | 4min11s | 2min39s |
awesome thanks. I merged #729 and released 0.3.2
opened another suggestion with https://github.com/staabm/phpstan-dba/pull/730
could you measure this also on your project?
Nice another win! Running PHPStan with dev-weak fa8541a brings the time down to 3min34s. Time with garbage collection disabled stays the same.
Nice another win! Running PHPStan with dev-weak fa8541a brings the time down to 3min34s.
thanks, released as 0.3.3
I am out of ideas for further improvemens.
could you do another measure like https://github.com/staabm/phpstan-dba/issues/667#issuecomment-2469305049 ?
another question: could you have a look of a phpstan run not at all loading phpstan-dba (regular vs. disabled-gc), so we can see whether plain phpstan might also need some GC quirks
ok, one last idea you could check :)
https://github.com/staabm/phpstan-dba/pull/731
No improvements, but on the bright side, it looks like all/most of the overhead is now coming from elsewhere.
| php ./bin/phpstan | php -d zend.enable_gc=0 ./bin/phpstan | |
|---|---|---|
| 0.3.33 | 3min28s | 2min38s |
| dev-less-arg 33363d4 | 3min31s | 2min38s |
| staabm/phpstan-dba disabled | 3min17s | 2min29s |
Thanks a lot for looking into this! I'll play around with disabling the other extensions to see where the remaining ~1min of added time is coming from and will report it there.
Thats great news. Hopefully none of my other extensions responsible for the remaining stuff ;-)