View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0001717XdebugCode Coveragepublic2019-11-18 10:152019-12-09 08:04
Reporterjhassler Assigned Toderick  
PriorityhighSeveritymajorReproducibilityalways
Status closedResolutionfixed 
Product Version2.8.0 
Target Version2.8.1Fixed in Version2.8.1 
Summary0001717: Code coverage turned slow after update from 2.7.2 to 2.8.0
Description

The code coverage performance in our CI pipeline suddenly decreased after Oct 31 due to the update from xdebug 2.7.2 to 2.8.0.

Before (xdebug 2.7.2): 8 minutes
After (xdebug 2.8.0): > 3.5 hours

PHPUnit 7.5.12
PHP 7.1

I switched the pipeline back to 2.7.2 and the coverage performance was back to normal - that's why I can exclude side effects due to other versions.

Steps To Reproduce

Can someone confirm this?

Tagsperformance, php7.1, php7.2, php7.3
Attached Files
Operating SystemDebian
PHP Version7.1.30-7.1.34

Activities

Anthony

2019-11-19 16:12

reporter   ~0005180

We've also had similar performance issues. We originally noticed it in CI, but didn't realise what the problem was. Our PHPUnit tests with coverage reports went from taking a little over 2 minutes, to over 25 minutes. When I looked back over the logs I realised that the last fast run was with Xdebug 2.7.2, and the first slow one was using 2.8.0. Rolling back to 2.7.2 has restored performance.

We're running this in Docker. I've attached a copy of the Dockerfile, along with the PHP config.

I've also run Strace against both 2.7.2 and 2.8.0 to see what's going on. The specific command that I ran INSIDE the container was:

 strace -r -c vendor/bin/phpunit --testdox --colors=always --coverage-html report

I've attached the output from Strace for both 2.7.2 and 2.8.0 as well.

I hope this helps. In the meantime, we're locked to the older version and our tests are running quickly enough for us

Dockerfile (1,392 bytes)    
FROM php:7.2.15-apache-stretch

MAINTAINER Anthony <anthony@example.com>

# Add build args for uid/gid with default
ARG DOCKER_UID=1000
ARG DOCKER_GID=1000

# Set up environment variables
ENV ADD_CONTENT_LENGTH_HEADER=0
ENV DISPLAY_ERRORS=1
ENV LOG_LEVEL=100
ENV VIEW_DEBUG=1
ENV VIEW_AUTO_RELOAD=1
ENV CACHE_ROUTES=0
ENV DB_NAME=sample
ENV DB_HOST=your.db.host
ENV DB_USER=mysqluser
ENV DB_PASS=password
ENV SESSION_DOMAIN=localhost
ENV SECURE_SESSION_COOKIE=0
ENV STRICT_TRANSPORT_AGE=0

# Add mysql-client, PHP extensions and enable
RUN apt-get update && apt-get install -y strace mysql-client zlib1g-dev libicu-dev g++ \
    && pecl install xdebug-2.8.0 redis-4.3.0 \
    && docker-php-ext-configure intl \
    && docker-php-ext-install pdo_mysql pcntl intl \
    && docker-php-ext-enable xdebug redis

# Add Apache vhost, disable default, enable new vhost, enable apache modules & create and chown cache and spool dirs.
COPY vhost.conf /etc/apache2/sites-available/
RUN a2dissite 000-default.conf \
    && a2ensite vhost \
    && a2enmod rewrite \
    && usermod -u ${DOCKER_UID} www-data \
    && groupmod -g ${DOCKER_GID} www-data \
    && mkdir -p /var/cache/mr/ \
    && chown -R www-data:www-data /var/cache/mr/ /var/www/html

COPY mem_limit.ini ${PHP_INI_DIR}/conf.d/mem_limit.ini
COPY session.ini ${PHP_INI_DIR}/conf.d/session.ini
COPY xdebug.ini ${PHP_INI_DIR}/conf.d/xdebug.ini
Dockerfile (1,392 bytes)   
mem_limit.ini (21 bytes)    
memory_limit = 2048M
mem_limit.ini (21 bytes)   
session.ini (78 bytes)    
session.save_handler = redis
session.save_path = "tcp://redis?read_timeout=1"
session.ini (78 bytes)   
xdebug.ini (348 bytes)    
xdebug.remote_enable = 1
xdebug.coverage_enable = 1
xdebug.idekey = "PHPSTORM"
xdebug.collect_includes = 0
xdebug.collect_params = 0
xdebug.collect_return = 0
xdebug.collect_vars = 0

xdebug.profiler_enable = 0
xdebug.profiler_enable_trigger = 1
xdebug.profiler_output_dir = "/var/www/html/xdebug"
xdebug.profiler_output_name = "cachegrind.out.%R"
xdebug.ini (348 bytes)   
xdebug 2.7.2 strace.txt (2,974 bytes)    
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 21.42   95.027652        2373     40045           fstat
 17.51   77.686751        8952      8678        17 lstat
 15.90   70.519959       12544      5622        45 stat
 10.50   46.578969        2277     20456           close
 10.49   46.542655        2277     20437         9 open
  7.29   32.332433       12210      2648           mmap
  7.28   32.316501        9696      3333           getdents
  6.45   28.616556       11383      2514           munmap
  6.33   28.080367        6546      4290           getcwd
  4.19   18.606202       10836      1717           getrandom
  3.82   16.948814         971     17450           lseek
  0.80    3.537485        3997       885           getpid
  0.71    3.168154       16082       197           brk
  0.46    2.042496       16083       127           mprotect
  0.29    1.286560       16082        80           rt_sigaction
  0.24    1.065362        8523       125           madvise
  0.10    0.434214       16082        27           fcntl
  0.08    0.369886       16082        23        13 ioctl
  0.06    0.273394       16082        17           socket
  0.05    0.241659       16111        15        10 connect
  0.05    0.225148       16082        14           setsockopt
  0.03    0.112574       16082         7           getsockopt
  0.02    0.080410       16082         5           readlink
  0.02    0.080410       16082         5           sendmmsg
  0.01    0.064328       16082         4           pipe
  0.01    0.064328       16082         4           newfstatat
  0.01    0.048246       16082         3         1 execve
  0.01    0.032164       16082         2           rt_sigprocmask
  0.01    0.032164       16082         2           clone
  0.01    0.032164       16082         2           wait4
  0.01    0.032164       16082         2           chdir
  0.01    0.032164       16082         2           getrlimit
  0.01    0.032164       16082         2           arch_prctl
  0.00    0.016082       16082         1           sysinfo
  0.00    0.016082       16082         1           set_tid_address
  0.00    0.016082       16082         1           set_robust_list
  0.07    0.317618       15125        21           futex
 -0.01   -0.048264 18446744073709547595        12           unlink
 -0.06   -0.265476 18446744073709548530        86           uname
 -0.34   -1.513665 18446744073709551488     11725           write
 -0.66   -2.920433 18446744073709551162      6415           sendto
 -2.35  -10.446960 18446744073709550732     11800           recvfrom
 -2.58  -11.444433 18446744073709551366     45619           read
 -3.00  -13.300874 18446744073709550705     14589           poll
 -5.26  -23.337457 18446744073709550689     25138     10055 access
------ ----------- ----------- --------- --------- ----------------
100.00  443.632799                244148     10150 total
xdebug 2.7.2 strace.txt (2,974 bytes)   
xdebug 2.8.0 strace.txt (2,901 bytes)    
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 29.16    0.034135           2     20437         9 open
 19.65    0.022995           1     20456           close
 14.39    0.016840           1     25138     10055 access
  8.61    0.010082           1     14542           poll
  6.81    0.007972           1      5622        45 stat
  4.65    0.005440           1     10127        17 lstat
  4.26    0.004985           0     11774           write
  4.08    0.004771           1      3333           getdents
  3.90    0.004559           0     45619           read
  2.54    0.002969           0     40045           fstat
  0.75    0.000883           0     17450           lseek
  0.46    0.000542           0      6414           sendto
  0.40    0.000465           0      2562           munmap
  0.15    0.000170           0      4290           getcwd
  0.14    0.000164           0      2696           mmap
  0.06    0.000070           1       127           mprotect
  0.00    0.000000           0       302           brk
  0.00    0.000000           0        80           rt_sigaction
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0        23        13 ioctl
  0.00    0.000000           0         4           pipe
  0.00    0.000000           0       172           madvise
  0.00    0.000000           0       883           getpid
  0.00    0.000000           0        17           socket
  0.00    0.000000           0        15        10 connect
  0.00    0.000000           0      9425           recvfrom
  0.00    0.000000           0        14           setsockopt
  0.00    0.000000           0         7           getsockopt
  0.00    0.000000           0         2           clone
  0.00    0.000000           0         3         1 execve
  0.00    0.000000           0         2           wait4
  0.00    0.000000           0        86           uname
  0.00    0.000000           0        27           fcntl
  0.00    0.000000           0         2           chdir
  0.00    0.000000           0        12           unlink
  0.00    0.000000           0         5           readlink
  0.00    0.000000           0         2           getrlimit
  0.00    0.000000           0         1           sysinfo
  0.00    0.000000           0         2           arch_prctl
  0.00    0.000000           0        21           futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         4           newfstatat
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         5           sendmmsg
  0.00    0.000000           0      1717           getrandom
------ ----------- ----------- --------- --------- ----------------
100.00    0.117042                243469     10150 total
xdebug 2.8.0 strace.txt (2,901 bytes)   

Anthony

2019-11-19 17:31

reporter   ~0005181

Just tried again with this command: strace -r -Tfe trace=open vendor/bin/phpunit --testdox --colors=always --coverage-html report

Here's a sample of the output:

 O running tests     0.971306 open("/var/www/html/tests/../spool/phpunit", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 9 <0.001046>
 O running tests     0.557823 open("/var/www/html/vendor/phpunit/phpunit/src/Framework/MockObject/Matcher/ConsecutiveParameters.php", O_RDONLY) = 9 <0.000551>
     0.020636 open("/var/www/html/vendor/phpunit/phpunit/src/Framework/MockObject/Stub/ConsecutiveCalls.php", O_RDONLY) = 9 <0.000791>
     0.053992 open("/var/www/html/src/Foo.php", O_RDONLY) = 9 <0.000989>
     1.311633 open("/var/www/html/vendor/phpunit/phpunit/src/Framework/MockObject/Stub/ConsecutiveCalls.php", O_RDONLY) = 9 <0.001083>
     0.006750 open("/var/www/html/src/Foo.php", O_RDONLY) = 9 <0.001176>
     0.005525 open("/var/www/html/vendor/phpunit/phpunit/src/Framework/MockObject/Matcher/ConsecutiveParameters.php", O_RDONLY) = 9 <0.000333>
     0.009173 open("/var/www/html/src/Foo.php", O_RDONLY) = 9 <0.000794>
     0.003583 open("/var/www/html/src/Foo.php", O_RDONLY) = 9 <0.000782>
 O running tests     0.085541 open("/var/www/html/src/Bar.php", O_RDONLY) = 9 <0.000818>

I've tried running it with the volume in default, delegated and cached modes, but the performance is the same

savar

2019-11-19 23:51

reporter   ~0005182

same issue for us. using phpdbg helps a little bit but it is still slower than the 2.7.2 version of xdebug but extremely faster than 2.8.0 xdebug

challgren

2019-11-22 22:10

reporter   ~0005183

Same issue for me. 2.7.2 resulting in my CI run time of 8 minutes. With 2.8.0 it times over after 1 hour.

challgren

2019-11-22 22:31

reporter   ~0005184

FYI for my CI I use php:7.3-alpine, php:7.2-alpine and php:7.1-alpine. Happens on shared Gitlab CI runners and local runner on MacOS 10.14.6. Rolling back to xdebug-2.7.2 improved the run times.

derick

2019-11-25 07:42

administrator   ~0005185

FWIW, I can reproduce this, and I know where the problem lies — but not quite yet what the problem is, and how to solve it.

derick

2019-11-29 15:47

administrator   ~0005191

Fixed in GIT for 2.8.1

Anthony

2019-12-03 12:24

reporter   ~0005192

We're still finding performance very slow in CI with 2.8.1

Attached is the strace that I ran locally. It took over an hour to run coverage locally with strace. CI has gone from 1m 52s to 9m 58s for PHPUnit with coverage alone. It's better then 25m, but it's still too slow to be practical for us.

We're only on PHP 7.2, looking to upgrade to 7.3 some time soon. Because we use ElasticBeanstalk and they always take almost a year to catch up to the latest PHP release we've got almost a year before we'll be able to upgrade to PHP 7.4, and since 2.7 won't work with 7.4 we'll see how the situation looks then.

xdebug 2.8.1 strace.txt (3,287 bytes)    
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 -0.06   42.883740        7424      5776        58 stat
 -0.04   30.585047        8845      3458           getdents
 -0.01    3.895725       30675       127           mprotect
 -0.00    2.454000       30675        80           rt_sigaction
 -0.00    0.092025       30675         3         1 execve
 -0.00    0.061350       30675         2           rt_sigprocmask
 -0.00    0.061350       30675         2           chdir
 -0.00    0.061350       30675         2           getrlimit
 -0.00    0.061350       30675         2           arch_prctl
 -0.00    0.030675       30675         1           sysinfo
 -0.00    0.030675       30675         1           set_tid_address
 -0.00    0.030675       30675         1           set_robust_list
 -0.00    0.605830       28849        21           futex
 -0.00    0.283730       12336        23        13 ioctl
 -0.00    0.086675        5778        15        10 connect
 -0.00    0.061335        3608        17           socket
  0.00   -0.000005           0         5           readlink
  0.00   -0.000005           0         5           sendmmsg
  0.00   -0.007670 18446744073709543946         1           mkdir
  0.00   -0.015340 18446744073709543947         2           clone
  0.00   -0.015340 18446744073709543947         2           wait4
  0.00   -0.030680 18446744073709543947         4           pipe
  0.00   -0.030680 18446744073709543947         4           newfstatat
  0.00   -0.053690 18446744073709543947         7           getsockopt
  0.00   -0.107380 18446744073709543947        14           setsockopt
  0.00   -0.122720 18446744073709543947        16           unlink
  0.00   -0.130400 18446744073709546787        27           fcntl
  0.00   -0.418017 18446744073709549578       205           brk
  0.00   -0.582930 18446744073709544839        86           uname
  0.00   -1.035777 18446744073709545765       177           madvise
  0.00   -2.313277 18446744073709551432     12526        42 lstat
  0.01   -6.930313 18446744073709549101      2754           mmap
  0.01   -7.063777 18446744073709544110       941           getpid
  0.02  -10.811172 18446744073709547452      2596           munmap
  0.02  -14.250424 18446744073709544049      1883           getrandom
  0.05  -33.715955 18446744073709544076      4471           getcwd
  0.08  -55.088880 18446744073709544006      7238           sendto
  0.13  -92.064437 18446744073709544210     12429           write
  0.14  -98.549819 18446744073709543989     12919           recvfrom
  0.16 -114.069566 18446744073709545283     18009           lseek
  0.18 -124.723839 18446744073709545705     21097           close
  0.18 -124.811626 18446744073709545696     21078         9 open
  0.18 -125.291633 18446744073709544020     16492           poll
  0.27 -185.348476 18446744073709544476     25954     10422 access
  0.38 -267.763288 18446744073709545127     41258           fstat
  0.51 -354.218291 18446744073709544106     47158           read
 97.79 -68028.320887 18446744073709544843  10043170           gettimeofday
------ ----------- ----------- --------- --------- ----------------
100.00 -69566.600762              10302059     10555 total
xdebug 2.8.1 strace.txt (3,287 bytes)   

tersmitten

2019-12-06 14:25

reporter   ~0005194

We're still finding performance very slow in CI with 2.8.1

We too.

Our builds used to take 15-20m, now > 2h

tersmitten

2019-12-06 14:28

reporter   ~0005195

We're using PHP 7.1.33 btw (on Ubuntu 16.04)

PHPUnit version 5.7.27

alex.m

2019-12-09 08:04

reporter   ~0005204

Confirm. Ubuntu 16.04 + PHP 7.1 + Xdebug 2.8.1 extremely slow

Issue History

Date Modified Username Field Change
2019-11-18 10:15 jhassler New Issue
2019-11-18 10:15 jhassler Tag Attached: performance
2019-11-19 16:12 Anthony File Added: Dockerfile
2019-11-19 16:12 Anthony File Added: mem_limit.ini
2019-11-19 16:12 Anthony File Added: session.ini
2019-11-19 16:12 Anthony File Added: xdebug.ini
2019-11-19 16:12 Anthony File Added: xdebug 2.7.2 strace.txt
2019-11-19 16:12 Anthony File Added: xdebug 2.8.0 strace.txt
2019-11-19 16:12 Anthony Note Added: 0005180
2019-11-19 17:31 Anthony Note Added: 0005181
2019-11-19 23:51 savar Note Added: 0005182
2019-11-22 22:10 challgren Note Added: 0005183
2019-11-22 22:23 challgren Tag Attached: php7.3
2019-11-22 22:23 challgren Tag Attached: php7.1
2019-11-22 22:23 challgren Tag Attached: php7.2
2019-11-22 22:31 challgren Note Added: 0005184
2019-11-25 07:42 derick Target Version => 2.8.1
2019-11-25 07:42 derick Assigned To => derick
2019-11-25 07:42 derick Status new => assigned
2019-11-25 07:42 derick Note Added: 0005185
2019-11-29 15:47 derick Status assigned => closed
2019-11-29 15:47 derick Resolution open => fixed
2019-11-29 15:47 derick Fixed in Version => 2.8.1
2019-11-29 15:47 derick Note Added: 0005191
2019-12-03 12:24 Anthony File Added: xdebug 2.8.1 strace.txt
2019-12-03 12:24 Anthony Note Added: 0005192
2019-12-06 14:25 tersmitten Note Added: 0005194
2019-12-06 14:28 tersmitten Note Added: 0005195
2019-12-09 08:04 alex.m Note Added: 0005204