Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance Issue with 1.6.0 #101

Closed
cvigorsICBF opened this issue Jul 29, 2022 · 17 comments · Fixed by #102
Closed

Performance Issue with 1.6.0 #101

cvigorsICBF opened this issue Jul 29, 2022 · 17 comments · Fixed by #102
Labels
Bug Something isn't working
Milestone

Comments

@cvigorsICBF
Copy link

BC Break Report

Q A
Version 1.6.0

Summary

The zendframework-bridge is a dependency of other libraries we use, e.g. API Tool, Laminas Cache, Laminas Form, and after doing a composer update from 1.5.0. to 1.6.0, performance of our application has taken a significant hit.
Each request to the application takes around 1 second longer and phpunit tests run time has increased significantly.

Previous behavior

Application performance was good
PHPUnit tests completed < 2 mins

Current behavior

Application performance has degraded significantly, with requests taking an extra second to process
PHPUnit tests complete in 10 mins.

How to reproduce

The best way to reproduce is to run the unit tests.
The unit tests that uses Laminas Test's AbstractControllerTestCase->dispatch() show a significant reduction on time to complete.
Downgrading to zendframework-bridge 1.5.0 allows the unit tests to complete in the expected time.

I will look into providing a working example of the issue, but it will be next week before I can do this.
As this is a widely used library, and seems to cause a performance reduction and not a break, I think others may be experiencing poorer performance by their applications, I wanted to get this issue raised as soon as possible

@Ocramius
Copy link
Member

Hmm, could you run a profiler (xdebug profile) and compare 1.5.0 and 1.6.0?

I only see this diff: laminas:7f04939...laminas:d74d2da

Unless the bridge config being processed is gigantic, I don't understand how this could happen 🤔

@cvigorsICBF
Copy link
Author

Will this snippet do? It's taken from my development environment and sorted by Duration Exclusive desc.
You can see very slow duration time from Laminas\ZendFrameworkBridge\Replacements::__construct() at the top

I have a snippet of the same report using 1.5.0 further down. The Replacements:_construct is much faster in that report so appears much further down in the report when sorted this way. This is its entry, it only gets called once, while with 1.6.0 it is getting called 6836 times.

Laminas\ZendFrameworkBridge\Replacements::__construct() 1 0.652 0.503 0.65 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/Replacements.php:15

Zend Server Z-Ray - Request function statistics with FrameworkBridge 1.6.0

Total rows: 1635
Function Count Duration Inclusive (ms) Duration Exclusive (ms) Average (ms) Defined At
Laminas\ZendFrameworkBridge\Replacements::__construct() 6836 1,810.173 863.339 0.26 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/Replacements.php:15
str_replace() 3965008 699.656 699.656 0.00  
oci_connect() 3 366.300 366.300 122.10  
strpos() 2277039 243.069 243.069 0.00  
strtr() 26902 176.735 176.735 0.01  
oci_execute() 9 74.859 74.859 8.32  
Laminas\ZendFrameworkBridge\ConfigPostProcessor::replacementRuleMatch() 32925 105.531 45.287 0.00 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:218
Laminas\ZendFrameworkBridge\ConfigPostProcessor::__invoke() 6835 2,182.981 43.920 0.32 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:100
Laminas\ZendFrameworkBridge\ConfigPostProcessor::Laminas\ZendFrameworkBridge{closure}() 131692 41.553 33.820 0.00 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:63
oci_fetch_object() 1097 31.466 31.466 0.03  
Composer\Autoload\includeFile() 505 34.332 29.592 0.07 /home/cvigors/dev/git/api/vendor/composer/ClassLoader.php:569
Laminas\ZendFrameworkBridge\ConfigPostProcessor::replace() 32925 2,182.644 25.612 0.07 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:160
is_callable() 132085 18.807 18.807 0.00  
Laminas\ZendFrameworkBridge\ConfigPostProcessor::fallbackReplacement() 26087 168.226 8.035 0.01 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:235
Laminas\ZendFrameworkBridge\Replacements::replace() 25346 183.755 7.577 0.01 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/Replacements.php:36
Laminas\ZendFrameworkBridge\ConfigPostProcessor::initializeReplacements() 6835 1,815.606 5.725 0.27 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:437

Zend Server Z-Ray - Request function statistics with FrameworkBridge 1.5.0

Total rows: 1634
Function Count Duration Inclusive (ms) Duration Exclusive (ms) Average (ms) Defined At
oci_execute() 9 679.606 679.606 75.51  
oci_fetch_object() 1097 568.756 568.756 0.52  
oci_connect() 3 371.691 371.691 123.90  
strtr() 26902 168.508 168.508 0.01  
Laminas\ZendFrameworkBridge\ConfigPostProcessor::replacementRuleMatch() 32925 96.662 42.052 0.00 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:208
Laminas\ZendFrameworkBridge\ConfigPostProcessor::Laminas\ZendFrameworkBridge{closure}() 131692 37.195 30.296 0.00 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:60
Laminas\ZendFrameworkBridge\ConfigPostProcessor::replace() 32925 311.576 21.682 0.01 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:150
is_callable() 132085 17.541 17.541 0.00  
Composer\Autoload\includeFile() 505 15.180 11.256 0.03 /home/cvigors/dev/git/api/vendor/composer/ClassLoader.php:569
Laminas\ZendFrameworkBridge\ConfigPostProcessor::__invoke() 6835 311.615 10.068 0.04 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:97
Laminas\ZendFrameworkBridge\ConfigPostProcessor::fallbackReplacement() 26087 159.111 7.679 0.01 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/ConfigPostProcessor.php:225
Laminas\ZendFrameworkBridge\Replacements::replace() 25346 175.019 7.052 0.01 /home/cvigors/dev/git/api/vendor/laminas/laminas-zendframework-bridge/src/Replacements.php:36

@Ocramius
Copy link
Member

Hmm, interesting how Laminas\ZendFrameworkBridge\Replacements::__construct() is repeated so many times.

Can indeed see how the inclusive ConfigPostProcessor calls were non-existing before, but not now.

The bridge keeps re-initializing itself each time too.

@Ocramius
Copy link
Member

@weierophinney I don't have clear insight on how the replacements logic is initialized: is the bridge supposed to scan the config each time?

@Xerkus
Copy link
Member

Xerkus commented Jul 29, 2022

I assume this was collected on the test suite run? I suspect you might have module manager events not getting reset between tests, which results in more and more listeners attached to mergeConfig event.

public function init($moduleManager)
{
$moduleManager
->getEventManager()
->attach('mergeConfig', [$this, 'onMergeConfig']);
}

This would result in ever increasing amount of bridge's config post processor calls and twice the amount of Replacement constructor calls.

@cvigorsICBF
Copy link
Author

No, not a unit test. This was an actual API request to the application on my development environment.

@Xerkus
Copy link
Member

Xerkus commented Jul 29, 2022

This is very strange, since config post processing should ever happen once. And with config caching enabled it should not happen at all after the first call.
Replacements in 1.6.0 instantiated twice: first in ConfigPostProcessor constructor and then each time it is invoked.

In the call statistics you provided number of invocations for Replacements constructor is 1 more than number of calls to Laminas\ZendFrameworkBridge\ConfigPostProcessor::__invoke().
This is inconsistent with the code of the listener, unless post processor is invoked in recursive manner.

$processor = new ConfigPostProcessor();
$configMerger->setMergedConfig(
$processor(
$configMerger->getMergedConfig($returnAsObject = false)
)
);

And sure thing there are $this-->__invoke() calls:

$config[$key] = is_array($data) ? $this->__invoke($data, [$key]) : $data;

and
$serviceInstance = is_array($serviceInstance) ? $this->__invoke($serviceInstance) : $serviceInstance;

@Xerkus Xerkus added the Bug Something isn't working label Jul 29, 2022
@Xerkus
Copy link
Member

Xerkus commented Jul 29, 2022

What is worse, each time Replacements is created it loads a file with default replacements. file system access done many times is the biggest contributor to slowdown here.

@Xerkus
Copy link
Member

Xerkus commented Jul 29, 2022

@cvigorsICBF unless you need this package I would recommend to get rid of it entirely since it is a Zend Framework transition helper.
Remove module, or config processor if you use ConfigProvider with mezzio, then remove package from the project with replace in the root composer.json

    "replace": {
        "laminas/laminas-zendframework-bridge": "*"
    },

This would also remove autoloading overhead it is causing.

@cvigorsICBF
Copy link
Author

I'd like to remove it, as I see that it has been removed from other libraries like Form, View, Cache. I'll need to upgrade those libraries.

It still seems to be a requirement of API-Tools.
I can fix this application to use 1.5.0 though.

@weierophinney
Copy link
Member

As @Xerkus notes, the instantiation of Replacements should happen:

  • During initialization of the listener
  • When the listener is invoked
  • and if config caching is happening, only on the initial request that creates the cache

The whole point of the listener is to scan config and rewrite ZF-related keys to their Laminas equivalents, and it only needs to be done once. The main change from 1.5.0 to 1.6.0 is that we check for configuration related to the bridge itself and use that to seed the replacements rules before running them; otherwise, the way it works is identical to the previous version, and checking for that configuration is almost negligible in terms of performance (it literally pulls a single key, and then makes sure it is an array of non-empty keys and non-empty values; if you don't have any defined, it's a no-op). If you are not defining that configuration, its usage is essentially identical, and shouldn't change much in performance. (The only thing I'm not happy about is the fact I have to initialize the Replacements instance in the constructor; I did that to appease Psalm, but we could potentially get rid of that call.)

As such, I'd love to know:

  • Are you in development mode in production, by any chance? (This would mean there's no config caching.)
  • If not, have you disabled config caching by any chance?
  • And if neither of those is true: can you provide a full stack trace of a request? I'd like to know if something else is invoking this functionality.

As for Laminas API Tools... the most recent versions of those libraries either have dropped the requirement, or likely can. Do you know which ones are bringing it in? You can use composer why {package name} to find out why a package is installed, and composer show {package name} to get the version of the package installed.

@Ocramius
Copy link
Member

Does #102 solve this?

@weierophinney
Copy link
Member

Does #102 solve this?

It should; @cvigorsICBF , can you test 1.6.1, please?

@cvigorsICBF
Copy link
Author

Thankfully not in development mode in production.
image

Config cache is disabled though:
grep -R config_cache_enabled
config/application.config.php: 'config_cache_enabled' => false,

The info I would have been providing so far would be from development where development mode is enabled.

API Tools does seem to require it, api-tools-api-problem for example has it included in its composer.json
https://github.com/laminas-api-tools/api-tools-api-problem/blob/1.6.x/composer.json
I would be able to upgrade some of the others, especially where it isn't an api-tools library

composer why laminas/laminas-zendframework-bridge
laminas-api-tools/api-tools-skeleton 1.5.x-dev requires laminas/laminas-zendframework-bridge (1.5)
laminas-api-tools/api-tools 1.6.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-admin 1.9.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-admin-ui 1.5.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-api-problem 1.5.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-asset-manager 1.5.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-content-negotiation 1.7.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-content-validation 1.11.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-documentation 1.4.1 requires laminas/laminas-zendframework-bridge (^1.1)
laminas-api-tools/api-tools-hal 1.9.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-mvc-auth 1.7.1 requires laminas/laminas-zendframework-bridge (^1.1)
laminas-api-tools/api-tools-oauth2 1.8.0 requires laminas/laminas-zendframework-bridge (^1.1)
laminas-api-tools/api-tools-provider 1.5.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas-api-tools/api-tools-rest 1.7.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-code 3.5.1 requires laminas/laminas-zendframework-bridge (^1.1)
laminas/laminas-composer-autoloading 2.2.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-console 2.8.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-developer-tools 1.3.2 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-filter 2.12.0 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-form 2.17.1 requires laminas/laminas-zendframework-bridge (^1.1)
laminas/laminas-hydrator 3.2.1 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-inputfilter 2.12.1 requires laminas/laminas-zendframework-bridge (^1.0)
laminas/laminas-servicemanager 3.7.0 requires laminas/laminas-zendframework-bridge (^1.0)

@cvigorsICBF
Copy link
Author

Does #102 solve this?

It should; @cvigorsICBF , can you test 1.6.1, please?

Yes, I am going to say that it does.
Unit Test performance is consistent when using versions 1.5.0 and 1.6.1
I won't be able to test on production until I do a release next week, but version 1.6.1 looks good as far as dev is concerned

@Xerkus
Copy link
Member

Xerkus commented Jul 29, 2022

Thanks you for the report.

@Xerkus Xerkus closed this as completed Jul 29, 2022
@Ocramius Ocramius added this to the 1.6.1 milestone Jul 29, 2022
@cvigorsICBF
Copy link
Author

Thanks you all for the very quick response to this issue. It is very much appreciated.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Something isn't working
Projects
None yet
4 participants