View Issue Details
ID | Project | Category | View Status | Date Submitted | Last Update |
---|---|---|---|---|---|
0001641 | Xdebug | Stacktraces | public | 2019-03-04 01:05 | 2019-03-13 02:17 |
Reporter | blackbass | Assigned To | derick | ||
Priority | normal | Severity | major | Reproducibility | always |
Status | closed | Resolution | fixed | ||
Product Version | 2.7.0RC2 | ||||
Fixed in Version | 2.7.1 | ||||
Summary | 0001641: Perfomance degradation with getpid syscall | ||||
Description | PHP 7.3.0 ... 7.3.2 Docker (18.09, 17.09) Xdebug 2.7.0(beta, RC1, RC2) spam syscall getpid on every file load operation | ||||
Steps To Reproduce | create empty composer.json create dummy script <?php require_once 'vendor/autoload.php'; echo 123; results of strace you can view in additional_info field ==== On big project with many vendors vendors strace -c with this script will return that: 123% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 41.86 0.012273 2 7899 getpid 22.55 0.006613 30 218 lstat 10.07 0.002952 13 221 17 open 6.57 0.001925 6 304 mmap 5.49 0.001611 8 208 close 4.40 0.001291 3 457 fstat ------ ----------- ----------- --------- --------- ---------------- 100.00 0.029320 9912 80 total on symfony console list command: strace -c php bin/console.php list ^Cstrace: Process 1500 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 98.33 11.215031 2 7031533 getpid 0.64 0.072488 34 2163 332 access 0.30 0.034574 9 3646 lstat 0.28 0.032297 20 1605 17 open 0.14 0.016454 10 1589 close 0.11 0.012051 3 4298 fstat 0.07 0.008038 6 1345 munmap 0.06 0.007300 5 1525 mmap 0.04 0.004016 7 583 4 stat 0.01 0.001664 3 557 read 0.00 0.000470 3 159 getdents without xdebug everything ok | ||||
Additional Information | strace Without xdebug remote session ----- 00:46:22 lstat("/var/www/auto/vendor/autoload.php", {st_mode=S_IFREG|0644, st_size=178, ...}) = 0 <0.003589> 00:46:22 lstat("/var/www/auto/vendor", {st_mode=S_IFDIR|0755, st_size=128, ...}) = 0 <0.002433> 00:46:22 open("/var/www/auto/vendor/autoload.php", O_RDONLY) = 3 <0.002015> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=178, ...}) = 0 <0.001043> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=178, ...}) = 0 <0.001962> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=178, ...}) = 0 <0.000655> 00:46:22 mmap(NULL, 178, PROT_READ, MAP_SHARED, 3, 0) = 0x7f9f6646e000 <0.000044> 00:46:22 munmap(0x7f9f6646e000, 178) = 0 <0.000997> 00:46:22 close(3) = 0 <0.025386> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=97616}, NULL) = 0 <0.002586> 00:46:22 getpid() = 327 <0.000061> 00:46:22 getpid() = 327 <0.000069> 00:46:22 getpid() = 327 <0.000084> 00:46:22 lstat("/var/www/auto/vendor/composer/autoload_real.php", {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.013354> 00:46:22 lstat("/var/www/auto/vendor/composer", {st_mode=S_IFDIR|0755, st_size=320, ...}) = 0 <0.012800> 00:46:22 open("/var/www/auto/vendor/composer/autoload_real.php", O_RDONLY) = 3 <0.098061> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.006031> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.040537> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.001583> 00:46:22 mmap(NULL, 1762, PROT_READ, MAP_SHARED, 3, 0) = 0x7f9f6646e000 <0.000035> 00:46:22 munmap(0x7f9f6646e000, 1762) = 0 <0.000064> 00:46:22 close(3) = 0 <0.003009> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=284715}, NULL) = 0 <0.000085> 00:46:22 getpid() = 327 <0.000076> 00:46:22 getpid() = 327 <0.000066> 00:46:22 getpid() = 327 <0.000055> 00:46:22 getpid() = 327 <0.000032> 00:46:22 getpid() = 327 <0.000040> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=287079}, NULL) = 0 <0.000048> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000026> 00:46:22 getpid() = 327 <0.000031> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=288276}, NULL) = 0 <0.000037> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000022> 00:46:22 getpid() = 327 <0.000030> 00:46:22 getpid() = 327 <0.000025> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=289153}, NULL) = 0 <0.000033> 00:46:22 getpid() = 327 <0.000138> 00:46:22 getpid() = 327 <0.000031> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=289819}, NULL) = 0 <0.000175> 00:46:22 getpid() = 327 <0.000035> 00:46:22 getpid() = 327 <0.000092> 00:46:22 getpid() = 327 <0.000025> 00:46:22 getpid() = 327 <0.000025> 00:46:22 getpid() = 327 <0.000037> 00:46:22 lstat("/var/www/auto/vendor/composer/ClassLoader.php", {st_mode=S_IFREG|0644, st_size=13459, ...}) = 0 <0.044433> 00:46:22 open("/var/www/auto/vendor/composer/ClassLoader.php", O_RDONLY) = 3 <0.003333> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=13459, ...}) = 0 <0.001188> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=13459, ...}) = 0 <0.008426> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=13459, ...}) = 0 <0.038343> 00:46:22 mmap(NULL, 13459, PROT_READ, MAP_SHARED, 3, 0) = 0x7f9f6646b000 <0.000158> 00:46:22 munmap(0x7f9f6646b000, 13459) = 0 <0.000172> 00:46:22 close(3) = 0 <0.007917> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=449484}, NULL) = 0 <0.000338> 00:46:22 getpid() = 327 <0.000228> 00:46:22 getpid() = 327 <0.000147> 00:46:22 getpid() = 327 <0.000952> 00:46:22 getpid() = 327 <0.000137> 00:46:22 getpid() = 327 <0.000156> 00:46:22 getpid() = 327 <0.000097> 00:46:22 getpid() = 327 <0.000162> 00:46:22 getpid() = 327 <0.000131> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=457720}, NULL) = 0 <0.000170> 00:46:22 getpid() = 327 <0.000039> 00:46:22 getpid() = 327 <0.000032> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.004076> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=506246}, NULL) = 0 <0.000083> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000041> 00:46:22 getpid() = 327 <0.000032> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=508617}, NULL) = 0 <0.000165> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000032> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000028> 00:46:22 getpid() = 327 <0.000036> 00:46:22 lstat("/var/www/auto/vendor/composer/autoload_static.php", {st_mode=S_IFREG|0644, st_size=317, ...}) = 0 <0.025765> 00:46:22 open("/var/www/auto/vendor/composer/autoload_static.php", O_RDONLY) = 3 <0.066066> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=317, ...}) = 0 <0.018639> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=317, ...}) = 0 <0.081617> 00:46:22 fstat(3, {st_mode=S_IFREG|0644, st_size=317, ...}) = 0 <0.011327> 00:46:22 mmap(NULL, 317, PROT_READ, MAP_SHARED, 3, 0) = 0x7f9f6646e000 <0.000209> 00:46:22 munmap(0x7f9f6646e000, 317) = 0 <0.000307> 00:46:22 close(3) = 0 <0.005657> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=742875}, NULL) = 0 <0.000130> 00:46:22 getpid() = 327 <0.000036> 00:46:22 getpid() = 327 <0.000036> 00:46:22 getpid() = 327 <0.000034> 00:46:22 getpid() = 327 <0.000042> 00:46:22 getpid() = 327 <0.000032> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=744223}, NULL) = 0 <0.000053> 00:46:22 getpid() = 327 <0.000043> 00:46:22 getpid() = 327 <0.000045> 00:46:22 getpid() = 327 <0.000036> 00:46:22 getpid() = 327 <0.000047> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=745242}, NULL) = 0 <0.000051> 00:46:22 getpid() = 327 <0.000044> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000027> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=746100}, NULL) = 0 <0.000038> 00:46:22 getpid() = 327 <0.000034> 00:46:22 getpid() = 327 <0.000045> 00:46:22 getpid() = 327 <0.000034> 00:46:22 getpid() = 327 <0.000034> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000033> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=747378}, NULL) = 0 <0.000050> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000026> 00:46:22 gettimeofday({tv_sec=1551660382, tv_usec=748255}, NULL) = 0 <0.000041> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000029> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000027> 00:46:22 getpid() = 327 <0.000044> 00:46:22 getpid() = 327 <0.000034> 00:46:22 getpid() = 327 <0.000032> 00:46:22 getpid() = 327 <0.000033> 00:46:22 getpid() = 327 <0.000031> 00:46:22 getpid() = 327 <0.000045> 00:46:22 write(1, "123", 3123) = 3 <0.000026> 00:46:22 getpid() = 327 <0.000031> 00:46:22 close(2) = 0 <0.000036> 00:46:22 close(1) = 0 <0.000034> strace With xdebug remote session ----- "step_into -i 48\0", 128, 0, NULL, NULL) = 16 <7.467581> [pid 508] lstat("/var/www/auto/vendor/composer/autoload_real.php", {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.000759> [pid 508] lstat("/var/www/auto/vendor/composer", {st_mode=S_IFDIR|0755, st_size=203, ...}) = 0 <0.000021> [pid 508] open("/var/www/auto/vendor/composer/autoload_real.php", O_RDONLY) = 4 <0.000235> [pid 508] fstat(4, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.000064> [pid 508] fstat(4, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.000015> [pid 508] fstat(4, {st_mode=S_IFREG|0644, st_size=1762, ...}) = 0 <0.000015> [pid 508] mmap(NULL, 1762, PROT_READ, MAP_SHARED, 4, 0) = 0x7f20f5e16000 <0.000078> [pid 508] munmap(0x7f20f5e16000, 1762) = 0 <0.000261> [pid 508] close(4) = 0 <0.000193> [pid 508] getpid() = 508 <0.000073> [pid 508] getpid() = 508 <0.000012> [pid 508] getpid() = 508 <0.000023> [pid 508] getpid() = 508 <0.000013> [pid 508] write(3, "321\0<?xml version=\"1.0\" encoding"..., 326) = 326 <0.000034> [pid 508] recvfrom(3, "stack_get -i 49\0", 128, 0, NULL, NULL) = 16 <0.294516> [pid 508] write(3, "577\0<?xml version=\"1.0\" encoding"..., 582) = 582 <0.000044> [pid 508] recvfrom(3, "context_get -i 50 -d 0 -c 0\0", 128, 0, NULL, NULL) = 28 <0.170437> [pid 508] write(3, "198\0<?xml version=\"1.0\" encoding"..., 203) = 203 <0.000038> [pid 508] recvfrom(3, "context_get -i 51 -d 0 -c 1\0", 128, 0, NULL, NULL) = 28 <0.159945> [pid 508] write(3, "7202\0<?xml version=\"1.0\" encodin"..., 7208) = 7208 <0.000054> [pid 508] recvfrom(3, "context_get -i 52 -d 0 -c 2\0", 128, 0, NULL, NULL) = 28 <0.236242> [pid 508] write(3, "198\0<?xml version=\"1.0\" encoding"..., 203) = 203 <0.000036> [pid 508] recvfrom(3, "step_into -i 53\0", 128, 0, NULL, NULL) = 16 <5.774993> [pid 508] getpid() = 508 <0.000015> [pid 508] getpid() = 508 <0.000050> [pid 508] write(3, "307\0<?xml version=\"1.0\" encoding"..., 312) = 312 <0.000078> [pid 508] recvfrom(3, "stack_get -i 54\0", 128, 0, NULL, NULL) = 16 <0.148856> [pid 508] write(3, "442\0<?xml version=\"1.0\" encoding"..., 447) = 447 <0.000040> [pid 508] recvfrom(3, "context_get -i 55 -d 0 -c 0\0", 128, 0, NULL, NULL) = 28 <0.154518> [pid 508] write(3, "198\0<?xml version=\"1.0\" encoding"..., 203) = 203 <0.000049> [pid 508] recvfrom(3, "context_get -i 56 -d 0 -c 1\0", 128, 0, NULL, NULL) = 28 <0.159570> [pid 508] write(3, "7202\0<?xml version=\"1.0\" encodin"..., 7208) = 7208 <0.000045> [pid 508] recvfrom(3, "context_get -i 57 -d 0 -c 2\0", 128, 0, NULL, NULL) = 28 <0.200547> [pid 508] write(3, "198\0<?xml version=\"1.0\" encoding"..., 203) = 203 <0.000034> [pid 508] recvfrom(3,"step_into -i 58\0", 128, 0, NULL, NULL) = 16 <1.951919> [pid 508] getpid() = 508 <0.000014> [pid 508] getpid() = 508 <0.000014> [pid 508] getpid() = 508 <0.000025> [pid 508] getpid() = 508 <0.000014> [pid 508] getpid() = 508 <0.000014> [pid 508] write(3, "322\0<?xml version=\"1.0\" encoding"..., 327) = 327 <0.000042> [pid 508] recvfrom(3, "stack_get -i 59\0", 128, 0, NULL, NULL) = 16 <0.147643> [pid 508] write(3, "631\0<?xml version=\"1.0\" encoding"..., 636) = 636 <0.000043> [pid 508] recvfrom(3, "context_get -i 60 -d 0 -c 0\0", 128, 0, NULL, NULL) = 28 <0.202932> [pid 508] write(3, "919\0<?xml version=\"1.0\" encoding"..., 924) = 924 <0.000039> [pid 508] recvfrom(3, "context_get -i 61 -d 0 -c 1\0", 128, 0, NULL, NULL) = 28 <0.147002> [pid 508] write(3, "7202\0<?xml version=\"1.0\" encodin"..., 7208) = 7208 <0.000050> [pid 508] recvfrom(3, "context_get -i 62 -d 0 -c 2\0", 128, 0, NULL, NULL) = 28 <0.215789> [pid 508] write(3, "198\0<?xml version=\"1.0\" encoding"..., 203) = 203 <0.000034> | ||||
Tags | No tags attached. | ||||
Operating System | |||||
PHP Version | 7.3.2-7.3.4 | ||||
|
I have the same issue, i did some tests: PHP 7.3.3-1+ubuntu18.04.1+deb.sury.org+1 PHP 7.2.16-1+ubuntu18.04.1+deb.sury.org+1 PHP 7.3.3-1+ubuntu18.04.1+deb.sury.org+1 + php-xdebug_2.7.0+2.5.5-1+ubuntu18.04.1+deb.sury.org+1_amd64 PHP 7.2.16-1+ubuntu18.04.1+deb.sury.org+1 + php-xdebug_2.7.0+2.5.5-1+ubuntu18.04.1+deb.sury.org+1_amd64 PHP 7.2.16-1+ubuntu18.04.1+deb.sury.org+1 + php-xdebug_2.6.0+2.5.5-1+ubuntu18.04.1+deb.sury.org+1_amd64 Symfony cache warmup for a large project: <code> 7.3 7.2 7.3+xdebug-2.7.0 7.2+xdebug-2.7.0 7.2+xdebug-2.6.0 8,908s 10,014s 126,250s 110,346s 19,241s 7,731s 8,324s 117,914s 112,205s 18,110s 9,035s 8,602s 109,510s 122,575s 17,367s 7,005s 7,802s 114,216s 116,401s 17,065s 10,747s 10,842s 116,974s 114,885s 17,598s </code> Basically, we can't run xdebug on our devservers anymore as several pages will just hit the 30s php timeout. Straces: (only top 3-4 shown) <code> PHP 7.3: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 25.67 0.481834 5 89687 10112 lstat 13.30 0.249577 7 34724 2445 stat 12.77 0.239598 11 21114 2817 openat PHP 7.2: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 24.73 0.445916 5 89688 10112 lstat 13.54 0.244142 12 21113 2817 openat 13.07 0.235713 7 34727 2448 stat PHP 7.3 + xdebug 2.7.0 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 98.98 331.828781 4 76907237 getpid 0.23 0.780007 8 93160 10112 lstat 0.17 0.569675 27 21115 2817 openat 0.15 0.486888 14 34724 2445 stat PHP 7.2 + xdebug 2.7.0 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 98.78 223.628090 4 52090195 getpid 0.29 0.663600 8 78637 10115 lstat 0.15 0.341328 11 30607 1422 stat 0.15 0.330559 18 18176 2818 openat PHP 7.2 + xdebug 2.6.0 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 25.66 0.426514 5 89688 10112 lstat 12.71 0.211269 10 21114 2817 openat 11.76 0.195505 6 34727 2448 stat </code> |
|
This is very easily fixed with this patch: Index: xdebug_com.c IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== --- xdebug_com.c (revision 136f37dd02da680cf9dd09f69cb5ffea924825e8) +++ xdebug_com.c (date 1552049137000) @@ -485,16 +485,14 @@ int xdebug_is_debug_connection_active_for_current_pid() { - long pid = getpid(); - /* Start debugger if previously a connection was established and this * process no longer has the same PID */ - if ((xdebug_is_debug_connection_active() && (XG(remote_connection_pid) != pid))) { + if ((xdebug_is_debug_connection_active() && (XG(remote_connection_pid) != getpid()))) { xdebug_restart_debugger(); } return ( - XG(remote_connection_enabled) && (XG(remote_connection_pid) == pid) + XG(remote_connection_enabled) && (XG(remote_connection_pid) == getpid()) ); } Using the original code with app/console list = 29.570 seconds Running app/console list with this code = 1.4 seconds and 2.340.299 less calls to getpid() |
|
Thanks for the report, and the Pull Request! |
|
looks like that code smell |
Date Modified | Username | Field | Change |
---|---|---|---|
2019-03-04 01:05 | blackbass | New Issue | |
2019-03-08 09:57 | kees | Note Added: 0004941 | |
2019-03-08 12:48 | kees | Note Added: 0004942 | |
2019-03-08 16:56 | derick | Assigned To | => derick |
2019-03-08 16:56 | derick | Status | new => closed |
2019-03-08 16:56 | derick | Resolution | open => fixed |
2019-03-08 16:56 | derick | Fixed in Version | => 2.7.1 |
2019-03-08 16:56 | derick | Note Added: 0004945 | |
2019-03-13 02:17 | blackbass | Note Added: 0004962 |