View Issue Details
|ID||Project||Category||View Status||Date Submitted||Last Update|
|0001988||Xdebug||Uncategorized||public||2021-06-24 06:56||2021-08-18 12:23|
|Status||closed||Resolution||no change required|
|Platform||IA64||OS||Ubuntu Linux (PHP in Docker)||OS Version||20.04|
|Summary||0001988: Potentially slow performance of ReflectionMethod::getPrototype|
|Description||When "develop" mode is activated, calls to ReflectionMethod::getPrototype get very slow (~7ms) in some conditions. I didn't manage to build a simple reproducer, for me this only occurs when building the Symfony DIC container (where this function will be called thousands of times, leading to request durations of 30+ seconds). But for this case the problem is 100% reproducible.|
After deactivating Xdebug, duration of the function call is negligible (~2s for the complete request instead of 30s, but this comes from other sources, getPrototype has practically no impact then). Stopping the listener or removing the trigger cookie is not enough; also Xdebug is configured to be activated on trigger only.
Thank you for your work!
|Steps To Reproduce||A minimal Symfony project reproducing the issue can be found here: https://github.com/umulmrum/symfony-perf-test (just build the container - let me know if you need a pointer on how to run a Symfony app)|
I didn't report this to Symfony as I can't see anything special in their method usage, so thought it might be best here. The problem is reproducible for colleagues using the same Docker setup, so it isn't specific to my machine but might somehow be specific to our setup, though I can't think of any cause (if you have a suggestion, I'm happy to investigate further).
|Additional Information||The slowness happens in \Symfony\Component\DependencyInjection\Compiler\AutowireRequiredMethodsPass|
|Tags||No tags attached.|
|Operating System||Ubuntu Linux|
Did some tests and would like to share the results:
The problem DOES occur on another machine with a plain setup (no Docker, fresh PHP 7.4 install, Xdebug 3.0.4) with the linked simple Symfony app.
The problem does NOT occur when downgrading to Xdebug 2.9.8 using my real-world application (and otherwise unchanged environment). Symfony container build time goes down to ~12s which is expected. As the container grew in the meantime, build time went up to 158s with Xdebug 3.0.4 (with 12507 calls to ReflectionMethod::getPrototype using up 129s = 81% of the wall time according to Blackfire)
Thanks again for your help!
Just acknowledging that I've seen the issue, but I didn't have time yet to try out your docker container.
I suspect that because Xdebug 3 removed a bunch of settings, it is always doing more work creating stack traces. I suspect that the Symfony methods here might include very big objects etc in the function call that happens many times. You can try setting https://xdebug.org/docs/all_settings#var_display_max_depth to a lower value (1, instead of the default 3) to see if that makes things better. If you only care about debugging with Xdebug, then you can set xdebug.mode=debug, and then all the work that Xdebug does in 'develop' mode should not be done.
@derick: Thank you for your reply, that's the right direction. I found that we even configured var_display_max_depth = 10 (maybe I'll find out why) so that seems to be the reason why this problem hurt us more than others. When reducing the value to 3, build time is reduced by half, and when reducing to 1 it's 11s compared to 6s without Xdebug.
Disabling debug mode and setting var_display_max_depth = 3 will reduce wall time to 9s.
So we will definitely use some of your suggestions. If you can find the time I still appreciate optimization on Xdebug's side so that it's harder to shoot oneself in the foot. In any case thanks again :-)
||I have already done most of these optimisations with Xdebug 3.0, so I will be closing this issue. There will always be ongoing work on making Xdebug more performant.|
|2021-06-24 06:56||umulmrum||New Issue|
|2021-07-27 09:31||umulmrum||Note Added: 0005943|
|2021-08-06 17:57||derick||Status||new => acknowledged|
|2021-08-06 17:57||derick||Note Added: 0005962|
|2021-08-16 09:08||umulmrum||Note Added: 0005982|
|2021-08-18 12:23||derick||Assigned To||=> derick|
|2021-08-18 12:23||derick||Status||acknowledged => closed|
|2021-08-18 12:23||derick||Resolution||open => no change required|
|2021-08-18 12:23||derick||Note Added: 0005987|