Bug #49383 [Bgs]: Lots of empty fstat() calls slow performance

2010-08-12 Thread rasmus
Edit report at http://bugs.php.net/bug.php?id=49383&edit=1

 ID: 49383
 Updated by: ras...@php.net
 Reported by:olga at metacafe dot com
 Summary:Lots of empty fstat() calls slow performance
 Status: Bogus
 Type:   Bug
 Package:Performance problem
 Operating System:   Red Hat 3.4.6-10
 PHP Version:5.3, 6
 Block user comment: N

 New Comment:

The reason open_basedir affects this is because for security reasons we
can't 

enable the stat cache when open_basedir is enabled which will also
affect stats 

after the file is opened since it isn't the open_basedir check itself
causing 

the stat but the fact that the open_basedir feature forces the stat
cache to be 

disabled.



The main thing that changed between 5.2.x and 5.3.x with respect to
stats is 

that we rewrote the stat cache to be more efficient.  It now does
intra-path 

caching of realpath() lookups as opposed to just caching the return of
the 

realpath() call, but it doesn't sound like this is the issue here.



One thing you can try is to compile PHP without phar support. 
./configure --

disable-phar and see if that changes things.  Beyond that you would need
to set 

a gdb breakpoint and get a backtrace of those calls.  Generally we are
not too 

concerned about fstat calls since they tend to be extremely fast in most


environments.  It is the full stat/lstat calls that need to hit the disk
that 

tend to be slow.


Previous Comments:

[2010-08-12 15:58:41] a dot rogge at solvention dot de

First of all: No, we don't use open_basedir or safe_mode or stuff like
that.

But I still do not understand what this has to do with the issue.



The redundant fstat() calls are obviously *not* from open_basedir,
because the fstat() calls are done after the file was opened.



I run 5.1.6, 5.2.14 and 5.3.2 with the same configuration. For 5.1.6 and
5.2.14 everything looks normally, in 5.3.2 there are suddenly three
instead of one fstat() call after opening the file. The calls are
identical and adjacent with no other syscalls in between. The two
successive calls do not provide any more information than the first one
and thus are redundant and useless.



This is obviously a performance regression. Do you want to tell me that
this is a new feature?


[2010-08-12 01:24:32] ras...@php.net

Do you have openbase_dir enabled?  If so, for security reasons we can't
use the 

stat cache which is going to cause a lot of stats.  For a setup with
slow stats, I 

suggest chroot/jail or something along those lines rather than
open_basedir to 

keep users separated.


[2010-08-11 20:10:56] a dot rogge at solvention dot de

Nobody cares wether or not APC works around the problem. There is
obviously a regression from 5.2 to 5.3.



Somebody maanged to triple the number of fstat() calls that are done for
an include().



Yesterday I "reproduced" the issue on our webcluster. Running the Red
Hat provided PHP 5.1.6 (from RHEL 5.5) the loadavg was around 8 for all
boxes. Upgrading to PHP 5.3.2 made the loadavg raised to values of 30 or
higher. Page load time went from < 1 second to around 30 seconds.

The best part is: we did install and configure apc for 5.3.2, but not
for 5.1.6



So eventually 5.3.2 *with* APC produces 3 times more load and needs 30
times longer than our ancient 5.1.6 *without* APC.



However, I must admit that we have our PHP-files on GFS2 where stat() is
traditionally a bit slow.


[2010-01-21 23:16:42] ras...@php.net

Unable to reproduce under apc.


[2009-10-14 11:28:06] olga at metacafe dot com

The problem persists.



We upgraded APC to the latest version (3.1.3p1). Cache full count is 0,
hit ratio is 99.9%. I understand that this shouldn't happen, but there
are still 3 fstat() calls per file opened.



Here's our APC configuration - maybe you can see if anything is wrong
with it? Do you have other versions?



apc.cache_by_default1

apc.canonicalize1

apc.coredump_unmap  0

apc.enable_cli  1

apc.enabled 1

apc.file_md50

apc.file_update_protection  2

apc.filters 

apc.gc_ttl  3600

apc.include_once_override   1

apc.lazy_classes0

apc.lazy_functions  0

apc.max_file_size   1M

apc.mmap_file_mask  /tmp/apc.IR76ZW

apc.num_files_hint  1024

apc.preload_path

apc.report_autofilter   0

apc.rfc1867 0

apc.rfc1867_freq0

apc.rfc1867_nameAPC_UPLOAD_PROGRESS

apc.rfc1867_prefix  upload_

apc.rfc1867_ttl 3600

apc.shm_segments1

apc.shm_size128

apc.stat0

apc.stat_ctime  0

apc.ttl 7200

apc.use_reque

Bug #49383 [Bgs]: Lots of empty fstat() calls slow performance

2010-08-11 Thread rasmus
Edit report at http://bugs.php.net/bug.php?id=49383&edit=1

 ID: 49383
 Updated by: ras...@php.net
 Reported by:olga at metacafe dot com
 Summary:Lots of empty fstat() calls slow performance
 Status: Bogus
 Type:   Bug
 Package:Performance problem
 Operating System:   Red Hat 3.4.6-10
 PHP Version:5.3, 6
 Block user comment: N

 New Comment:

Do you have openbase_dir enabled?  If so, for security reasons we can't
use the 

stat cache which is going to cause a lot of stats.  For a setup with
slow stats, I 

suggest chroot/jail or something along those lines rather than
open_basedir to 

keep users separated.


Previous Comments:

[2010-08-11 20:10:56] a dot rogge at solvention dot de

Nobody cares wether or not APC works around the problem. There is
obviously a regression from 5.2 to 5.3.



Somebody maanged to triple the number of fstat() calls that are done for
an include().



Yesterday I "reproduced" the issue on our webcluster. Running the Red
Hat provided PHP 5.1.6 (from RHEL 5.5) the loadavg was around 8 for all
boxes. Upgrading to PHP 5.3.2 made the loadavg raised to values of 30 or
higher. Page load time went from < 1 second to around 30 seconds.

The best part is: we did install and configure apc for 5.3.2, but not
for 5.1.6



So eventually 5.3.2 *with* APC produces 3 times more load and needs 30
times longer than our ancient 5.1.6 *without* APC.



However, I must admit that we have our PHP-files on GFS2 where stat() is
traditionally a bit slow.


[2010-01-21 23:16:42] ras...@php.net

Unable to reproduce under apc.


[2009-10-14 11:28:06] olga at metacafe dot com

The problem persists.



We upgraded APC to the latest version (3.1.3p1). Cache full count is 0,
hit ratio is 99.9%. I understand that this shouldn't happen, but there
are still 3 fstat() calls per file opened.



Here's our APC configuration - maybe you can see if anything is wrong
with it? Do you have other versions?



apc.cache_by_default1

apc.canonicalize1

apc.coredump_unmap  0

apc.enable_cli  1

apc.enabled 1

apc.file_md50

apc.file_update_protection  2

apc.filters 

apc.gc_ttl  3600

apc.include_once_override   1

apc.lazy_classes0

apc.lazy_functions  0

apc.max_file_size   1M

apc.mmap_file_mask  /tmp/apc.IR76ZW

apc.num_files_hint  1024

apc.preload_path

apc.report_autofilter   0

apc.rfc1867 0

apc.rfc1867_freq0

apc.rfc1867_nameAPC_UPLOAD_PROGRESS

apc.rfc1867_prefix  upload_

apc.rfc1867_ttl 3600

apc.shm_segments1

apc.shm_size128

apc.stat0

apc.stat_ctime  0

apc.ttl 7200

apc.use_request_time1

apc.user_entries_hint   4096

apc.user_ttl7200

apc.write_lock  1


[2009-09-03 16:49:18] ras...@php.net

The only time this code is executed if you are running APC is if the
script is not cached.  So, either your APC setup is not working, you are
constantly trashing your cache (check apc.php and look at the cache-full
counter), or something else weird is going on.  



These fstats are coming from compiler which reads the script from disk
and compiles it down to opcodes.  It is impossible for this code to
execute on an APC-cached script because we point the executor directly
at the already compiled opcodes in shared memory.




[2009-09-03 15:06:28] olga at metacafe dot com

Thanks for the quick response.



We do work with APC. I tested the new PHP without APC also, to make sure
the fstat() calls aren't caused by it. But the statistics I sent to you
are from web server that works with APC.



You can also see from my first submission that in 5.2.9 fstat() doesn't
take much time.




The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at

http://bugs.php.net/bug.php?id=49383


-- 
Edit this bug report at http://bugs.php.net/bug.php?id=49383&edit=1