View Issue Details

IDProjectCategoryView StatusLast Update
0002076XdebugStep Debuggingpublic2022-07-05 15:55
Reporterrobsangar Assigned Toderick  
PrioritynormalSeverityminorReproducibilityalways
Status feedbackResolutionopen 
Product Version3.1.3 
Summary0002076: Application slow when debugger is not running VS Code
Description

I have been using Xdebug for quite some time now. A few weeks ago i upgraded PHP from 7.4 to 8.0 and i feel like since the update the applications are running slower. Recently i have realised that the application is running fast whenever the debugger in VS Code is running and very slow when it is not running. Disabling Xdebug in php makes the application run fast again.

php.ini:
zend_extension=xdebug

xdebug.mode = debug
xdebug.start_with_request = yes
xdebug.client_port = 9000
xdebug.log = D:/php/xdebug.log
xdebug.max_nesting_level = 200
xdebug.var_display_max_children = 1024
xdebug.var_display_max_data = -1
xdebug.var_display_max_depth = 16

TagsNo tags attached.
Operating System
PHP Version8.0.10-8.0.19

Activities

Ownerofthisisle

2022-03-23 09:38

reporter   ~0006248

I can reproduce the issue in my IDE.
In the xdebug log I saw the reason for the slowness. Xdebug tries to connect with the vsCode Debugger (which is not running), thus getting a timeout.
That is perfektly OK, but I think xdebug is overdoing the retries, as I have this lines 19x in my log:

[150432] [Step Debug] INFO: Connecting to configured address/port: localhost:9000.
[150432] [Step Debug] ERR: Time-out connecting to debugging client, waited: 200 ms. Tried: localhost:9000 (through xdebug.client_host/xdebug.client_port) :-(

A partly solution is, to set the timeout via xdebug config option to a lower value like 50 ms, which still allows debugging on my system (and reduces wait time from 4s to 1s).
But still I would want the retries reduced to a reasonable 3 - 5 retries. Maybe this could also be configurable, but I ve not found an option to do so?

derick

2022-03-25 16:29

administrator   ~0006256

That is perfektly OK, but I think xdebug is overdoing the retries, as I have this lines 19x in my log:

Xdebug does not retry anything. It will try it for every PHP request instead. Does your single page perhaps make 18 sub-requests?

Xdebug will try to connect once for each request. If the network stack is not set-up correctly, then it might need to wait for this (up to) 200ms. In most cases, if there is nothing listening the network stack should reject nearly instantly, and there should be very little slow down. In my local environment, it takes just over half a millisecond:

1648225554.887540 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 5
1648225554.887566 connect(5, {sa_family=AF_INET, sin_port=htons(9003), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
1648225554.887598 getsockname(5, {sa_family=AF_INET, sin_port=htons(57503), sin_addr=inet_addr("127.0.0.1")}, [28->16]) = 0
1648225554.887623 close(5)              = 0
1648225554.887643 socket(AF_INET6, SOCK_DGRAM|SOCK_CLOEXEC, IPPROTO_IP) = 5
1648225554.887667 connect(5, {sa_family=AF_INET6, sin6_port=htons(9003), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = 0
1648225554.887698 getsockname(5, {sa_family=AF_INET6, sin6_port=htons(49317), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, [28]) = 0
1648225554.887726 close(5)              = 0
1648225554.887752 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 5
1648225554.887778 fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
1648225554.887799 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
1648225554.887819 connect(5, {sa_family=AF_INET6, sin6_port=htons(9003), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
1648225554.887885 poll([{fd=5, events=POLLIN|POLLPRI|POLLOUT}], 1, 200) = 1 ([{fd=5, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
1648225554.887918 close(5)              = 0
1648225554.887942 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
1648225554.887964 fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
1648225554.887983 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
1648225554.888002 connect(5, {sa_family=AF_INET, sin_port=htons(9003), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
1648225554.888069 poll([{fd=5, events=POLLIN|POLLPRI|POLLOUT}], 1, 200) = 1 ([{fd=5, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
1648225554.888097 close(5)              = 0
1648225554.888126 write(2, "Xdebug: [Step Debug] Could not c"..., 134Xdebug: [Step Debug] Could not connect to debugging client. Tried: localhost:9003 (through xdebug.client_host/xdebug.client_port) :-(

Can you run an strace to see what it does in your case? You can run your (command line app) with something like, with the log being written to /tmp/strace.log.

strace -o /tmp/strace.log -tttt php -dxdebug.mode=debug -dxdebug.start_with_request=yes /tmp/equinox.php

Ownerofthisisle

2022-03-31 12:33

reporter   ~0006265

Last edited: 2022-03-31 15:55

It does not look as if the 19 connection attempts are triggered by subrequest since I receive the same log, when opening a very simple website like

<?php 
echo "Something"; 
phpinfo();

Strange though - the simple script is NOT delayed, while the website I had tried before (a symfony application) is delayed quite exactly 19 x xdebug.connect_timeout_ms.

So the log is the same, the delay only happens with symfony.
Does this make any sense to you?

I am on windows here, so I could not follow your proposal with strace, is there something else I can do to help tracking the issue?

Ownerofthisisle

2022-04-07 11:18

reporter   ~0006268

I just rechecked, and found my last note is not entirely true.

A simple php script is only 1 x xdebug.connect_timeout_ms delayed and leads to only ONE entry in xdebug.log.
With symfony however I consistently have 19 log entries and a delay of 19 x xdebug.connect_timeout_ms.

You last comment left me with some questions though:

  • In both cases there is only one http request, what do you mean by php subrequest and can you guess what symfony is doing to create them?
  • How can the network stack be setup incorrectly? Is there another way to find out why it is not rejecting at once, since nothing listens on port 9000?

derick

2022-04-11 08:46

administrator   ~0006271

In both cases there is only one http request, what do you mean by php subrequest and can you guess what symfony is doing to create them?

I don't know specifically, but many frameworks route all requests (even for images etc) through /index.php or something like that, generating more HTTP requests beyond the initial one that you started yourself in the browser. It's likely symfony does that too. Your browser's debug tool will be able to tell you what requests it makes to where, and what takes time. If you take an image of something like that, perhaps that gives a hint.

How can the network stack be setup incorrectly? Is there another way to find out why it is not rejecting at once, since nothing listens on port 9000?

I don't know Windows, but any normal stack would instantly reject an incoming request to a port that is not open. It is possible that some tools (firewalls, anti virus) gets in the way and instead of instantly declining the incoming connection, it waits until the initiator (Xdebug) times out the connection request.

Ownerofthisisle

2022-04-11 10:18

reporter   ~0006272

In my browser dev tool, I have 9 request when I call my symfony main page, only 3 of them are listed in my apache.log.
The others are base42encoded pics and not fetched from server, a request made by redux devtool and one made by react testing library.

This still does not fit to the logs somehow.

Another observation (maybe irrelevant), when I turn the vs code debugger on (and everything is fine again), I don't have 19 happy faces in the log, as I was expecting.

I only got one:
[6696] [Step Debug] INFO: Connected to debugging client: localhost:9000 (through xdebug.client_host/xdebug.client_port). :-)
[6696] [Step Debug] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug&quot; fileuri="file:///D:/Apps/Apache/PIC/public/index.php" language="PHP" xdebug:language_version="8.0.8" protocol_version="1.0" appid="6696"><engine version="3.1.3"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]>&lt;/url>&lt;copyright>&lt;![CDATA[Copyright (c) 2002-2022 by Derick Rethans]]></copyright></init>

So it seems that the subrequests only happen, WHEN the vs code debugger is off.

rthgfbghty

2022-07-05 15:55

reporter   ~0006343

I also experience this. In my access.log i have two requests:
[05/Jul/2022:17:11:49 +0200] 127.0.0.1 - - "GET /wp-content/themes/roupez/test.php HTTP/1.1" 200 86452
[05/Jul/2022:17:12:47 +0200] 127.0.0.1 - - "GET /favicon.ico HTTP/1.1" 200 -

In my error.log i have:
[05-Jul-2022 17:11:54 Europe/Stockholm] Xdebug: [Step Debug] Time-out connecting to debugging client, waited: 200 ms. Tried: localhost:9003 (through xdebug.client_host/xdebug.client_port) :-(
[05-Jul-2022 15:11:55 UTC] Xdebug: [Step Debug] Time-out connecting to debugging client, waited: 200 ms. Tried: localhost:9003 (through xdebug.client_host/xdebug.client_port) :-(
THIS LINE IS REPEATED 125 TIMES SO I CUT THAT SECTION OUT
[05-Jul-2022 15:12:46 UTC] Xdebug: [Step Debug] Time-out connecting to debugging client, waited: 200 ms. Tried: localhost:9003 (through xdebug.client_host/xdebug.client_port) :-(

The network tab in chrome debugger only shows two requests being made (the same ones as in my access.log). If i turn on the debugger in vs code, the problem is gone and the page is rendered in a second instead of almost a minute. Am I correct to assume ONE connection attempt is made at each request to the web server? In my case, all i do is load the wordpress core, and i suppose it probably does run quite a bit of other code, but i see no new requests coming in to my webserver, so in theory nothin would trigger a new connection attempt from xdebug unless through some other internal php mechanism that i'm not aware of.

This is my setup:
Apache/2.4.47 (Win64)
OpenSSL/1.1.1k
mod_fcgid/2.3.10-dev
PHP/7.4.30 (php-7.4.30-nts-Win32-vc15-x64)
Xdebug/v3.1.5

Issue History

Date Modified Username Field Change
2022-03-17 10:41 robsangar New Issue
2022-03-23 09:38 Ownerofthisisle Note Added: 0006248
2022-03-25 16:29 derick Assigned To => derick
2022-03-25 16:29 derick Status new => feedback
2022-03-25 16:29 derick Note Added: 0006256
2022-03-31 12:33 Ownerofthisisle Note Added: 0006265
2022-03-31 15:55 derick Note Edited: 0006265
2022-04-07 11:18 Ownerofthisisle Note Added: 0006268
2022-04-11 08:46 derick Note Added: 0006271
2022-04-11 10:18 Ownerofthisisle Note Added: 0006272
2022-07-05 15:55 rthgfbghty Note Added: 0006343