Page MenuHomePhabricator

XDebug makes requiring files unreasonably slow and affects open file limit
Closed, ResolvedPublic

Description

See T247587#6306855 for a workaround.

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 updated the task description. (Show Details)

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.

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...

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.

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...)

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.)

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.

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).

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.

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

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

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
sudo service apache2 restart

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

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

@Tgr I guess the issue is on MediaWiki Vagrant? Assuming it is based on Stretch and has the php 7.2 package we have build, can you try the xdebug from:

https://apt.wikimedia.org/wikimedia/pool/component/php72/x/xdebug/php-xdebug_2.7.0-1%2Bwmf2_amd64.deb

It is 2.7.0 with a few cherry picks to fix some of the perfs issues.

Vagrant already uses the apt.wikimedia php-xdebug package, and still shows this bug. (The patch above is a red herring BTW, the issue was unrelated to shared directories.) Changing from 2.7.0 to 2.7.2 fixes it and is harmless otherwise. Would be nice to upload a deb file somewhere to make the process simpler (maybe even ship it with Vagrant), unfortunately I don't know much about packaging and don't have the time to learn it right now.

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

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

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

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

Change 640865 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/vagrant@master] Hack for using a working version of Xdebug

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

Change 837166 had a related patch set uploaded (by Mainframe98; author: Mainframe98):

[mediawiki/vagrant@master] Switch to PHP 7.4

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

Change 837166 abandoned by Mainframe98:

[mediawiki/vagrant@master] Switch to PHP 7.4

Reason:

This patch is targeting the wrong branch and needs to be redone after buster-migration has been rebased on top of master

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

Change 842964 had a related patch set uploaded (by Mainframe98; author: Mainframe98):

[mediawiki/vagrant@master] Switch to PHP 7.4

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

Change 842964 merged by jenkins-bot:

[mediawiki/vagrant@master] Switch to PHP 7.4

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

Tgr assigned this task to Mainframe98.

After T271649: Make single wiki + Virtualbox provider work with a Buster base image and the patch above, Vagrant now uses XDebug 3.

Change 640865 abandoned by Gergő Tisza:

[mediawiki/vagrant@master] Hack for using a working version of Xdebug

Reason:

we are on XDebug 3 now

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