View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0001641XdebugStacktracespublic2019-03-04 01:052019-03-13 02:17
Reporterblackbass Assigned Toderick  
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionfixed 
Product Version2.7.0RC2 
Fixed in Version2.7.1 
Summary0001641: Perfomance degradation with getpid syscall
DescriptionPHP 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 Reproducecreate 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>
TagsNo tags attached.
Operating System
PHP Version7.3.2-7.3.4

Activities

kees

2019-03-08 09:57

reporter   ~0004941

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>

kees

2019-03-08 12:48

reporter   ~0004942

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

derick

2019-03-08 16:56

administrator   ~0004945

Thanks for the report, and the Pull Request!

blackbass

2019-03-13 02:17

reporter   ~0004962

looks like that code smell

Issue History

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