View Issue Details

IDProjectCategoryView StatusLast Update
0002234XdebugStep Debuggingpublic2024-05-06 10:28
Reporterpsihius Assigned Toderick  
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionfixed 
PlatformlinuxOSDebian GNU/LinuxOS Version 12
Product Version3.3.1 
Fixed in Version3.3.2 
Summary0002234: When Step Debugging is enabled in Trigger mode, there is a 27+ times slowdown in performance despite no step debug session
Description

On a bigger Symfony project (Symfony 6.3 and EasyAdmin 4.8.8) the cache clearing operation has a huge slowdown that makes xdebug almost unusable in the development environment on 3.3.x series where this was not an issue up to 3.2.2 (tested also on 3.1.6).

All tests are done on the latest php-fpm:8.2 docker image, with only difference being changing the version of the xdebug being compiled for it:


Copyright (c) The PHP Group
Zend Engine v4.2.14, Copyright (c) Zend Technologies
    with Zend OPcache v8.2.14, Copyright (c), by Zend Technologies```

For 3.3.0 and 3.3.1
When I run `bin/console cache:clear` with XDEBUG_MODE=off - the process runs in 3.5 seconds
When I run `bin/console cache:clear` with XDEBUG_MODE=debug and `start_with_request=trigger`  - the process runs in 1 minute and 35 seconds.
When I run `bin/console cache:clear` with XDEBUG_MODE=debug and XDEBUG_TRIGGER=PHPSTORM - the process takes 1 minute and 46 seconds (no breakpoints set, just allow it to run the whole process)

For 3.2.2
When I run `bin/console cache:clear` with XDEBUG_MODE=off - the process runs in 3.5 seconds
When I run `bin/console cache:clear` with XDEBUG_MODE=debug and `start_with_request=trigger`  - the process runs in 6.5 seconds
When I run `bin/console cache:clear` with XDEBUG_MODE=debug and XDEBUG_TRIGGER=PHPSTORM - the process takes 18.7 seconds (no breakpoints set, just allow it to run the whole process)
Steps To Reproduce

As far as I can tell, grab any sizeable application that has some commands that do heavy parsing of files like template compilation, dependency injection container rebuilding, or any parser that generates a lot of function/method calls and feed it bigger and bigger chunks of data to see bigger and bigger slowdown that snowballs more and more without activating a step debugging session.

Additional Information

I can provide access to a server where a similar project lives that's mine (same SF and EasyAdmin setup, a classic Digital Ocean droplet, no docker), but has a similar problem (2.7 sec vs 1m18sec) or we can figure out a session where I provide temp access to my PC where the project from above lives and has a docker setup that's easy to manipulate.

TagsNo tags attached.
Operating SystemLinux
PHP Version8.2.0-8.2.9

Activities

psihius

2024-01-05 11:55

reporter   ~0006749

I've taken a bog-standard Symfony 7.0 skeleton application as per official documentation and a simple docker env based on php-fpm:8.2 image, here are results:

XDebug 3.3.1

psihius@psihius-pc:~/projects/symfony$ docker compose exec php php -v
PHP 8.2.14 (cli) (built: Dec 27 2023 23:33:55) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.2.14, Copyright (c) Zend Technologies
    with Xdebug v3.3.1, Copyright (c) 2002-2023, by Derick Rethans
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=off php bin/console cache:clear

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

real    0m1,479s
user    0m0,037s
sys 0m0,030s
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=debug php bin/console cache:clear
[22] Log opened at 2024-01-05 11:51:18.937988
[22] [Config] INFO: Control socket set up succesfully: '@xdebug-ctrl.22'
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] Log closed at 2024-01-05 11:51:45.772269

real    0m26,968s
user    0m0,030s
sys 0m0,035s
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=debug -e XDEBUG_TRIGGER=PHPSTORM php bin/console cache:clear
[29] Log opened at 2024-01-05 11:51:55.534683
[29] [Config] INFO: Control socket set up succesfully: '@xdebug-ctrl.29'
[29] [Step Debug] INFO: Connecting to configured address/port: host.docker.internal:9003.
[29] [Step Debug] INFO: Connected to debugging client: host.docker.internal:9003 (through xdebug.client_host/xdebug.client_port).
[29] [Step Debug] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" fileuri="file:///var/www/html/bin/console" language="PHP" xdebug:language_version="8.2.14" protocol_version="1.0" appid="29" idekey="PHPSTORM"><engine version="3.3.1"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]></url><copyright><![CDATA[Copyright (c) 2002-2023 by Derick Rethans]]></copyright></init>

[29] [Step Debug] <- eval -i 1 -- KHN0cmluZykoaW5pX2dldCgneGRlYnVnLmNvdmVyYWdlX2VuYWJsZScpLic7Jy5pbmlfZ2V0KCd4ZGVidWcucHJvZmlsZXJfZW5hYmxlJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfYXV0b3N0YXJ0JykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfY29ubmVjdF9iYWNrJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfbW9kZScpKQ==
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="1"><property type="string" size="635" encoding="base64"><![CDATA[VGhpcyBzZXR0aW5nIGhhcyBiZWVuIGNoYW5nZWQsIHNlZSB0aGUgdXBncmFkaW5nIGd1aWRlIGF0IGh0dHBzOi8veGRlYnVnLm9yZy9kb2NzL3VwZ3JhZGVfZ3VpZGUjY2hhbmdlZC14ZGVidWcuY292ZXJhZ2VfZW5hYmxlO1RoaXMgc2V0dGluZyBoYXMgYmVlbiBjaGFuZ2VkLCBzZWUgdGhlIHVwZ3JhZGluZyBndWlkZSBhdCBodHRwczovL3hkZWJ1Zy5vcmcvZG9jcy91cGdyYWRlX2d1aWRlI2NoYW5nZWQteGRlYnVnLnByb2ZpbGVyX2VuYWJsZTtUaGlzIHNldHRpbmcgaGFzIGJlZW4gY2hhbmdlZCwgc2VlIHRoZSB1cGdyYWRpbmcgZ3VpZGUgYXQgaHR0cHM6Ly94ZGVidWcub3JnL2RvY3MvdXBncmFkZV9ndWlkZSNjaGFuZ2VkLXhkZWJ1Zy5yZW1vdGVfYXV0b3N0YXJ0O1RoaXMgc2V0dGluZyBoYXMgYmVlbiBjaGFuZ2VkLCBzZWUgdGhlIHVwZ3JhZGluZyBndWlkZSBhdCBodHRwczovL3hkZWJ1Zy5vcmcvZG9jcy91cGdyYWRlX2d1aWRlI2NoYW5nZWQteGRlYnVnLnJlbW90ZV9jb25uZWN0X2JhY2s7VGhpcyBzZXR0aW5nIGhhcyBiZWVuIGNoYW5nZWQsIHNlZSB0aGUgdXBncmFkaW5nIGd1aWRlIGF0IGh0dHBzOi8veGRlYnVnLm9yZy9kb2NzL3VwZ3JhZGVfZ3VpZGUjY2hhbmdlZC14ZGVidWcucmVtb3RlX21vZGU=]]></property></response>

[29] [Step Debug] <- feature_set -i 2 -n show_hidden -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="2" feature="show_hidden" success="1"></response>

[29] [Step Debug] <- feature_set -i 3 -n max_depth -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="3" feature="max_depth" success="1"></response>

[29] [Step Debug] <- feature_set -i 4 -n max_children -v 100
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="4" feature="max_children" success="1"></response>

[29] [Step Debug] <- feature_set -i 5 -n extended_properties -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="5" feature="extended_properties" success="1"></response>

[29] [Step Debug] <- feature_set -i 6 -n notify_ok -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="6" feature="notify_ok" success="1"></response>

[29] [Step Debug] <- feature_set -i 7 -n resolved_breakpoints -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="7" feature="resolved_breakpoints" success="1"></response>

[29] [Step Debug] <- feature_set -i 8 -n breakpoint_include_return_value -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="8" feature="breakpoint_include_return_value" success="1"></response>

[29] [Step Debug] <- stdout -i 9 -c 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stdout" transaction_id="9" success="1"></response>

[29] [Step Debug] <- status -i 10
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="status" transaction_id="10" status="starting" reason="ok"></response>

[29] [Step Debug] <- step_into -i 11
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="step_into" transaction_id="11" status="break" reason="ok"><xdebug:message filename="file:///var/www/html/bin/console" lineno="7"></xdebug:message></response>

[29] [Step Debug] <- eval -i 12 -- aXNzZXQoJF9TRVJWRVJbJ1BIUF9JREVfQ09ORklHJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="12"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 13 -- aXNzZXQoJF9TRVJWRVJbJ1NFUlZFUl9OQU1FJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="13"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 14 -- aXNzZXQoJF9TRVJWRVJbJ1NTSF9DT05ORUNUSU9OJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="14"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 15 -- aXNzZXQoJF9TRVJWRVJbJ1NFUlZFUl9BRERSJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="15"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- breakpoint_set -i 16 -t line -f file:///home/psihius/projects/casa-market/src/Controller/HostArea/LocationCrudController.php -n 65
[29] [Step Debug] WARN: Breakpoint file name does not exist: /home/psihius/projects/casa-market/src/Controller/HostArea/LocationCrudController.php (No such file or directory).
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="16" id="290001" resolved="unresolved"></response>

[29] [Step Debug] <- stack_get -i 17
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="17"><stack where="{main}" level="0" type="file" filename="file:///var/www/html/bin/console" lineno="7"></stack></response>

[29] [Step Debug] <- stack_get -i 18
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="18"><stack where="{main}" level="0" type="file" filename="file:///var/www/html/bin/console" lineno="7"></stack></response>

[29] [Step Debug] <- context_names -i 19
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="19"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context><context name="User defined constants" id="2"></context></response>

[29] [Step Debug] <- context_get -i 20 -d 0 -c 0
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="20" context="0"></response>

[29] [Step Debug] <- context_get -i 21 -d 0 -c 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="21" context="1"><property name="$_GET" fullname="$_GET" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_POST" fullname="$_POST" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_COOKIE" fullname="$_COOKIE" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_FILES" fullname="$_FILES" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$argv" fullname="$argv" type="array" children="1" numchildren="2" page="0" pagesize="100"><property name="0" fullname="$argv[0]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="1" fullname="$argv[1]" type="string" size="11" encoding="base64"><![CDATA[Y2FjaGU6Y2xlYXI=]]></property></property><property name="$argc" fullname="$argc" type="int"><![CDATA[2]]></property><property name="$_ENV" fullname="$_ENV" type="array" children="1" numchildren="18" page="0" pagesize="100"><property name="PATH" fullname="$_ENV[&quot;PATH&quot;]" type="string" size="60" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9zYmluOi91c3IvbG9jYWwvYmluOi91c3Ivc2JpbjovdXNyL2Jpbjovc2JpbjovYmlu]]></property><property name="HOSTNAME" fullname="$_ENV[&quot;HOSTNAME&quot;]" type="string" size="12" encoding="base64"><![CDATA[NDA5NTU4OWUxYTk3]]></property><property name="TERM" fullname="$_ENV[&quot;TERM&quot;]" type="string" size="5" encoding="base64"><![CDATA[eHRlcm0=]]></property><property type="string" size="76"><name encoding="base64"><![CDATA[UEhQSVpFX0RFUFM=]]></name><fullname encoding="base64"><![CDATA[JF9FTlZbIlBIUElaRV9ERVBTIl0=]]></fullname><value encoding="base64"><![CDATA[YXV0b2NvbmYgCQlkcGtnLWRldiAJCWZpbGUgCQlnKysgCQlnY2MgCQlsaWJjLWRldiAJCW1ha2UgCQlwa2ctY29uZmlnIAkJcmUyYw==]]></value></property><property name="PHP_INI_DIR" fullname="$_ENV[&quot;PHP_INI_DIR&quot;]" type="string" size="18" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9ldGMvcGhw]]></property><property name="PHP_CFLAGS" fullname="$_ENV[&quot;PHP_CFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_CPPFLAGS" fullname="$_ENV[&quot;PHP_CPPFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_LDFLAGS" fullname="$_ENV[&quot;PHP_LDFLAGS&quot;]" type="string" size="12" encoding="base64"><![CDATA[LVdsLC1PMSAtcGll]]></property><property name="GPG_KEYS" fullname="$_ENV[&quot;GPG_KEYS&quot;]" type="string" size="122" encoding="base64"><![CDATA[MzlCNjQxMzQzRDhDMTA0QjJCMTQ2REMzRjlDMzlEQzBCOTY5ODU0NCBFNjA5MTNFNERGMjA5OTA3RDhFMzBEOTY2NTlBOTdDOUNGMkE3OTVBIDExOThDMDExNzU5MzQ5N0E1RUM1QzE5OTI4NkFGMUY5ODk3NDY5REM=]]></property><property name="PHP_VERSION" fullname="$_ENV[&quot;PHP_VERSION&quot;]" type="string" size="6" encoding="base64"><![CDATA[OC4yLjE0]]></property><property name="PHP_URL" fullname="$_ENV[&quot;PHP_URL&quot;]" type="string" size="51" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6]]></property><property name="PHP_ASC_URL" fullname="$_ENV[&quot;PHP_ASC_URL&quot;]" type="string" size="55" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6LmFzYw==]]></property><property name="PHP_SHA256" fullname="$_ENV[&quot;PHP_SHA256&quot;]" type="string" size="64" encoding="base64"><![CDATA[NzYzZWNkMzlmY2Y1MWMzODE1YWY2ZWY2ZTQzZmE5YWEwZDBiZDhlNWE2MTUwMDllNWY0NzgwYzkyNzA1ZjU4Mw==]]></property><property name="UID" fullname="$_ENV[&quot;UID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="GID" fullname="$_ENV[&quot;GID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="XDEBUG_TRIGGER" fullname="$_ENV[&quot;XDEBUG_TRIGGER&quot;]" type="string" size="8" encoding="base64"><![CDATA[UEhQU1RPUk0=]]></property><property name="XDEBUG_MODE" fullname="$_ENV[&quot;XDEBUG_MODE&quot;]" type="string" size="5" encoding="base64"><![CDATA[ZGVidWc=]]></property><property name="HOME" fullname="$_ENV[&quot;HOME&quot;]" type="string" size="8" encoding="base64"><![CDATA[L3Zhci93d3c=]]></property></property><property name="$_REQUEST" fullname="$_REQUEST" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_SERVER" fullname="$_SERVER" type="array" children="1" numchildren="27" page="0" pagesize="100"><property name="PATH" fullname="$_SERVER[&quot;PATH&quot;]" type="string" size="60" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9zYmluOi91c3IvbG9jYWwvYmluOi91c3Ivc2JpbjovdXNyL2Jpbjovc2JpbjovYmlu]]></property><property name="HOSTNAME" fullname="$_SERVER[&quot;HOSTNAME&quot;]" type="string" size="12" encoding="base64"><![CDATA[NDA5NTU4OWUxYTk3]]></property><property name="TERM" fullname="$_SERVER[&quot;TERM&quot;]" type="string" size="5" encoding="base64"><![CDATA[eHRlcm0=]]></property><property type="string" size="76"><name encoding="base64"><![CDATA[UEhQSVpFX0RFUFM=]]></name><fullname encoding="base64"><![CDATA[JF9TRVJWRVJbIlBIUElaRV9ERVBTIl0=]]></fullname><value encoding="base64"><![CDATA[YXV0b2NvbmYgCQlkcGtnLWRldiAJCWZpbGUgCQlnKysgCQlnY2MgCQlsaWJjLWRldiAJCW1ha2UgCQlwa2ctY29uZmlnIAkJcmUyYw==]]></value></property><property name="PHP_INI_DIR" fullname="$_SERVER[&quot;PHP_INI_DIR&quot;]" type="string" size="18" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9ldGMvcGhw]]></property><property name="PHP_CFLAGS" fullname="$_SERVER[&quot;PHP_CFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_CPPFLAGS" fullname="$_SERVER[&quot;PHP_CPPFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_LDFLAGS" fullname="$_SERVER[&quot;PHP_LDFLAGS&quot;]" type="string" size="12" encoding="base64"><![CDATA[LVdsLC1PMSAtcGll]]></property><property name="GPG_KEYS" fullname="$_SERVER[&quot;GPG_KEYS&quot;]" type="string" size="122" encoding="base64"><![CDATA[MzlCNjQxMzQzRDhDMTA0QjJCMTQ2REMzRjlDMzlEQzBCOTY5ODU0NCBFNjA5MTNFNERGMjA5OTA3RDhFMzBEOTY2NTlBOTdDOUNGMkE3OTVBIDExOThDMDExNzU5MzQ5N0E1RUM1QzE5OTI4NkFGMUY5ODk3NDY5REM=]]></property><property name="PHP_VERSION" fullname="$_SERVER[&quot;PHP_VERSION&quot;]" type="string" size="6" encoding="base64"><![CDATA[OC4yLjE0]]></property><property name="PHP_URL" fullname="$_SERVER[&quot;PHP_URL&quot;]" type="string" size="51" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6]]></property><property name="PHP_ASC_URL" fullname="$_SERVER[&quot;PHP_ASC_URL&quot;]" type="string" size="55" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6LmFzYw==]]></property><property name="PHP_SHA256" fullname="$_SERVER[&quot;PHP_SHA256&quot;]" type="string" size="64" encoding="base64"><![CDATA[NzYzZWNkMzlmY2Y1MWMzODE1YWY2ZWY2ZTQzZmE5YWEwZDBiZDhlNWE2MTUwMDllNWY0NzgwYzkyNzA1ZjU4Mw==]]></property><property name="UID" fullname="$_SERVER[&quot;UID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="GID" fullname="$_SERVER[&quot;GID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="XDEBUG_TRIGGER" fullname="$_SERVER[&quot;XDEBUG_TRIGGER&quot;]" type="string" size="8" encoding="base64"><![CDATA[UEhQU1RPUk0=]]></property><property name="XDEBUG_MODE" fullname="$_SERVER[&quot;XDEBUG_MODE&quot;]" type="string" size="5" encoding="base64"><![CDATA[ZGVidWc=]]></property><property name="HOME" fullname="$_SERVER[&quot;HOME&quot;]" type="string" size="8" encoding="base64"><![CDATA[L3Zhci93d3c=]]></property><property name="PHP_SELF" fullname="$_SERVER[&quot;PHP_SELF&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="SCRIPT_NAME" fullname="$_SERVER[&quot;SCRIPT_NAME&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="SCRIPT_FILENAME" fullname="$_SERVER[&quot;SCRIPT_FILENAME&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="PATH_TRANSLATED" fullname="$_SERVER[&quot;PATH_TRANSLATED&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="DOCUMENT_ROOT" fullname="$_SERVER[&quot;DOCUMENT_ROOT&quot;]" type="string" size="0" encoding="base64"><![CDATA[]]></property><property name="REQUEST_TIME_FLOAT" fullname="$_SERVER[&quot;REQUEST_TIME_FLOAT&quot;]" type="float"><![CDATA[1704455515.5348]]></property><property name="REQUEST_TIME" fullname="$_SERVER[&quot;REQUEST_TIME&quot;]" type="int"><![CDATA[1704455515]]></property><property name="argv" fullname="$_SERVER[&quot;argv&quot;]" type="array" children="1" numchildren="2"></property><property name="argc" fullname="$_SERVER[&quot;argc&quot;]" type="int"><![CDATA[2]]></property></property></response>

[29] [Step Debug] <- context_get -i 22 -d 0 -c 2
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="22" context="2"></response>

[29] [Step Debug] <- run -i 23

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="run" transaction_id="23" status="stopping" reason="ok"></response>

[29] [Step Debug] <- detach -i 24
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="detach" transaction_id="24" status="stopping" reason="ok"></response>

[29] Log closed at 2024-01-05 11:52:23.289318

real    0m27,903s
user    0m0,029s
sys 0m0,038s
psihius@psihius-pc:~/projects/symfony$ 

XDebug 3.2.2

psihius@psihius-pc:~/projects/symfony$ docker compose exec php php -v
PHP 8.2.14 (cli) (built: Dec 27 2023 23:33:55) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.2.14, Copyright (c) Zend Technologies
    with Xdebug v3.2.2, Copyright (c) 2002-2023, by Derick Rethans
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=off php bin/console cache:clear

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

real    0m1,441s
user    0m0,025s
sys 0m0,039s
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=debug php bin/console cache:clear
[22] Log opened at 2024-01-05 11:54:52.869526
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] [Config] INFO: Trigger value for 'XDEBUG_TRIGGER' not found, falling back to 'XDEBUG_SESSION'
[22] [Config] INFO: Trigger value for 'XDEBUG_SESSION' not found, so not activating
[22] Log closed at 2024-01-05 11:54:54.885139

real    0m2,169s
user    0m0,043s
sys 0m0,022s
psihius@psihius-pc:~/projects/symfony$ time docker compose exec -e XDEBUG_MODE=debug -e XDEBUG_TRIGGER=PHPSTORM php bin/console cache:clear
[29] Log opened at 2024-01-05 11:55:04.129761
[29] [Step Debug] INFO: Connecting to configured address/port: host.docker.internal:9003.
[29] [Step Debug] INFO: Connected to debugging client: host.docker.internal:9003 (through xdebug.client_host/xdebug.client_port).
[29] [Step Debug] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" fileuri="file:///var/www/html/bin/console" language="PHP" xdebug:language_version="8.2.14" protocol_version="1.0" appid="29" idekey="PHPSTORM"><engine version="3.2.2"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]></url><copyright><![CDATA[Copyright (c) 2002-2023 by Derick Rethans]]></copyright></init>

[29] [Step Debug] <- eval -i 1 -- KHN0cmluZykoaW5pX2dldCgneGRlYnVnLmNvdmVyYWdlX2VuYWJsZScpLic7Jy5pbmlfZ2V0KCd4ZGVidWcucHJvZmlsZXJfZW5hYmxlJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfYXV0b3N0YXJ0JykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfY29ubmVjdF9iYWNrJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfbW9kZScpKQ==
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="1"><property type="string" size="635" encoding="base64"><![CDATA[VGhpcyBzZXR0aW5nIGhhcyBiZWVuIGNoYW5nZWQsIHNlZSB0aGUgdXBncmFkaW5nIGd1aWRlIGF0IGh0dHBzOi8veGRlYnVnLm9yZy9kb2NzL3VwZ3JhZGVfZ3VpZGUjY2hhbmdlZC14ZGVidWcuY292ZXJhZ2VfZW5hYmxlO1RoaXMgc2V0dGluZyBoYXMgYmVlbiBjaGFuZ2VkLCBzZWUgdGhlIHVwZ3JhZGluZyBndWlkZSBhdCBodHRwczovL3hkZWJ1Zy5vcmcvZG9jcy91cGdyYWRlX2d1aWRlI2NoYW5nZWQteGRlYnVnLnByb2ZpbGVyX2VuYWJsZTtUaGlzIHNldHRpbmcgaGFzIGJlZW4gY2hhbmdlZCwgc2VlIHRoZSB1cGdyYWRpbmcgZ3VpZGUgYXQgaHR0cHM6Ly94ZGVidWcub3JnL2RvY3MvdXBncmFkZV9ndWlkZSNjaGFuZ2VkLXhkZWJ1Zy5yZW1vdGVfYXV0b3N0YXJ0O1RoaXMgc2V0dGluZyBoYXMgYmVlbiBjaGFuZ2VkLCBzZWUgdGhlIHVwZ3JhZGluZyBndWlkZSBhdCBodHRwczovL3hkZWJ1Zy5vcmcvZG9jcy91cGdyYWRlX2d1aWRlI2NoYW5nZWQteGRlYnVnLnJlbW90ZV9jb25uZWN0X2JhY2s7VGhpcyBzZXR0aW5nIGhhcyBiZWVuIGNoYW5nZWQsIHNlZSB0aGUgdXBncmFkaW5nIGd1aWRlIGF0IGh0dHBzOi8veGRlYnVnLm9yZy9kb2NzL3VwZ3JhZGVfZ3VpZGUjY2hhbmdlZC14ZGVidWcucmVtb3RlX21vZGU=]]></property></response>

[29] [Step Debug] <- feature_set -i 2 -n show_hidden -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="2" feature="show_hidden" success="1"></response>

[29] [Step Debug] <- feature_set -i 3 -n max_depth -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="3" feature="max_depth" success="1"></response>

[29] [Step Debug] <- feature_set -i 4 -n max_children -v 100
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="4" feature="max_children" success="1"></response>

[29] [Step Debug] <- feature_set -i 5 -n extended_properties -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="5" feature="extended_properties" success="1"></response>

[29] [Step Debug] <- feature_set -i 6 -n notify_ok -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="6" feature="notify_ok" success="1"></response>

[29] [Step Debug] <- feature_set -i 7 -n resolved_breakpoints -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="7" feature="resolved_breakpoints" success="1"></response>

[29] [Step Debug] <- feature_set -i 8 -n breakpoint_include_return_value -v 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="8" feature="breakpoint_include_return_value" success="1"></response>

[29] [Step Debug] <- stdout -i 9 -c 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stdout" transaction_id="9" success="1"></response>

[29] [Step Debug] <- status -i 10
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="status" transaction_id="10" status="starting" reason="ok"></response>

[29] [Step Debug] <- step_into -i 11
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="step_into" transaction_id="11" status="break" reason="ok"><xdebug:message filename="file:///var/www/html/bin/console" lineno="7"></xdebug:message></response>

[29] [Step Debug] <- eval -i 12 -- aXNzZXQoJF9TRVJWRVJbJ1BIUF9JREVfQ09ORklHJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="12"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 13 -- aXNzZXQoJF9TRVJWRVJbJ1NFUlZFUl9OQU1FJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="13"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 14 -- aXNzZXQoJF9TRVJWRVJbJ1NTSF9DT05ORUNUSU9OJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="14"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- eval -i 15 -- aXNzZXQoJF9TRVJWRVJbJ1NFUlZFUl9BRERSJ10p
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="15"><property type="bool"><![CDATA[0]]></property></response>

[29] [Step Debug] <- breakpoint_set -i 16 -t line -f file:///home/psihius/projects/casa-market/src/Controller/HostArea/LocationCrudController.php -n 65
[29] [Step Debug] WARN: Breakpoint file name does not exist: /home/psihius/projects/casa-market/src/Controller/HostArea/LocationCrudController.php (No such file or directory).
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="breakpoint_set" transaction_id="16" id="290001" resolved="unresolved"></response>

[29] [Step Debug] <- stack_get -i 17
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="17"><stack where="{main}" level="0" type="file" filename="file:///var/www/html/bin/console" lineno="7"></stack></response>

[29] [Step Debug] <- stack_get -i 18
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stack_get" transaction_id="18"><stack where="{main}" level="0" type="file" filename="file:///var/www/html/bin/console" lineno="7"></stack></response>

[29] [Step Debug] <- context_names -i 19
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_names" transaction_id="19"><context name="Locals" id="0"></context><context name="Superglobals" id="1"></context><context name="User defined constants" id="2"></context></response>

[29] [Step Debug] <- context_get -i 20 -d 0 -c 0
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="20" context="0"></response>

[29] [Step Debug] <- context_get -i 21 -d 0 -c 1
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="21" context="1"><property name="$_GET" fullname="$_GET" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_POST" fullname="$_POST" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_COOKIE" fullname="$_COOKIE" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_FILES" fullname="$_FILES" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$argv" fullname="$argv" type="array" children="1" numchildren="2" page="0" pagesize="100"><property name="0" fullname="$argv[0]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="1" fullname="$argv[1]" type="string" size="11" encoding="base64"><![CDATA[Y2FjaGU6Y2xlYXI=]]></property></property><property name="$argc" fullname="$argc" type="int"><![CDATA[2]]></property><property name="$_ENV" fullname="$_ENV" type="array" children="1" numchildren="18" page="0" pagesize="100"><property name="PATH" fullname="$_ENV[&quot;PATH&quot;]" type="string" size="60" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9zYmluOi91c3IvbG9jYWwvYmluOi91c3Ivc2JpbjovdXNyL2Jpbjovc2JpbjovYmlu]]></property><property name="HOSTNAME" fullname="$_ENV[&quot;HOSTNAME&quot;]" type="string" size="12" encoding="base64"><![CDATA[MjhiZjNjYzY1N2E2]]></property><property name="TERM" fullname="$_ENV[&quot;TERM&quot;]" type="string" size="5" encoding="base64"><![CDATA[eHRlcm0=]]></property><property type="string" size="76"><name encoding="base64"><![CDATA[UEhQSVpFX0RFUFM=]]></name><fullname encoding="base64"><![CDATA[JF9FTlZbIlBIUElaRV9ERVBTIl0=]]></fullname><value encoding="base64"><![CDATA[YXV0b2NvbmYgCQlkcGtnLWRldiAJCWZpbGUgCQlnKysgCQlnY2MgCQlsaWJjLWRldiAJCW1ha2UgCQlwa2ctY29uZmlnIAkJcmUyYw==]]></value></property><property name="PHP_INI_DIR" fullname="$_ENV[&quot;PHP_INI_DIR&quot;]" type="string" size="18" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9ldGMvcGhw]]></property><property name="PHP_CFLAGS" fullname="$_ENV[&quot;PHP_CFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_CPPFLAGS" fullname="$_ENV[&quot;PHP_CPPFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_LDFLAGS" fullname="$_ENV[&quot;PHP_LDFLAGS&quot;]" type="string" size="12" encoding="base64"><![CDATA[LVdsLC1PMSAtcGll]]></property><property name="GPG_KEYS" fullname="$_ENV[&quot;GPG_KEYS&quot;]" type="string" size="122" encoding="base64"><![CDATA[MzlCNjQxMzQzRDhDMTA0QjJCMTQ2REMzRjlDMzlEQzBCOTY5ODU0NCBFNjA5MTNFNERGMjA5OTA3RDhFMzBEOTY2NTlBOTdDOUNGMkE3OTVBIDExOThDMDExNzU5MzQ5N0E1RUM1QzE5OTI4NkFGMUY5ODk3NDY5REM=]]></property><property name="PHP_VERSION" fullname="$_ENV[&quot;PHP_VERSION&quot;]" type="string" size="6" encoding="base64"><![CDATA[OC4yLjE0]]></property><property name="PHP_URL" fullname="$_ENV[&quot;PHP_URL&quot;]" type="string" size="51" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6]]></property><property name="PHP_ASC_URL" fullname="$_ENV[&quot;PHP_ASC_URL&quot;]" type="string" size="55" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6LmFzYw==]]></property><property name="PHP_SHA256" fullname="$_ENV[&quot;PHP_SHA256&quot;]" type="string" size="64" encoding="base64"><![CDATA[NzYzZWNkMzlmY2Y1MWMzODE1YWY2ZWY2ZTQzZmE5YWEwZDBiZDhlNWE2MTUwMDllNWY0NzgwYzkyNzA1ZjU4Mw==]]></property><property name="UID" fullname="$_ENV[&quot;UID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="GID" fullname="$_ENV[&quot;GID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="XDEBUG_MODE" fullname="$_ENV[&quot;XDEBUG_MODE&quot;]" type="string" size="5" encoding="base64"><![CDATA[ZGVidWc=]]></property><property name="XDEBUG_TRIGGER" fullname="$_ENV[&quot;XDEBUG_TRIGGER&quot;]" type="string" size="8" encoding="base64"><![CDATA[UEhQU1RPUk0=]]></property><property name="HOME" fullname="$_ENV[&quot;HOME&quot;]" type="string" size="8" encoding="base64"><![CDATA[L3Zhci93d3c=]]></property></property><property name="$_REQUEST" fullname="$_REQUEST" type="array" children="0" numchildren="0" page="0" pagesize="100"></property><property name="$_SERVER" fullname="$_SERVER" type="array" children="1" numchildren="27" page="0" pagesize="100"><property name="PATH" fullname="$_SERVER[&quot;PATH&quot;]" type="string" size="60" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9zYmluOi91c3IvbG9jYWwvYmluOi91c3Ivc2JpbjovdXNyL2Jpbjovc2JpbjovYmlu]]></property><property name="HOSTNAME" fullname="$_SERVER[&quot;HOSTNAME&quot;]" type="string" size="12" encoding="base64"><![CDATA[MjhiZjNjYzY1N2E2]]></property><property name="TERM" fullname="$_SERVER[&quot;TERM&quot;]" type="string" size="5" encoding="base64"><![CDATA[eHRlcm0=]]></property><property type="string" size="76"><name encoding="base64"><![CDATA[UEhQSVpFX0RFUFM=]]></name><fullname encoding="base64"><![CDATA[JF9TRVJWRVJbIlBIUElaRV9ERVBTIl0=]]></fullname><value encoding="base64"><![CDATA[YXV0b2NvbmYgCQlkcGtnLWRldiAJCWZpbGUgCQlnKysgCQlnY2MgCQlsaWJjLWRldiAJCW1ha2UgCQlwa2ctY29uZmlnIAkJcmUyYw==]]></value></property><property name="PHP_INI_DIR" fullname="$_SERVER[&quot;PHP_INI_DIR&quot;]" type="string" size="18" encoding="base64"><![CDATA[L3Vzci9sb2NhbC9ldGMvcGhw]]></property><property name="PHP_CFLAGS" fullname="$_SERVER[&quot;PHP_CFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_CPPFLAGS" fullname="$_SERVER[&quot;PHP_CPPFLAGS&quot;]" type="string" size="83" encoding="base64"><![CDATA[LWZzdGFjay1wcm90ZWN0b3Itc3Ryb25nIC1mcGljIC1mcGllIC1PMiAtRF9MQVJHRUZJTEVfU09VUkNFIC1EX0ZJTEVfT0ZGU0VUX0JJVFM9NjQ=]]></property><property name="PHP_LDFLAGS" fullname="$_SERVER[&quot;PHP_LDFLAGS&quot;]" type="string" size="12" encoding="base64"><![CDATA[LVdsLC1PMSAtcGll]]></property><property name="GPG_KEYS" fullname="$_SERVER[&quot;GPG_KEYS&quot;]" type="string" size="122" encoding="base64"><![CDATA[MzlCNjQxMzQzRDhDMTA0QjJCMTQ2REMzRjlDMzlEQzBCOTY5ODU0NCBFNjA5MTNFNERGMjA5OTA3RDhFMzBEOTY2NTlBOTdDOUNGMkE3OTVBIDExOThDMDExNzU5MzQ5N0E1RUM1QzE5OTI4NkFGMUY5ODk3NDY5REM=]]></property><property name="PHP_VERSION" fullname="$_SERVER[&quot;PHP_VERSION&quot;]" type="string" size="6" encoding="base64"><![CDATA[OC4yLjE0]]></property><property name="PHP_URL" fullname="$_SERVER[&quot;PHP_URL&quot;]" type="string" size="51" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6]]></property><property name="PHP_ASC_URL" fullname="$_SERVER[&quot;PHP_ASC_URL&quot;]" type="string" size="55" encoding="base64"><![CDATA[aHR0cHM6Ly93d3cucGhwLm5ldC9kaXN0cmlidXRpb25zL3BocC04LjIuMTQudGFyLnh6LmFzYw==]]></property><property name="PHP_SHA256" fullname="$_SERVER[&quot;PHP_SHA256&quot;]" type="string" size="64" encoding="base64"><![CDATA[NzYzZWNkMzlmY2Y1MWMzODE1YWY2ZWY2ZTQzZmE5YWEwZDBiZDhlNWE2MTUwMDllNWY0NzgwYzkyNzA1ZjU4Mw==]]></property><property name="UID" fullname="$_SERVER[&quot;UID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="GID" fullname="$_SERVER[&quot;GID&quot;]" type="string" size="4" encoding="base64"><![CDATA[MTAwMA==]]></property><property name="XDEBUG_MODE" fullname="$_SERVER[&quot;XDEBUG_MODE&quot;]" type="string" size="5" encoding="base64"><![CDATA[ZGVidWc=]]></property><property name="XDEBUG_TRIGGER" fullname="$_SERVER[&quot;XDEBUG_TRIGGER&quot;]" type="string" size="8" encoding="base64"><![CDATA[UEhQU1RPUk0=]]></property><property name="HOME" fullname="$_SERVER[&quot;HOME&quot;]" type="string" size="8" encoding="base64"><![CDATA[L3Zhci93d3c=]]></property><property name="PHP_SELF" fullname="$_SERVER[&quot;PHP_SELF&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="SCRIPT_NAME" fullname="$_SERVER[&quot;SCRIPT_NAME&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="SCRIPT_FILENAME" fullname="$_SERVER[&quot;SCRIPT_FILENAME&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="PATH_TRANSLATED" fullname="$_SERVER[&quot;PATH_TRANSLATED&quot;]" type="string" size="11" encoding="base64"><![CDATA[YmluL2NvbnNvbGU=]]></property><property name="DOCUMENT_ROOT" fullname="$_SERVER[&quot;DOCUMENT_ROOT&quot;]" type="string" size="0" encoding="base64"><![CDATA[]]></property><property name="REQUEST_TIME_FLOAT" fullname="$_SERVER[&quot;REQUEST_TIME_FLOAT&quot;]" type="float"><![CDATA[1704455704.1299]]></property><property name="REQUEST_TIME" fullname="$_SERVER[&quot;REQUEST_TIME&quot;]" type="int"><![CDATA[1704455704]]></property><property name="argv" fullname="$_SERVER[&quot;argv&quot;]" type="array" children="1" numchildren="2"></property><property name="argc" fullname="$_SERVER[&quot;argc&quot;]" type="int"><![CDATA[2]]></property></property></response>

[29] [Step Debug] <- context_get -i 22 -d 0 -c 2
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="context_get" transaction_id="22" context="2"></response>

[29] [Step Debug] <- run -i 23

 // Clearing the cache for the dev environment with debug true                                                          

 [OK] Cache for the "dev" environment (debug=true) was successfully cleared.                                            

[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="run" transaction_id="23" status="stopping" reason="ok"></response>

[29] [Step Debug] <- detach -i 24
[29] [Step Debug] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="detach" transaction_id="24" status="stopping" reason="ok"></response>

[29] Log closed at 2024-01-05 11:55:09.400103

real    0m5,400s
user    0m0,031s
sys 0m0,035s
psihius@psihius-pc:~/projects/symfony$ 

psihius

2024-01-05 12:09

reporter   ~0006750

Results are the same for PHP 8.3.1 and XDebug 3.3.1 combo

RayWest

2024-01-19 05:07

reporter   ~0006786

I am having the same problem as reported here (PHP 8.3.1 + XDebug 3.3.1) except I'm using Laravel 10.x.

However, I just tested my app with PHP 8.2.15 + XDebug 3.3.1 and it seems to work fine.

RayWest

2024-01-19 05:26

reporter   ~0006787

I just test PHP 8.3.1 + XDebug 3.3.1 and this time i used FCGI mode. This worked fine without hanging.
Seems to be something related to using PHP as an Apache module.
The FCGI mode was mentioned in a comment on this ticket: https://bugs.xdebug.org/view.php?id=2216

psihius

2024-01-19 09:49

reporter   ~0006790

I use nginx + PHP-FPM. It and CLI both have the same performance degradation.

derick

2024-01-24 11:19

administrator   ~0006792

Can you all try setting xdebug.control_socket=no in php.ini (or equivalent)?

This is unlikely to affect the (I believe) different issue with Apache on Windows (0002216).

If the issue still does persist with that setting made, I would love to see a system trace. Use strace -o /tmp/xdebug-3.2.txt -f -s 4096 -tt php <yourscript.php> — for that to be most useful, that needs to be something you can run as a single script on the command line. Make a different file for Xdebug 3.2 vs 3.3. You also might have to install strace, which you can find in the strace package (on Debian, at least).

psihius

2024-01-24 11:46

reporter   ~0006793

Adding xdebug.control_socket=no on Linux does solve the performance degradation - with it, it takes 5 seconds to complete the CLI command (bin/console cache:clear for Symfony app)7

derick

2024-01-24 11:56

administrator   ~0006794

That's good to know — would you be so kind as to make two straces as I asked regardless? I locally don't see this performance degradation, and I would like to investigate.

psihius

2024-01-24 12:04

reporter   ~0006795

Just to make sure we are aligned on the settings, for 3.2 and 3.3 run with the following settings:


xdebug.mode=debug
xdebug.start_with_request=trigger
xdebug.trigger_value=PHPSTORM
xdebug.client_host=host.docker.internal
xdebug.client_port=9003
xdebug.log=/tmp/xdebug.log
xdebug.idekey=PHPSTORM```

psihius

2024-01-24 12:51

reporter   ~0006796

@derick I made a docker setup at https://github.com/psihius/xdebug-debug-mode-issue that uses standard php8.2-fpm that has everything you need to reproduce the issue and I verified it indeed is present.
It uses standard php8.2-fpm docker image, installs xdebug via PECL.
There are 2 services: php-3.3 with xdebug 3.3.1 and php-3.2 with xdebug 3.2.2.
My host system is Linux Mint 21.3 Linux psihius-pc 6.5.0-14-generic #14~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Nov 20 18:15:30 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

checkout the repository, run composer install (docker images do contain composer if need be: docker compose exec php-3.3 composer install

time docker compose exec php-3.3 bin/console cache:clear
time docker compose exec php-3.2 bin/console cache:clear

To see the execution time differences.

time docker compose exec php-3.3 strace -o /var/www/html/xdebug-3.3.txt -f -s 4096 -tt php bin/console cache:clear
time docker compose exec php-3.2 strace -o /var/www/html/xdebug-3.2.txt -f -s 4096 -tt php bin/console cache:clear

To generate the traces. I'm running those on my side, but it is taking it's time and those files are getting over 1.2GB in side, so maybe it's better to just grab the repo and do it locally? (I will continue generating the files and upload them somewhere)

psihius

2024-01-24 13:14

reporter   ~0006797

PHP 8.2 with XDebug 3.2.2 trace - https://drive.google.com/file/d/1-pZYMrENRncKDbY55yMCtUgKv6S4humA/view?usp=sharing - small file, unpacked 18MB
PHP 8.2 with XDebug 3.3.1 trace - https://drive.google.com/file/d/1o3l9jHu0KBJVL98AGP2lL46IqBf5pcXL/view?usp=sharing - big file, 170 MB packed, 1.8 GB unpacked

derick

2024-01-24 14:52

administrator   ~0006798

It calls cloeck_gettime 19 million times, so no wonder it's slow :-D:

$ cat xdebug-3.3.txt | grep clock_getti | wc -l
19900827

psihius

2024-01-24 20:21

reporter   ~0006799

The only difference is xdebug version here, so seems to originate with xdebug itself.

Is any more information needed or is this sufficient to figure out why it does that and come up with how to fix it?

derick

2024-01-25 13:55

administrator   ~0006801

Yeah, it's definitely an Xdebug thing. However, it is part of a new feature in Xdebug. I did try complex scripts before selecting a default check and time, but I think that docker makes checking the time after every statement more impactful than on native hardware. For Xdebug 3.3.2, I will disable this feature by default until I can come up with a better default check or implementation.

I did just run your timing with docker. In one window, I ran:

composer install
docker compose up

And in another terminal, the two commands.

The times were pretty equal. What I don't understand is that I don't get the clock_gettime in the strace for Xdebug 3.3 at all though. Is there a setting in your docker config or environment that I am missing maybe?

psihius

2024-01-25 14:06

reporter   ~0006802

Not as far as I can tell, the only thing related to docker I had was DOCKER_BUILDKIT=1, but I tried it with set to 0 and that did not change anything.

Here's my env

SHELL=/bin/bash
SESSION_MANAGER=local/psihius-pc:@/tmp/.ICE-unix/1297,unix/psihius-pc:/tmp/.ICE-unix/1297
QT_ACCESSIBILITY=1
COLORTERM=truecolor
XDG_CONFIG_DIRS=/etc/xdg/xdg-cinnamon:/etc/xdg
XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0
NVM_INC=/home/psihius/.nvm/versions/node/v18.12.1/include/node
GNOME_DESKTOP_SESSION_ID=this-is-deprecated
LANGUAGE=en_US
MANDATORY_PATH=/usr/share/gconf/cinnamon.mandatory.path
LC_ADDRESS=lv_LV.UTF-8
LC_NAME=lv_LV.UTF-8
SSH_AUTH_SOCK=/run/user/1000/keyring/ssh
DESKTOP_SESSION=cinnamon
LC_MONETARY=lv_LV.UTF-8
GTK_MODULES=gail:atk-bridge
PWD=/home/psihius/projects/symfony
LOGNAME=psihius
XDG_SESSION_DESKTOP=cinnamon
QT_QPA_PLATFORMTHEME=qt5ct
XDG_SESSION_TYPE=x11
GPG_AGENT_INFO=/run/user/1000/gnupg/S.gpg-agent:0:1
SYSTEMD_EXEC_PID=6298
XAUTHORITY=/home/psihius/.Xauthority
XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/psihius
GDM_LANG=en_US
HOME=/home/psihius
IM_CONFIG_PHASE=1
LC_PAPER=lv_LV.UTF-8
LANG=en_US.UTF-8
GITHUB_TOKEN=**SNIP**
LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.webp=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:
XDG_CURRENT_DESKTOP=X-Cinnamon
VTE_VERSION=6800
XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0
GNOME_TERMINAL_SCREEN=/org/gnome/Terminal/screen/4515ca5a_3339_46e5_add7_3cb1c3c7f756
DOCKER_BUILDKIT=0
NVM_DIR=/home/psihius/.nvm
LESSCLOSE=/usr/bin/lesspipe %s %s
XDG_SESSION_CLASS=user
TERM=xterm-256color
LC_IDENTIFICATION=lv_LV.UTF-8
DEFAULTS_PATH=/usr/share/gconf/cinnamon.default.path
LESSOPEN=| /usr/bin/lesspipe %s
USER=psihius
GNOME_TERMINAL_SERVICE=:1.147
DISPLAY=:0
SHLVL=1
NVM_CD_FLAGS=
LC_TELEPHONE=lv_LV.UTF-8
LC_MEASUREMENT=lv_LV.UTF-8
PAPERSIZE=a4
XDG_RUNTIME_DIR=/run/user/1000
LC_TIME=lv_LV.UTF-8
GTK3_MODULES=xapp-gtk3-module
XDG_DATA_DIRS=/usr/share/cinnamon:/usr/share/gnome:/home/psihius/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share:/usr/share
PATH=/home/psihius/.nvm/versions/node/v18.12.1/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/home/psihius/.local/share/JetBrains/Toolbox/scripts:/home/psihius/.local/share/JetBrains/Toolbox/scripts
GDMSESSION=cinnamon
DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
NVM_BIN=/home/psihius/.nvm/versions/node/v18.12.1/bin
LC_NUMERIC=lv_LV.UTF-8
OLDPWD=/home/psihius/projects/casa-market
_=/usr/bin/env

I run a pretty fresh kernel, could that be something that has an effect? But as far as customisations to the OS go, I run a bog standard install without any tinkering at all of Linux Mint 21.3.

Linux psihius-pc 6.5.0-14-generic #14~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Nov 20 18:15:30 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

psihius

2024-01-25 14:07

reporter   ~0006803

That string it above mapped as an issue link is # 14~22.04.1-Ubuntu without the space :)

psihius

2024-01-25 14:13

reporter   ~0006804

Also I want note that this issue also affects my host system the same way, so docker itself is not really an issue here.

psihius

2024-01-25 14:25

reporter   ~0006805

Okay, I think I might have a lead: https://unix.stackexchange.com/questions/553845/should-i-be-seeing-non-vdso-clock-gettime-syscalls-on-x86-64-using-hpet

hpet acpi_pm 

Does this vector help with digging into it? :)

derick

2024-01-25 14:36

administrator   ~0006806

Yes, that definitely helps

derick

2024-01-25 14:54

administrator   ~0006807

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc hpet acpi_pm 

For me.
If I force the source to hpet, I can now reproduce your issue.

I remember this having been an issue in the past with Docker on OSX, but I thought they had fixed that (https://github.com/docker/for-mac/issues/3455#issuecomment-1092529479, 0001701).

As a "fun" thing to do, can you restart your dockerd server process? I would run sudo /etc/init.d/docker restart on Linux. And then again show your available clock sources; and if it's then tsc, to make an strace to see if the issue persists.

psihius

2024-01-25 15:03

reporter   ~0006808

My OS has only those two clock sources available, there's no tcs option. I checked the bios and fiddled with some settings - didn't affect the clocks though, same results.

derick

2024-01-25 15:10

administrator   ~0006809

Odd — what hardware is that? I would check the boot up bios messages, as I am pretty sure tsc should be universally available.

Luckily, I can now detect this — and I'll see if I can come up with a good (reasonable) solution. I'll likely do the following:

When PHP/Xdebug is starting:

  • if the current clock source is not tsc, add a warning and disable the feature by default
  • change from checking the time for every statement, to every 5 (and function start), to have fewer overhead even in the cases where the clock is working right.

Ideally I would check the passed time in a thread, but that opens up a whole new can of worms.

derick

2024-01-25 15:11

administrator   ~0006810

grep flags /proc/cpuinfo should show tsc

derick

2024-01-25 15:12

administrator   ~0006811

dmesg | grep -i tsc could show warnings about tsc being broken

psihius

2024-01-25 15:35

reporter   ~0006812

TSC is being marked unstable

[    0.000000] tsc: Detected 3793.004 MHz processor
[    0.116458] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x6d590ddb140, max_idle_ns: 881590404252 ns
[    0.364534] clocksource: Switched to clocksource tsc-early
[    1.668483] tsc: Refined TSC clocksource calibration: 3818.978 MHz
[    1.668510] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x6e18c12c200, max_idle_ns: 881590713015 ns
[    1.668549] clocksource: Switched to clocksource tsc
[    2.628399] clocksource: timekeeping watchdog on CPU4: Marking clocksource 'tsc' as unstable because the skew is too large:
[    2.628408] clocksource:                       'tsc' cs_nsec: 479863693 cs_now: f6a9fd9dc cs_last: efd64c262 mask: ffffffffffffffff
[    2.628410] clocksource:                       Clocksource 'tsc' skewed -3302533 ns (-3 ms) over watchdog 'hpet' interval of 483166226 ns (483 ms)
[    2.628413] clocksource:                       'tsc' is current clocksource.
[    2.628415] tsc: Marking TSC unstable due to clocksource watchdog
[    2.628535] clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0,9,15.
[    9.711003] kvm_amd: TSC scaling supported

Hardware: https://termbin.com/oeye

psihius

2024-01-25 15:43

reporter   ~0006813

I can force TSC clock with clocksource=tsc tsc=reliable on the boot options, but googling around shows that unstable TSC is not uncommon, so either way accounting for other clock sources seems prudent.
I'll try to see if there's newer BIOS and firmware for my motherboard, but yeah - there's quite a lot of results for Zen 3 architecture mentioning unstable TSC

derick

2024-01-30 09:55

administrator   ~0006818

Hi!

I have now merged the detection (and automatic disabling of the feature in case there is no tsc clock) into the xdebug_3_3 branch. It would be great if you could test the following:

  • Once with XDEBUG_MODE=off
  • Once without any Xdebug settings (but XDEBUG_MODE=debug)
  • Once with -dxdebug.control_socket=default (and XDEBUG_MODE=debug)
  • Once with -dxdebug.control_socket=off (and XDEBUG_MODE=debug)
  • Once with -dxdebug.control_socket=time (and XDEBUG_MODE=debug)

Xdebug will also log (through xdebug.log) if it detected the non-availability of the tsc clock. Whether tsc clock is available is now also listed in xdebug_info() output.

You can get the ZIP file of the branch at https://github.com/xdebug/xdebug/archive/refs/heads/xdebug_3_3.zip in case you don't want to git clone the Xdebug repository.

derick

2024-02-08 14:26

administrator   ~0006839

Did you manage to find time to test this?

derick

2024-03-28 17:01

administrator   ~0006873

@psihius? Can you please answer the last questions that I put to you?

derick

2024-05-06 10:26

administrator   ~0006940

This should have been addressed in Xdebug 3.3.2.

psihius

2024-05-06 10:28

reporter   ~0006941

@derick sorry life got in the way, I will test this today and report.

Issue History

Date Modified Username Field Change
2024-01-05 11:26 psihius New Issue
2024-01-05 11:55 psihius Note Added: 0006749
2024-01-05 12:09 psihius Note Added: 0006750
2024-01-19 05:07 RayWest Note Added: 0006786
2024-01-19 05:26 RayWest Note Added: 0006787
2024-01-19 09:49 psihius Note Added: 0006790
2024-01-24 11:19 derick Assigned To => derick
2024-01-24 11:19 derick Status new => feedback
2024-01-24 11:19 derick Note Added: 0006792
2024-01-24 11:46 psihius Note Added: 0006793
2024-01-24 11:46 psihius Status feedback => assigned
2024-01-24 11:56 derick Status assigned => feedback
2024-01-24 11:56 derick Note Added: 0006794
2024-01-24 12:04 psihius Note Added: 0006795
2024-01-24 12:04 psihius Status feedback => assigned
2024-01-24 12:51 psihius Note Added: 0006796
2024-01-24 13:14 psihius Note Added: 0006797
2024-01-24 14:52 derick Note Added: 0006798
2024-01-24 20:21 psihius Note Added: 0006799
2024-01-25 13:55 derick Note Added: 0006801
2024-01-25 14:06 psihius Note Added: 0006802
2024-01-25 14:07 psihius Note Added: 0006803
2024-01-25 14:13 psihius Note Added: 0006804
2024-01-25 14:25 psihius Note Added: 0006805
2024-01-25 14:36 derick Note Added: 0006806
2024-01-25 14:54 derick Note Added: 0006807
2024-01-25 15:03 psihius Note Added: 0006808
2024-01-25 15:10 derick Note Added: 0006809
2024-01-25 15:11 derick Note Added: 0006810
2024-01-25 15:12 derick Note Added: 0006811
2024-01-25 15:35 psihius Note Added: 0006812
2024-01-25 15:43 psihius Note Added: 0006813
2024-01-30 09:55 derick Status assigned => feedback
2024-01-30 09:55 derick Note Added: 0006818
2024-02-08 14:26 derick Note Added: 0006839
2024-03-28 17:01 derick Note Added: 0006873
2024-05-06 10:26 derick Status feedback => closed
2024-05-06 10:26 derick Resolution open => fixed
2024-05-06 10:26 derick Fixed in Version => 3.3.2
2024-05-06 10:26 derick Note Added: 0006940
2024-05-06 10:28 psihius Note Added: 0006941