A little bit harder to get clean output on this one. The numbers in the
<>'s are the times for the system call. Here is a 4.2 hello world
request:
accept(24, {sin_family=AF_INET, sin_port=htons(57198),
sin_addr=inet_addr("10.0.1.254")}}, [16]) = 3 <4.035087>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x40035250, [], SA_INTERRUPT|0x4000000}, 8) = 0
<0.000009>
getsockname(3, {sin_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("10.0.1.253")}}, [16]) = 0 <0.000009>
setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000011>
alarm(300) = 0 <0.000010>
read(3, "GET /index.php HTTP/1.0\r\nUser-Ag"..., 4096) = 106 <0.000018>
rt_sigaction(SIGUSR1, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000008>
time(NULL) = 1046024055 <0.000008>
alarm(300) = 300 <0.000009>
alarm(0) = 300 <0.000008>
stat64("/html/index.php", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000023>
alarm(300) = 0 <0.000009>
umask(077) = 022 <0.000007>
umask(022) = 077 <0.000008>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000008>
rt_sigaction(SIGPROF, {0x40690508, [PROF], SA_RESTART|0x4000000}, {0x40690508, [PROF],
SA_RESTART|0x4000000}, 8) = 0 <0.000008>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000008>
getcwd("/usr/sbin", 4095) = 10 <0.000012>
chdir("/html") = 0 <0.000014>
open("/html/index.php", O_RDONLY) = 4 <0.000019>
getcwd("/html", 4095) = 6 <0.000009>
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>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffe1a0) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000009>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x402ba000
<0.000027>
read(4, "<html>\n<body>\n<?\n\techo \"Hello Wo"..., 8192) = 58 <0.000015>
read(4, "", 4096) = 0 <0.000008>
read(4, "", 8192) = 0 <0.000008>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffd160) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000008>
close(4) = 0 <0.000010>
munmap(0x402ba000, 4096) = 0 <0.000013>
alarm(300) = 300 <0.000009>
alarm(0) = 300 <0.000008>
chdir("/usr/sbin") = 0 <0.000019>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 <0.000009>
umask(022) = 022 <0.000007>
alarm(0) = 0 <0.000008>
select(4, [3], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000010>
write(3, "HTTP/1.1 200 OK\r\nDate: Sun, 23 F"..., 232) = 232 <0.000034>
time(NULL) = 1046024055 <0.000008>
write(39, "10.0.1.254 - - [23/Feb/2003:10:1"..., 94) = 94 <0.000024>
alarm(30) = 0 <0.000009>
shutdown(3, 1 /* send */) = 0 <0.000024>
select(4, [3], NULL, NULL, {2, 0}) = 1 (in [3], left {2, 0}) <0.000775>
read(3, "", 512) = 0 <0.000014>
close(3) = 0 <0.000027>
alarm(0) = 30 <0.000008>
rt_sigaction(SIGUSR1, {0x40035250, [], SA_INTERRUPT|0x4000000}, {SIG_IGN}, 8) = 0
<0.000009>
alarm(0) = 0 <0.000008>
This is just from accept-to-accept, so it doesn't include any Apache/PHP
startup calls at all. A couple of these syscalls are from Apache but
starting with the alarm(300) call (I think) we are in PHP. The only thing
that looks slightly off to me in this set of calls are the consecutive
umask() calls. Might be something worth tracking down to see if one can
be eliminated. The point here however is to compare to 4.3:
accept(24, {sin_family=AF_INET, sin_port=htons(57262),
sin_addr=inet_addr("10.0.1.254")}}, [16]) = 3 <8.485988>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x40035250, [], SA_INTERRUPT|0x4000000}, 8) = 0
<0.000009>
getsockname(3, {sin_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("10.0.1.253")}}, [16]) = 0 <0.000010>
setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000012>
alarm(300) = 0 <0.000010>
read(3, "GET /index.php HTTP/1.0\r\nUser-Ag"..., 4096) = 106 <0.000016>
rt_sigaction(SIGUSR1, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000008>
time(NULL) = 1046024677 <0.000008>
alarm(300) = 300 <0.000008>
alarm(0) = 300 <0.000008>
stat64("/html/index.php", {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000022>
alarm(300) = 0 <0.000009>
umask(077) = 022 <0.000008>
umask(022) = 077 <0.000007>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000009>
rt_sigaction(SIGPROF, {0x4072d6b4, [PROF], SA_RESTART|0x4000000}, {0x4072d6b4, [PROF],
SA_RESTART|0x4000000}, 8) = 0 <0.000008>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000007>
getcwd("/usr/sbin", 4095) = 10 <0.000012>
chdir("/html") = 0 <0.000015>
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.000013>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 <0.000009>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000008>
rt_sigaction(SIGPROF, {0x4072d6b4, [PROF], SA_RESTART|0x4000000}, {0x4072d6b4, [PROF],
SA_RESTART|0x4000000}, 8) = 0 <0.000009>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000008>
getcwd("/html", 4095) = 6 <0.000010>
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>
open("/html/index.php", O_RDONLY) = 4 <0.000018>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x402ba000
<0.000028>
_llseek(4, 0, [0], SEEK_CUR) = 0 <0.000009>
lseek(4, 0, SEEK_SET) = 0 <0.000009>
brk(0) = 0x81a8000 <0.000008>
brk(0x81a9000) = 0x81a9000 <0.000011>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffd190) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000009>
brk(0) = 0x81a9000 <0.000007>
brk(0x81aa000) = 0x81aa000 <0.000009>
read(4, "<html>\n<body>\n<?\n\techo \"Hello Wo"..., 8192) = 58 <0.000016>
read(4, "", 4096) = 0 <0.000008>
read(4, "", 8192) = 0 <0.000009>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffc150) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000008>
close(4) = 0 <0.000010>
munmap(0x402ba000, 4096) = 0 <0.000014>
alarm(300) = 300 <0.000010>
alarm(0) = 300 <0.000008>
chdir("/usr/sbin") = 0 <0.000019>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 <0.000008>
umask(022) = 022 <0.000007>
alarm(0) = 0 <0.000008>
select(4, [3], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000011>
write(3, "HTTP/1.1 200 OK\r\nDate: Sun, 23 F"..., 232) = 232 <0.000034>
time(NULL) = 1046024677 <0.000009>
write(39, "10.0.1.254 - - [23/Feb/2003:10:2"..., 94) = 94 <0.000024>
alarm(30) = 0 <0.000009>
shutdown(3, 1 /* send */) = 0 <0.000022>
select(4, [3], NULL, NULL, {2, 0}) = 1 (in [3], left {2, 0}) <0.000758>
read(3, "", 512) = 0 <0.000013>
close(3) = 0 <0.000027>
alarm(0) = 30 <0.000009>
rt_sigaction(SIGUSR1, {0x40035250, [], SA_INTERRUPT|0x4000000}, {SIG_IGN}, 8) = 0
<0.000009>
alarm(0) = 0 <0.000008>
65 system calls for the same request with 4.3 compared to 50 for 4.2. As
we saw with the cgi case, we are doing a double realpath() on the script.
The two lstat64() calls come from the realpath() call and in 4.2 we only
see a single set of those. The deeper your doc_root, the more expensive
this becomes. At Yahoo! I had to turn off the realpath() call completely
so it is never called in PHP 4.2, but now in 4.3 we are doing it twice!
Ouch! This is something we need to fix before 4.3.2. I'll try to get a
patch in tomorrow. A couple of setitimer() calls have also snuck in
before the open() call. In 4.2 to open the script we did:
getcwd("/usr/sbin", 4095) = 10 <0.000012>
chdir("/html") = 0 <0.000014>
open("/html/index.php", O_RDONLY) = 4 <0.000019>
getcwd("/html", 4095) = 6 <0.000009>
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>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffe1a0) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000009>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
For 4.3 this ballooned to:
getcwd("/usr/sbin", 4095) = 10 <0.000012>
chdir("/html") = 0 <0.000015>
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.000013>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 <0.000009>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000008>
rt_sigaction(SIGPROF, {0x4072d6b4, [PROF], SA_RESTART|0x4000000}, {0x4072d6b4, [PROF],
SA_RESTART|0x4000000}, 8) = 0 <0.000009>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000008>
getcwd("/html", 4095) = 6 <0.000010>
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>
open("/html/index.php", O_RDONLY) = 4 <0.000018>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
fstat64(4, {st_mode=S_IFREG|0644, st_size=58, ...}) = 0 <0.000008>
Even in 4.2, I think we can optimize it. Assuming chdir() doesn't return
an error, we shouldn't need that second getpwd() call since we just did
the chdir() and we should know where we are.
In 4.3, we have the obviously bogus double realpath() which I will fix.
We have the setitimer() calls which I don't understand which I assume
cause the sigaction and sigprocmask calls and then finally we fstat the
file descriptor 3 times instead of once which also needs to be fixed.
Once we have opened the script and mmap'ed some memory, in 4.2 we simply
start reading from the file descriptor and the next set of syscalls are:
read(4, "<html>\n<body>\n<?\n\techo \"Hello Wo"..., 8192) = 58 <0.000015>
read(4, "", 4096) = 0 <0.000008>
read(4, "", 8192) = 0 <0.000008>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffd160) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000008>
close(4) = 0 <0.000010>
munmap(0x402ba000, 4096) = 0 <0.000013>
I don't understand that ioctl() there, but otherwise it looks fine.
In 4.3 we have:
_llseek(4, 0, [0], SEEK_CUR) = 0 <0.000009>
lseek(4, 0, SEEK_SET) = 0 <0.000009>
brk(0) = 0x81a8000 <0.000008>
brk(0x81a9000) = 0x81a9000 <0.000011>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffd190) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000009>
brk(0) = 0x81a9000 <0.000007>
brk(0x81aa000) = 0x81aa000 <0.000009>
read(4, "<html>\n<body>\n<?\n\techo \"Hello Wo"..., 8192) = 58 <0.000016>
read(4, "", 4096) = 0 <0.000008>
read(4, "", 8192) = 0 <0.000009>
ioctl(4, SNDCTL_TMR_TIMEBASE, 0xbfffc150) = -1 ENOTTY (Inappropriate ioctl for device)
<0.000008>
close(4) = 0 <0.000010>
munmap(0x402ba000, 4096) = 0 <0.000014>
I really don't understand the SEEK_CUR there. We're seeking forward 0
bytes from the current location followed directly by a SEEK_SET back to 0?
Is this streams overhead or something? Wez?
>From there on the requests are similar. The alarm(0) calls right after
alarm(300) could probably be skipped in both cases.
Anyway, I will go after all these extra lstat/fstat calls and fix that,
but I would appreciate some help with the setitimer() and weird seeking
stuff.
-Rasmus
--
PHP Development Mailing List <http://www.php.net/>
To unsubscribe, visit: http://www.php.net/unsub.php
