Skip to content

Instantly share code, notes, and snippets.

@Antnee

Antnee/strace.txt

Last active November 19, 2019 16:43
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save Antnee/21112d64467f1d09b11428321625f65e to your computer and use it in GitHub Desktop.
Save Antnee/21112d64467f1d09b11428321625f65e to your computer and use it in GitHub Desktop.
Download ZIP
Slow Xdebug 2.8.0 Strace
Raw
strace.txt
% 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
@Antnee
Copy link
Author

Antnee commented Nov 19, 2019

And the same test again, only running Xdebug 2.7.2:

% 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

@Antnee
Copy link
Author

Antnee commented Nov 19, 2019

Here's a quick example of the sort of thing that I'm getting from a strace -r -Tfe trace=open vendor/bin/phpunit --testdox --colors=always --coverage-html report command:

 ◓ running tests     0.971306 open("/var/www/html/tests/../spool/phpunit", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 9 <0.001046>
 ◑ 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>
 ◒ running tests     0.085541 open("/var/www/html/src/Bar.php", O_RDONLY) = 9 <0.000818>

App filenames obfuscated

There are a lot of very slow opens, and they come from all over the app, not just in the vendor/ directory as displayed above; I have them all over the app, and there's no obvious pattern to it, either

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment