Page MenuHomePhabricator

XDebug makes requiring files unreasonably slow and affects open file limit
Open, Needs TriagePublic

Description

Without xdebug:

vagrant@vagrant:~$ echo ';' | time mwscript eval.php

0.12user 0.04system 0:00.23elapsed 73%CPU (0avgtext+0avgdata 46968maxresident)k
0inputs+16outputs (0major+8104minor)pagefaults 0swaps

With xdebug:

vagrant@vagrant:~$ echo ';' | time mwscript eval.php
PHP Warning:  require(/vagrant/mediawiki/includes/debug/logger/monolog/LogstashFormatter.php): failed to open stream: Too many open files in /vagrant/mediawiki/includes/AutoLoader.php on line 109
[snip; trace is something like eval.php -> Setup.php -> ExtensionRegistry::getCache -> ObjectCache -> LoggerFactory -> MonologSpi, so pretty early on in the setup]
Command exited with non-zero status 255
1.22user 2.81system 0:23.61elapsed 17%CPU (0avgtext+0avgdata 173928maxresident)k
0inputs+95288outputs (0major+39738minor)pagefaults 0swaps

The error can be avoided by raising ulimit (which is 1024 by default), but then it just hangs forever.
(Note also the huge difference in outputs - 16 vs. 95288.)

A simple non-MediaWiki test:

vagrant@vagrant:~$ for i in {1..1100}; do echo -e '<?php\nreturn '$i';' > script$i.php; done
vagrant@vagrant:~$ cat > script.php 
<?php

for ($i = 1; $i<=1100; $i++) {
	require "script$i.php";
}

vagrant@vagrant:~$ xdebug_off
vagrant@vagrant:~$ /usr/bin/time php script.php
0.04user 0.02system 0:00.08elapsed 85%CPU (0avgtext+0avgdata 28496maxresident)k
1544inputs+0outputs (0major+3431minor)pagefaults 0swaps

vagrant@vagrant:~$ xdebug_on
vagrant@vagrant:~$ /usr/bin/time php script.php
0.45user 1.44system 0:12.50elapsed 15%CPU (0avgtext+0avgdata 97904maxresident)k
0inputs+46712outputs (0major+20740minor)pagefaults 0swaps

that's about 10ms per file opened, and about 4000 outputs (whatever those are) per require.
(Note that this is in the vagrant user's home directory. So, not an NFS / shared folder issue, or at least not straightforwardly.)

vagrant@vagrant:~$ php --version
PHP 7.2.26-1+0~20191218.33+debian9~1.gbpb5a340+wmf1 (cli) (built: Jan  9 2020 12:24:18) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.2.26-1+0~20191218.33+debian9~1.gbpb5a340+wmf1, Copyright (c) 1999-2018, by Zend Technologies
    with Xdebug v2.7.0, Copyright (c) 2002-2019, by Derick Rethans

Nothing obviously related in the 2.7 release notes (not sure if it's specific to that release, anyway).

Event Timeline

Tgr created this task.Mar 13 2020, 8:09 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 13 2020, 8:09 AM
Tgr updated the task description. (Show Details)Mar 13 2020, 8:10 AM
Tgr updated the task description. (Show Details)
Tgr updated the task description. (Show Details)Mar 13 2020, 8:21 AM
Tgr added a comment.EditedMar 13 2020, 8:28 AM

This seems like two unrelated issues. The "outputs" issue and some of the slowdown is because xdebug logging was enabled, and the logfile is in a shared folder. With a local file, or no logging, those issues disappear:

# local logfile
vagrant@vagrant:~$ /usr/bin/time php script.php
0.60user 2.04system 0:07.74elapsed 34%CPU (0avgtext+0avgdata 177520maxresident)k
0inputs+18768outputs (0major+40584minor)pagefaults 0swaps

# no logging
vagrant@vagrant:~$ /usr/bin/time php script.php
0.46user 2.03system 0:07.85elapsed 31%CPU (0avgtext+0avgdata 172584maxresident)k
0inputs+0outputs (0major+39339minor)pagefaults 0swaps

still super slow though (8s vs 12s while it's ~0.05 without xdebug). And still hits open file limits with xdebug but not without.

Tgr added a comment.Mar 14 2020, 1:17 AM

strace without xdebug: P10695
strace with xdebug: P10696

Not sure what to make of that. It does seem to try to close files after requiring them (several times, in fact) but the file handle does not get reused, so presumably they are not actually closed.

Change 579681 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/vagrant@master] Move xdebug logfile off the shared directory

https://gerrit.wikimedia.org/r/579681

There are file descriptors being opened that you did not capture. Some suggestions: openat, dup2, socket, accept...

Tgr added a comment.Mar 14 2020, 1:36 AM

Thanks! Unfiltered, grepped for a single descriptor: P10697
Which I think means the PHP file is closed but for every PHP file required, a new TCP connection is kept open.

Tgr added a comment.Mar 14 2020, 1:43 AM

XDebug bug #1641 also seems relevant to the performance problems. (Why are we on 2.7.0 anyway? 2.7.2 is almost a year old...)

Tgr added a comment.Mar 14 2020, 3:15 AM

The slowdown does not happen if there is no debug tool handling those connections. I use PHPStorm, so possibly it's an error with that and not XDebug?
Running the test above produces about 5M of XDebug log, consisting of many repetitions of

[29454] Log opened at 2020-03-14 02:54:12
[29454] I: Checking remote connect back address.
[29454] I: Checking header 'HTTP_X_FORWARDED_FOR'.
[29454] I: Checking header 'REMOTE_ADDR'.
[29454] W: Remote address not found, connecting to configured address/port: 10.11.12.1:9000. :-|
[29454] I: Connected to client. :-)
[29454] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" fileuri="file:///home/vagrant/script.php" language="PHP" xdebug:language_version="7.2.22-1+0~20190902.26+debian9~1.gbpd64eb7+wmf1" protocol_version="1.0" appid="29454" idekey="xdebug"><engine version="2.7.0"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]></url><copyright><![CDATA[Copyright (c) 2002-2019 by Derick Rethans]]></copyright></init>
[29454]
[29454] <- eval -i 1 -- KHN0cmluZykoaW5pX2dldCgneGRlYnVnLmNvdmVyYWdlX2VuYWJsZScpLic7Jy5pbmlfZ2V0KCd4ZGVidWcucHJvZmlsZXJfZW5hYmxlJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfYXV0b3N0YXJ0JykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfY29ubmVjdF9iYWNrJykuJzsnLmluaV9nZXQoJ3hkZWJ1Zy5yZW1vdGVfbW9kZScpKQ==
[29454] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="eval" transaction_id="1"><property type="string" size="11" encoding="base64"><![CDATA[MTswOzA7MTtyZXE=]]></property></response>
[29454]
[29454] <- feature_set -i 2 -n show_hidden -v 1
[29454] -> <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>
[29454]
[29454] <- feature_set -i 3 -n max_depth -v 1
[29454] -> <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>
[29454]
[29454] <- feature_set -i 4 -n max_children -v 100
[29454] -> <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>
[29454]
[29454] <- feature_set -i 5 -n extended_properties -v 1
[29454] -> <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>
[29454]
[29454] <- feature_set -i 6 -n resolved_breakpoints -v 1
[29454] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="6" status="starting" reason="ok"><error code="3"><message><![CDATA[invalid or missing options]]></message></error></response>
[29454]
[29454] <- feature_set -i 7 -n notify_ok -v 1
[29454] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="feature_set" transaction_id="7" feature="notify_ok" success="1"></response>
[29454]
[29454] <- stdout -i 8 -c 1
[29454] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="stdout" transaction_id="8" success="1"></response>
[29454]
[29454] <- status -i 9
[29454] -> <response xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" command="status" transaction_id="9" status="starting" reason="ok"></response>
[29454]
[29454] <- step_into -i 10
[29454] Log closed at 2020-03-14 02:54:12

then many repetitions of

[29454] Log opened at 2020-03-14 02:54:12
[29454] I: Checking remote connect back address.
[29454] I: Checking header 'HTTP_X_FORWARDED_FOR'.
[29454] I: Checking header 'REMOTE_ADDR'.
[29454] W: Remote address not found, connecting to configured address/port: 10.11.12.1:9000. :-|
[29454] I: Connected to client. :-)
[29454] -> <init xmlns="urn:debugger_protocol_v1" xmlns:xdebug="https://xdebug.org/dbgp/xdebug" fileuri="file:///home/vagrant/script.php" language="PHP" xdebug:language_version="7.2.22-1+0~20190902.26+debian9~1.gbpd64eb7+wmf1" protocol_version="1.0" appid="29454" idekey="xdebug"><engine version="2.7.0"><![CDATA[Xdebug]]></engine><author><![CDATA[Derick Rethans]]></author><url><![CDATA[https://xdebug.org]]></url><copyright><![CDATA[Copyright (c) 2002-2019 by Derick Rethans]]></copyright></init>
[29454]
[29454] Log closed at 2020-03-14 02:54:12

Those look normal, except they should only show up once, not a zillion times. (With 100 iterations of require in the test script, there first block is output in the logs 445 times, the second 462 times.)

Tgr added a comment.Mar 14 2020, 3:25 AM

The slowdown does not happen if there is no debug tool handling those connections. I use PHPStorm, so possibly it's an error with that and not XDebug?

Probably not, I can sort-of reproduce the behavior with the official XDebug command line client.

Tgr added a comment.Mar 14 2020, 7:07 AM

This is fixed in 2.7.2 #1641 or #1656, I guess, although neither seems exactly the right thing). Also, once it is fixed, the location of the logfile doesn't make any user-perceivable difference. Also apparently this was known, just hidden in the comments of a Phab task (which used to have a not-very-relevant title): T220406: Package XDebug 2.9 for apt.wikimedia.org. Duh.

Anyway, workaround for now is to just install XDebug 2.7.2 manually (from Debian testing, via the slightly-broken PECL, or by compiling the source - each of those is somewhat involved).

hashar added a subscriber: hashar.Apr 1 2020, 5:51 PM

XDebug 2.7.0 was also affected by some performance crippling issue T234418 . SRE were reluctant to upgrade to 2.7.2, so we went with cherry picking the patch that fixed my specific issue T234418#5594591

But yeah should get 2.7.2 definitely.

hashar added a comment.Apr 1 2020, 5:51 PM

(or you if you know which upstream patch fix them, they can be added to our Debian package).

Tgr added a comment.Apr 1 2020, 6:30 PM

As mentioned above, my best guess is #457 and my second best guess is #467 but I don't have much confidence in either.

Tgr added a comment.Wed, Jul 15, 12:10 AM

Anyway, workaround for now is to just install XDebug 2.7.2 manually (from Debian testing, via the slightly-broken PECL, or by compiling the source - each of those is somewhat involved).

Probably compiling from the source is the least painful (testing has 2.9 which requires changes to other packages):

sudo apt-get install php-dev
wget http://xdebug.org/files/xdebug-2.7.2.tgz
tar -xvzf xdebug-2.7.2.tgz 
cd xdebug-2.7.2/
phpize
./configure
make
sudo cp modules/xdebug.so /usr/lib/php/20170718

Change 579681 merged by jenkins-bot:
[mediawiki/vagrant@master] Move xdebug logfile off the shared directory

https://gerrit.wikimedia.org/r/579681