Newsgroups: php.internals
Path: news.php.net
Xref: news.php.net php.internals:49018
Return-Path: <v.damore@gmail.com>
Mailing-List: contact internals-help@lists.php.net; run by ezmlm
Delivered-To: mailing list internals@lists.php.net
Received: (qmail 64542 invoked from network); 9 Jul 2010 17:39:44 -0000
Received: from unknown (HELO lists.php.net) (127.0.0.1)
  by localhost with SMTP; 9 Jul 2010 17:39:44 -0000
Authentication-Results: pb1.pair.com header.from=v.damore@gmail.com; sender-id=pass; domainkeys=bad
Authentication-Results: pb1.pair.com smtp.mail=v.damore@gmail.com; spf=pass; sender-id=pass
Received-SPF: pass (pb1.pair.com: domain gmail.com designates 209.85.161.42 as permitted sender)
DomainKey-Status: bad
X-DomainKeys: Ecelerity dk_validate implementing draft-delany-domainkeys-base-01
X-PHP-List-Original-Sender: v.damore@gmail.com
X-Host-Fingerprint: 209.85.161.42 mail-fx0-f42.google.com  
Received: from [209.85.161.42] ([209.85.161.42:58446] helo=mail-fx0-f42.google.com)
	by pb1.pair.com (ecelerity 2.1.1.9-wez r(12769M)) with ESMTP
	id 2E/50-61692-DDE573C4 for <internals@lists.php.net>; Fri, 09 Jul 2010 13:39:42 -0400
Received: by fxm17 with SMTP id 17so1463905fxm.29
        for <internals@lists.php.net>; Fri, 09 Jul 2010 10:39:38 -0700 (PDT)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
        d=gmail.com; s=gamma;
        h=domainkey-signature:received:mime-version:received:from:date
         :message-id:subject:to:content-type;
        bh=l6G+DLtTh4amzyGlW3tEie6aeRkj9w79f0CSqI9cgxo=;
        b=FVl5X/Sxpo2O1DFLaLZH521khA88JIL98JuYWQNb/3awvTo5sk/3RxPDElQyXQRKE+
         ReeGHzcTrdEN73Cu9fTk3YRFfQUd5Iy2Gm/A/cfu+Tmrq8/MeAqoVhq0UrHno677eML2
         RbDWU3qwFoDP8iATVLXBf4ksf3puV/uAAX96E=
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=gmail.com; s=gamma;
        h=mime-version:from:date:message-id:subject:to:content-type;
        b=fCmkFfJXSPmyJOOBMnoqpdiGfOhikFy6rxF1NsWtxCJ1z9fTK6DPvjqtEuLiFtKnIK
         TC0K9Ac5JLIgrtH0wjNW3m+sEXANeZDIuou7yWK6aNkcvtXMQbB/RVgwF59t2j/GCU3W
         mcyTuA7wApucOIWHgypYpFL4Ih233wU7Ynm0I=
Received: by 10.239.190.20 with SMTP id v20mr297965hbh.45.1278697177229; Fri, 
	09 Jul 2010 10:39:37 -0700 (PDT)
MIME-Version: 1.0
Received: by 10.239.174.14 with HTTP; Fri, 9 Jul 2010 10:39:17 -0700 (PDT)
Date: Fri, 9 Jul 2010 19:39:17 +0200
Message-ID: <AANLkTik3JJKNodbzAnYGQ8qpAinSiFTQEyHIsdxbISeI@mail.gmail.com>
To: internals@lists.php.net
Content-Type: multipart/alternative; boundary=001485f03c06062c09048af7e34d
Subject: Performance problem with php
From: v.damore@gmail.com ("Vincenzo D'Amore")

--001485f03c06062c09048af7e34d
Content-Type: text/plain; charset=UTF-8

Hello all,

I have already notified to the mailing list a performance problem with
apache/mod_php5.

Now I have an update and I think this is probably a bug.
PHP lstat the full path more times before read the file when in apache httpd
configuration is specified *PHP_ADMIN_VALUE open_basedir *setting.

I have a simple website with only phpinfo.php page and inside we have only
"<? phpinfo() ?>".

httpd.2.2.15 fresh compiled and PHP 5.2.13.

If is specified *PHP_ADMIN_VALUE open_basedir* in Virtual host
configuration:

<Directory "/usr/local/myspace/webspace/httpdocs">
 *               PHP_ADMIN_VALUE open_basedir "/usr/local/myspace/webspace"*
</Directory>
<VirtualHost *:80>
        ServerName damorealt.xoom.it
        DocumentRoot "/usr/local/myspace/webspace/httpdocs"
    CustomLog   /var/log/httpd/damorealt/access_log   combined
    ErrorLog   /var/log/httpd/damorealt/error_log
</VirtualHost >

Calling page http://damorealt.xoom.it/phpinfo.php we can reproduce following
behavior:

25933 accept(3, {sa_family=AF_INET, sin_port=htons(47433),
sin_addr=inet_addr("212.48.14.186")}, [17179869200]) = 15
25933 getsockname(15, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("151.99.197.198")}, [17179869200]) = 0
25933 fcntl(15, F_GETFL)                = 0x2 (flags O_RDWR)
25933 fcntl(15, F_SETFL, O_RDWR|O_NONBLOCK) = 0
25933 read(15, "GET /phpinfo.php HTTP/1.0\r\nUser-"..., 8000) = 129
25933 gettimeofday({1278695388, 52976}, NULL) = 0
25933 stat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0
25933 open("/usr/local/myspace/.htaccess", O_RDONLY) = -1 ENOENT (No such
file or directory)
25933 open("/usr/local/myspace/webspace/.htaccess", O_RDONLY) = -1 ENOENT
(No such file or directory)
25933 open("/usr/local/myspace/webspace/httpdocs/.htaccess", O_RDONLY) = -1
ENOENT (No such file or directory)
25933 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php/.htaccess",
O_RDONLY) = -1 ENOTDIR (Not a directory)
25933 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={20, 0}}, NULL) =
0
25933 rt_sigaction(SIGPROF, {0x2b80442fdd80, [PROF], SA_RESTORER|SA_RESTART,
0x3916e302d0}, {SIG_DFL, [], 0}, 8) = 0
25933 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
25933 getcwd("/"..., 4095)              = 2
25933 chdir("/usr/local/myspace/webspace/httpdocs") = 0

*water boiling point*

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096, ...})
= 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

First check

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096, ...})
= 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

Second check

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096, ...})
= 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0

Third check (incomplete)

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096, ...})
= 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

Final check and then read the file.

25933 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php", O_RDONLY) =
16
25933 fstat(16, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
25933 read(16, "<? phpinfo() ?>\n", 8192) = 16
25933 read(16, "", 8192)                = 0
25933 read(16, "", 8192)                = 0
25933 close(16)                         = 0


If *PHP_ADMIN_VALUE open_basedir "/usr/local/myspace/webspace"  is
removed*in virtual host configuration we finally have simpliest
behavior:

226235 accept(3, {sa_family=AF_INET, sin_port=htons(59366),
sin_addr=inet_addr("212.48.14.186")}, [17179869200]) = 15
26235 getsockname(15, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("151.99.197.198")}, [17179869200]) = 0
26235 fcntl(15, F_GETFL)                = 0x2 (flags O_RDWR)
26235 fcntl(15, F_SETFL, O_RDWR|O_NONBLOCK) = 0
26235 read(15, "GET /phpinfo.php HTTP/1.0\r\nUser-"..., 8000) = 129
26235 gettimeofday({1278696735, 988799}, NULL) = 0
26235 stat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0
26235 open("/usr/local/myspace/.htaccess", O_RDONLY) = -1 ENOENT (No such
file or directory)
26235 open("/usr/local/myspace/webspace/.htaccess", O_RDONLY) = -1 ENOENT
(No such file or directory)
26235 open("/usr/local/myspace/webspace/httpdocs/.htaccess", O_RDONLY) = -1
ENOENT (No such file or directory)
26235 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php/.htaccess",
O_RDONLY) = -1 ENOTDIR (Not a directory)
26235 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={20, 0}}, NULL) =
0
26235 rt_sigaction(SIGPROF, {0x2afef587dd80, [PROF], SA_RESTORER|SA_RESTART,
0x3916e302d0}, {SIG_DFL, [], 0}, 8) = 0
26235 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
26235 getcwd("/"..., 4095)              = 2
26235 chdir("/usr/local/myspace/webspace/httpdocs") = 0

*water boiling point*

26235 time(NULL)                        = 1278696735
26235 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
26235 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
26235 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096, ...})
= 0
26235 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
26235 lstat("/usr/local/myspace/webspace/httpdocs", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
26235 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

And read the file.

26235 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php", O_RDONLY) =
16
26235 fstat(16, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
26235 read(16, "<? phpinfo() ?>\n", 8192) = 16
26235 read(16, "", 8192)                = 0
26235 read(16, "", 8192)                = 0
26235 close(16)                         = 0
26235 uname({sys="Linux", node="svilpar4", ...}) = 0
26235 time(NULL)                        = 1278696735
26235 writev(15, [{"HTTP/1.1 200 OK\r\nDate: Fri, 09 J"..., 173},
{"<!DOCTYPE html PUBLIC \"-//W3C//D"..., 4109}, {"<table border=\"0\"
cellpadding=\"3"..., 4101}], 3) = 8383
26235 writev(15, [{"<tr><td class=\"e\">highlight.bg</"..., 4105},
{"sendmail_from</td><td class=\"v\">"..., 4099}], 2) = 8204
26235 time(NULL)                        = 1278696735
26235 writev(15, [{" </td></tr>\n<tr><td class=\"e\">HT"..., 4108},
{"</td><td class=\"v\">1024</td><td "..., 4098}], 2) = 8206
26235 writev(15, [{"md2 md4 md5 sha1 sha256 sha384 s"..., 4098}, {"
</td></tr>\n</table><br />\n<tabl"..., 4106}], 2) = 8204
26235 writev(15, [{"session.use_cookies</td><td clas"..., 4104}, {" </td><td
class=\"v\">enabled </td"..., 4102}], 2) = 8206
26235 chdir("/")                        = 0
26235 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) =
0
26235 writev(15, [{"\"]</td><td class=\"v\">Keep-Alive<"..., 4206}], 1) =
4206
26235 write(10, "212.48.14.186 - - [09/Jul/2010:1"..., 116) = 116
26235 shutdown(15, 1 /* send */)        = 0
26235 poll([{fd=15, events=POLLIN}], 1, 2000) = 1 ([{fd=15,
revents=POLLIN|POLLHUP}])
26235 read(15, "", 512)                 = 0
26235 close(15)                         = 0
26235 read(4, 0x7fff615ff5eb, 1)        = -1 EAGAIN (Resource temporarily
unavailable)
26235 accept(3,

Note that this behavior also happens when safemode is ON.

Can somebody explain me why PHP have such behavior?

Best regards,
Vincenzo

--001485f03c06062c09048af7e34d--