Significant performance degradation with enable_lazy_ghost_objects: true

[javer]

Bug Report

Q	A
BC Break	no
Version	2.17.1

Summary

After updating ORM from 2.15.2 to 2.17.1 and turning on enable_lazy_ghost_objects as it's suggested I've noticed a significant performance degradation during test suite running. The overall suite became slower by noticeable 30%. Localizing the slow spot I've found that ProxyReferenceRepository::load() now takes 50 seconds in total instead of the previous 3.86 seconds, i.e. became 13x slower.
Tracking down ProxyReferenceRepository::load() -> ProxyReferenceRepository::unserialize() I've found that EntityManager::getReference() became 23x slower (2.055 seconds -> 47.888 seconds in total). This real project has hundreds of entities and complex relations between them. During running test suite with 1k+ scenarios a lot of fixtures are generated, saved and loaded (including references):

Time in seconds	enable_lazy_ghost_objects: false	enable_lazy_ghost_objects: true	Slowdown
EntityManager::getReference()	2.055900	47.887696	23.29x
UnitOfWork::tryGetById()	0.277827	9.693281	34.89x
ProxyFactory::getProxy()	0.751345	27.942798	37.19x
UnitOfWork::registerManaged()	0.611383	9.814827	16.05x

I've created a test command to reproduce the issue, and running it in the same project I get:

Time in seconds	enable_lazy_ghost_objects: false	enable_lazy_ghost_objects: true	Slowdown
Total	1.922614	8.043023	4.18x
EntityManager::getReference()	1.784766	7.948818	4.45x
UnitOfWork::tryGetById()	0.232570	0.254660	1.09x
ProxyFactory::getProxy()	0.605608	4.091646	6.76x
UnitOfWork::registerManaged()	0.547479	3.200220	5.85x

I've created a small reproducer: https://github.com/javer/doctrine-orm-lazy-ghost
It's a fresh Symfony 6.3 project with one additional commit: javer/doctrine-orm-lazy-ghost@36a3e20
Running bin/console app:test:orm I have the following results:

Time in seconds	enable_lazy_ghost_objects: false	enable_lazy_ghost_objects: true	Slowdown
Total	2.388989	4.273117	1.79x
UnitOfWork::tryGetById()	0.340158	0.349181	1.03x
ProxyFactory::getProxy()	0.709970	2.551538	3.59x
UnitOfWork::registerManaged()	0.776654	0.818202	1.05x

Slowdown numbers are not so high as in a real project, but there is only one simple entity without any relations, and no save/load operations, only getting references. Even in this simple case ProxyFactory::getProxy() slowdown by almost 4x is too expensive for using enable_lazy_ghost_objects.

Taking into account that enable_lazy_ghost_objects will be always true in ORM 3.0 I think it's worth fixing it.

How to reproduce

git clone https://github.com/javer/doctrine-orm-lazy-ghost
cd doctrine-orm-lazy-ghost
composer install
bin/console app:test:orm

Expected behavior

Turning on enable_lazy_ghost_objects shouldn't have a noticeable impact on the performance.

[derrabus]

cc @nicolas-grekas

[michnovka]

Has anybody else managed to reproduce this issue?

[marforon]

Yes, it's drawn back for us to upgrade; this represents a significant performance degradation.

[rrehbein]

Starting from the reproduction instructions javar left of:

git clone https://github.com/javer/doctrine-orm-lazy-ghost
cd doctrine-orm-lazy-ghost
composer install
bin/console app:test:orm

Run on an AWS EC2 AL2023 c5.large with php version:

PHP 8.2.15 (cli) (built: Jan 16 2024 12:19:32) (NTS gcc x86_64)
Copyright (c) The PHP Group
Zend Engine v4.2.15, Copyright (c) Zend Technologies
    with Zend OPcache v8.2.15, Copyright (c), by Zend Technologies

Results:

test	lazy: true	lazy: false	note
sample code run as-is	7.194498	2.752580
... after composer update	7.263963	2.794993
... after upgrade to SF6.4	7.284943	2.840720	This didn't change ORM version, so not really relevant
... after upgrade to ORM v3	6.807350	n/a
TestOrmCommand added to another project	7.287983	2.722694	a blended SF5.4/6.4 mid-upgrade

Reproduction code after SF6.4 update:

$ composer show 'doctrine/*' | awk '{print $1 " " $2}' | column -t

doctrine/cache                       2.2.0
doctrine/collections                 2.1.4
doctrine/common                      3.4.3
doctrine/dbal                        3.8.2
doctrine/deprecations                1.1.3
doctrine/doctrine-bundle             2.11.3
doctrine/doctrine-migrations-bundle  3.3.0
doctrine/event-manager               2.0.0
doctrine/inflector                   2.0.10
doctrine/instantiator                2.0.0
doctrine/lexer                       3.0.1
doctrine/migrations                  3.7.2
doctrine/orm                         2.18.0
doctrine/persistence                 3.2.0
doctrine/sql-formatter               1.1.3

Reproduction code after ORM v3 upgrade:

$ composer show 'doctrine/*' | awk '{print $1 " " $2}' | column -t

doctrine/cache                       2.2.0
doctrine/collections                 2.1.4
doctrine/dbal                        4.0.0
doctrine/deprecations                1.1.3
doctrine/doctrine-bundle             2.11.3
doctrine/doctrine-migrations-bundle  3.3.0
doctrine/event-manager               2.0.0
doctrine/inflector                   2.0.10
doctrine/instantiator                2.0.0
doctrine/lexer                       3.0.1
doctrine/migrations                  3.7.2
doctrine/orm                         3.0.0
doctrine/persistence                 3.2.0
doctrine/sql-formatter               1.1.3

Other project:

$ composer show 'doctrine/*' | awk '{print $1 " " $2}' | column -t

doctrine/annotations               2.0.1
doctrine/cache                     2.2.0
doctrine/collections               2.1.4
doctrine/common                    3.4.3
doctrine/data-fixtures             1.7.0
doctrine/dbal                      3.8.0
doctrine/deprecations              1.1.2
doctrine/doctrine-bundle           2.11.1
doctrine/doctrine-fixtures-bundle  3.5.1
doctrine/event-manager             1.2.0
doctrine/inflector                 2.0.9
doctrine/instantiator              1.5.0
doctrine/lexer                     2.1.0
doctrine/orm                       2.17.4
doctrine/persistence               3.2.0
doctrine/sql-formatter             1.1.3

[beberlei]

Here is a screenshot of a compare callgraph in Tideways Profiler, it shows the relevant parts that are slow:

• createLazyGhost static factory
• The callback returned from ProxyFactory::getProxyFactory

The overall slowdown is roughly in line what @rrehbein reported.

I will take a deeper look when i have more time.

[beberlei]

I looked at createLazyGhost factory method and found that it acts both as an initializer when invoked the first time, and then as a factory for lazy ghosts. It seems when the initializer code is run every time as well, this causes a lot of wasted CPU and allocated memory. A simple attempt to split both methods up cut 50% of the slowdown:

I hardcoded it into my doctrine/orm and symfony/var_exporter components of @javer testproject. So no nice diff, the changed lines are here: https://gist.github.com/beberlei/97899ea7ce4261502a6df1300ab9f181

This would require var-exporter to add these new methods, so I am looking to find a simpler fix that cuts the time and memory in createLazyGhost already.

[nicolas-grekas]

Below is a better patch for the ORM side. Together with this one symfony/symfony#54253, I get the following stats on my machine:

• lazy-ghosts disabled: 2.94 s
• lazy-ghosts patched: 4.02 s
• lazy-ghosts unpatched: 7.83 s

Locally, I also have a native proxy implementation for php-src (I need to write an RFC about it), and with it, I get 3.27s with the current API and implementation. That's good food for thoughts on my side to move this RFC forward :)

Here is the Blackfire.io comparison between disabled and patched lazy-ghosts:
https://blackfire.io/profiles/compare/4561cec4-97af-4c40-a180-ee5745ca8119/graph

The patch for ProxyFactory.php

--- a/src/Proxy/ProxyFactory.php
+++ b/src/Proxy/ProxyFactory.php
@@ -360,11 +360,11 @@ EOPHP;
      */
     private function createLazyInitializer(ClassMetadata $classMetadata, EntityPersister $entityPersister, IdentifierFlattener $identifierFlattener): Closure
     {
-        return static function (InternalProxy $proxy, InternalProxy $original) use ($entityPersister, $classMetadata, $identifierFlattener): void {
-            $identifier = $classMetadata->getIdentifierValues($original);
-            $entity     = $entityPersister->loadById($identifier, $original);
+        return static function (InternalProxy $proxy) use ($entityPersister, $classMetadata, $identifierFlattener): void {
+            $identifier = $classMetadata->getIdentifierValues($proxy);
+            $original   = $entityPersister->loadById($identifier);
 
-            if ($entity === null) {
+            if ($original === null) {
                 throw EntityNotFoundException::fromClassNameAndIdentifier(
                     $classMetadata->getName(),
                     $identifierFlattener->flattenIdentifier($classMetadata, $identifier)
@@ -382,7 +382,7 @@ EOPHP;
                     continue;
                 }
 
-                $property->setValue($proxy, $property->getValue($entity));
+                $property->setValue($proxy, $property->getValue($original));
             }
         };
     }
@@ -468,9 +468,7 @@ EOPHP;
         $identifierFields = array_intersect_key($class->getReflectionProperties(), $identifiers);
 
         $proxyFactory = Closure::bind(static function (array $identifier) use ($initializer, $skippedProperties, $identifierFields, $className): InternalProxy {
-            $proxy = self::createLazyGhost(static function (InternalProxy $object) use ($initializer, &$proxy): void {
-                $initializer($object, $proxy);
-            }, $skippedProperties);
+            $proxy = self::createLazyGhost($initializer, $skippedProperties);
 
             foreach ($identifierFields as $idField => $reflector) {
                 if (! isset($identifier[$idField])) {

[michnovka]

Is the goal to get to the same or better performance than with lazyghosts disabled or is this considered "good enough" result?

[nicolas-grekas]

This is good enough to me. The core issue with the current code is the initializer closure that creates a self-reference in the object graph, which adds a lot of pressure on the garbage collector. The other changes are minor perf optim that shouldn't matter much in practice.
Note that we're comparing two widely different set of proxies. The legacy proxy system has many serious limitations.

[beberlei]

@nicolas-grekas does your change here require the symfony change or are they independent?

The improvement is good enough for me too for now.

[nicolas-grekas]

The patch are independent. BUT the ORM patch makes the test suite fail on one or two test cases which we need to investigate.

[Tristan971]

This is good enough to me. [...] The legacy proxy system has many serious limitations.

I don't doubt that the new setup is better, and I'm sure eventually it will catch up, but right now we're seeing the same results as you outline in #11087 (comment), so losing half the performance (from 17s to 29s for setting up a subset of test fixtures).

That's many times better than before your patch, of course, but still a fairly high cost... I hope the issue keeps getting some attention until we're in a closer performance range.

EDIT: turns out I was comparing on 2.19.2 which lacks the patch; using 2.19.3 seems to fix the issue entirely for our use-case (at least with synthetic loads, we'll have to compare for real load).

[nicolas-grekas]

EDIT: turns out I was comparing on 2.19.2 which lacks the patch; using 2.19.3 seems to fix the issue entirely for our use-case (at least with synthetic loads, we'll have to compare for real load).

Good news!

We can close this issue then :)

[greg0ire]

Let's! Thanks @nicolas-grekas !

[Tristan971]

turns out I was comparing on 2.19.2 which lacks the patch; using 2.19.3 seems to fix the issue entirely for our use-case (at least with synthetic loads, we'll have to compare for real load).

For what it's worth, we also see no performance difference at all after deploying to our production:

So I can only agree with the decision to close it 👍

[javer]

I can confirm that after upgrading to doctrine/orm 2.19.3 turning on enable_lazy_ghost_objects makes the initial test suite slower only by negligible 5%.

Thank you very much @beberlei and @nicolas-grekas !