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