So, I am just starting out down the path to figure out why PHP 4.3 has
gotten so much slower than 4.2. "strace -c" provides the first clue. A
straight "./configure --enable-inline-optimization && make" command-line
build for 4.2, 4.3 and 5.0 run on a simple hello world script reveals that
we have gone from 219 system calls in 4.2 to 233 in 4.3 to 236 in 5.0.
This is a bad trend and we really need to make an effort to reverse this.
4.2 Hello World from command-line:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
21.86 0.000266 16 17 3 open
19.06 0.000232 29 8 write
15.69 0.000191 11 18 read
12.57 0.000153 2 85 brk
10.44 0.000127 5 24 old_mmap
4.11 0.000050 10 5 munmap
3.37 0.000041 7 6 mmap2
2.96 0.000036 5 8 mprotect
2.55 0.000031 2 15 fstat64
2.38 0.000029 2 14 close
0.74 0.000009 5 2 lstat64
0.66 0.000008 4 2 rt_sigaction
0.66 0.000008 8 1 getcwd
0.49 0.000006 3 2 2 ioctl
0.49 0.000006 6 1 uname
0.41 0.000005 3 2 setitimer
0.41 0.000005 3 2 fcntl64
0.33 0.000004 4 1 chdir
0.25 0.000003 2 2 getpid
0.25 0.000003 3 1 _llseek
0.16 0.000002 2 1 time
0.08 0.000001 1 1 gettimeofday
0.08 0.000001 1 1 rt_sigprocmask
------ ----------- ----------- --------- --------- ----------------
100.00 0.001217 219 5 total
4.3 Hello World from command-line:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
21.55 0.000292 15 20 7 open
18.30 0.000248 28 9 write
14.61 0.000198 12 17 read
13.06 0.000177 2 95 brk
8.34 0.000113 5 22 old_mmap
6.35 0.000086 22 4 lstat64
3.69 0.000050 10 5 munmap
3.03 0.000041 7 6 mmap2
2.58 0.000035 5 7 mprotect
2.36 0.000032 2 14 fstat64
2.21 0.000030 2 13 close
0.59 0.000008 2 4 setitimer
0.59 0.000008 3 3 rt_sigaction
0.59 0.000008 8 1 getcwd
0.37 0.000005 5 1 chdir
0.37 0.000005 5 1 uname
0.30 0.000004 2 2 2 ioctl
0.30 0.000004 2 2 fcntl64
0.22 0.000003 2 2 getpid
0.15 0.000002 2 1 time
0.15 0.000002 2 1 gettimeofday
0.15 0.000002 2 1 _llseek
0.15 0.000002 1 2 rt_sigprocmask
------ ----------- ----------- --------- --------- ----------------
100.00 0.001355 233 9 total
5.0 Hello World from command-line:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
21.70 0.000288 14 20 7 open
18.99 0.000252 28 9 write
15.07 0.000200 2 97 brk
14.92 0.000198 12 17 read
8.29 0.000110 5 22 old_mmap
5.43 0.000072 12 6 munmap
3.54 0.000047 7 7 mmap2
2.49 0.000033 5 7 mprotect
2.19 0.000029 2 13 close
2.03 0.000027 2 14 fstat64
1.43 0.000019 5 4 lstat64
0.68 0.000009 3 3 rt_sigaction
0.60 0.000008 2 4 setitimer
0.60 0.000008 8 1 getcwd
0.38 0.000005 5 1 uname
0.30 0.000004 4 1 chdir
0.30 0.000004 2 2 fcntl64
0.23 0.000003 2 2 getpid
0.23 0.000003 3 1 1 ioctl
0.23 0.000003 3 1 _llseek
0.15 0.000002 2 1 time
0.15 0.000002 1 2 rt_sigprocmask
0.08 0.000001 1 1 gettimeofday
------ ----------- ----------- --------- --------- ----------------
100.00 0.001327 236 8 total
Now, looking into these a bit more. We added 3 more open calls between
4.2 and 4.3. In 4.2 we had:
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000020>
open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000015>
open("/lib/libdl.so.2", O_RDONLY) = 3 <0.000017>
open("/lib/libpam.so.0", O_RDONLY) = 3 <0.000021>
open("/lib/libcrypt.so.1", O_RDONLY) = 3 <0.000017>
open("/lib/libresolv.so.2", O_RDONLY) = 3 <0.000017>
open("/lib/i686/libm.so.6", O_RDONLY) = 3 <0.000019>
open("/lib/libnsl.so.1", O_RDONLY) = 3 <0.000017>
open("/lib/i686/libc.so.6", O_RDONLY) = 3 <0.000019>
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3 <0.000034>
open("./php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000014>
open("/usr/local/lib/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000016>
open("/etc/nsswitch.conf", O_RDONLY) = 3 <0.000033>
open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000019>
open("/lib/libnss_files.so.2", O_RDONLY) = 3 <0.000021>
open("/etc/services", O_RDONLY) = 3 <0.000018>
open("/html/index.php", O_RDONLY) = 3 <0.000029>
In 4.3:
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000019>
open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000015>
open("/lib/libcrypt.so.1", O_RDONLY) = 3 <0.000018>
open("/lib/libresolv.so.2", O_RDONLY) = 3 <0.000021>
open("/lib/i686/libm.so.6", O_RDONLY) = 3 <0.000019>
open("/lib/libdl.so.2", O_RDONLY) = 3 <0.000018>
open("/lib/libnsl.so.1", O_RDONLY) = 3 <0.000018>
open("/lib/i686/libc.so.6", O_RDONLY) = 3 <0.000018>
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3 <0.000031>
open("./php-cgi.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000016>
open(".//php-cgi.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000010>
open("/usr/local/lib/php-cgi.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000016>
open("./php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000011>
open(".//php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000010>
open("/usr/local/lib/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
<0.000013>
open("/etc/nsswitch.conf", O_RDONLY) = 3 <0.000033>
open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000019>
open("/lib/libnss_files.so.2", O_RDONLY) = 3 <0.000020>
open("/etc/services", O_RDONLY) = 3 <0.000018>
open("/html/index.php", O_RDONLY) = 3 <0.000029>
So, obviously these opens don't really affect the module version since
they only happen on startup, but they still don't seem right. I
understand ./php-cgi.ini, but .//php-cgi.ini and .//php.ini? Looks like a
missing check there.
The 2 extra calls to lstat64 is more worrisome:
In 4.2:
lstat64("/html", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0 <0.000012>
lstat64("/html/index.php", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000011>
In 4.3:
lstat64("/html", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0 <0.000011>
lstat64("/html/index.php", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000011>
lstat64("/html", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0 <0.000011>
lstat64("/html/index.php", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000012>
What happened here? Why do we suddenly need to double stat this stuff?
It looks like the result of 2 calls to realpath() on the file to be
opened.
The extra write call is a bit odd.
In 4.2:
write(1, "X-Powered-By: PHP/4.2.4-dev", 27X-Powered-By: PHP/4.2.4-dev) = 27 <0.000009>
write(1, "\r\n", 2
write(1, "Content-type: text/html", 23Content-type: text/html) = 23 <0.000008>
write(1, "\r\n", 2
write(1, "\r\n", 2
write(1, "<html>\n<body>\n", 14<html>
write(1, "Hello World", 11Hello World) = 11 <0.000008>
write(1, "</body>\n</html>\t\n", 17</body>
In 4.3:
write(1, "Content-type: ", 14Content-type: ) = 14 <0.000008>
write(1, "text/html", 9text/html) = 9 <0.000008>
write(1, "\r\n", 2
write(1, "X-Powered-By: PHP/4.3.2-dev", 27X-Powered-By: PHP/4.3.2-dev) = 27 <0.000008>
write(1, "\r\n", 2
write(1, "\r\n", 2
write(1, "<html>\n<body>\n", 14<html>
write(1, "Hello World", 11Hello World) = 11 <0.000008>
write(1, "</body>\n</html>\t\n", 17</body>
It now takes two writes to write the content-type for some reason.
Anybody know what the increase from 85 to 95 brk calls actually tells us?
Anyway, just my first whack at this. Need to do the more useful mod_php
analysis as well.
-Rasmus
--
PHP Development Mailing List <http://www.php.net/>
To unsubscribe, visit: http://www.php.net/unsub.php
