Any PHP code does it.

The code:
<?php
echo "Hello!";
?>

The strace:
open("[path]/test.php", O_RDONLY) = 16
fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0
fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0
fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0
mmap(NULL, 82, PROT_READ, MAP_SHARED, 16, 0) = 0x2a9a8b4000
munmap(0x2a9a8b4000, 82)                = 0
close(16)                               = 0

You suppose it is because of fstat?  I seriously doubt that.  fstat is really fast because it doesn't need to touch the disk at all.  It simply grabs the stat struct from an already open file descriptor.  If you can show me some profiling numbers where fstat is anywhere on the radar, I'll take a look, but I am highly suspicious that fstat would have anything to do with any performance issues.

Disk-touching stats like lstat are the ones you need to worry about.  

When I compare 5.2.9 with 5.3, I see that

(a) 5.3 is slower. According to release notes, I was expecting performance improvement, or at least the same performance as in previous version.

(b) top 5 system calls in 5.3 take more time that in 5.2.9
lstat() calls are reduced, but fstat(), mmap() and munmap() are used much more than before.

Maybe I'm wrong about fstat(), but that's the only difference I found so far. What else could have caused this performance problem?

You need to do proper profiling to determine that.  Start by turning on all warning messages.  If you are throwing warnings or notices, even if you are not displaying or logging them anywhere, it is going to slow you down and there are a bunch of new ones in 5.3.  Set your error reporting to something like 16777215 (0xffffff) which will catch all current and future error levels and fix anything you see.  Then check your performance again.

Turning all messages on/off didn't change the behavior. We tend eliminate the notices on the development stage.

Can you please look at the system calls summary below? fstat() takes 25% of the total time. This doesn't happen in PHP 5.2.9.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 24.85   33.820248         256    131908           fstat
 13.54   18.431644         263     70002        66 lstat
  9.81   13.346466         259     51520           mmap
  9.72   13.223388         258     51175           munmap
  9.39   12.775102         264     48450       192 stat
  8.83   12.014341         265     45383        10 open
  8.72   11.866944         257     46154           close
  3.47    4.724639         255     18530       396 read
  3.26    4.430927         256     17297           lseek
  1.88    2.557480         244     10477           poll
  1.59    2.170520         261      8326           recvfrom
  1.52    2.073135         259      7994           sendto
...
------ ----------- ----------- --------- --------- ----------------
100.00  136.108580                526555      1324 total

In 5.2.9 fstat() takes about 8% of total time.

Still surprised these fstats take that long on your system.  Note also that if you install APC, they completely go away.  If you are down to caring about performance at the syscall level like that and you are not running a decent opcode cache, you are kind of confused.

Here is a backtrace of those 3 fstats:

#1  0x0137642f in do_fstat ()
#2  0x0137768f in _php_stream_fopen ()
#3  0x013719ba in _php_stream_open_wrapper_ex ()
#4  0x0135a1a3 in php_stream_open_for_zend_ex ()
#5  0x0135a2e0 in php_stream_open_for_zend ()
#6  0x013ca05f in zend_stream_fixup ()
#7  0x01383ae7 in open_file_for_scanning ()
#8  0x01383c8d in compile_file ()
#9  0x011eb8f7 in phar_compile_file ()
#10 0x013b4fa7 in zend_execute_scripts ()
#11 0x0135be38 in php_execute_script ()

#1  0x0137642f in do_fstat ()
#2  0x01376ee1 in php_stdiop_stat ()
#3  0x0135a148 in php_zend_stream_fsizer ()
#4  0x0135a206 in php_stream_open_for_zend_ex ()
#5  0x0135a2e0 in php_stream_open_for_zend ()
#6  0x013ca05f in zend_stream_fixup ()
#7  0x01383ae7 in open_file_for_scanning ()
#8  0x01383c8d in compile_file ()
#9  0x011eb8f7 in phar_compile_file ()
#10 0x013b4fa7 in zend_execute_scripts ()
#11 0x0135be38 in php_execute_script ()

#1  0x0137642f in do_fstat ()
#2  0x01377189 in php_stdiop_set_option ()
#3  0x0136fc8e in _php_stream_set_option ()
#4  0x0137dcec in _php_stream_mmap_range ()
#5  0x0135a295 in php_stream_open_for_zend_ex ()
#6  0x0135a2e0 in php_stream_open_for_zend ()
#7  0x013ca05f in zend_stream_fixup ()
#8  0x01383ae7 in open_file_for_scanning ()
#9  0x01383c8d in compile_file ()
#10 0x011eb8f7 in phar_compile_file ()
#11 0x013b4fa7 in zend_execute_scripts ()
#12 0x0135be38 in php_execute_script ()

The do_fstat() function has a cache, but those 3 calls set the 'force' flag to ignore the cached stat struct.  We need to track down whether it is possible to not force these.  It seems like it should be possible to get rid of at least one of those, if not 2.

But again, install an opcode cache, and this stops being a problem.

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 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.

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_default	1
apc.canonicalize	1
apc.coredump_unmap	0
apc.enable_cli	1
apc.enabled	1
apc.file_md5	0
apc.file_update_protection	2
apc.filters	
apc.gc_ttl	3600
apc.include_once_override	1
apc.lazy_classes	0
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_freq	0
apc.rfc1867_name	APC_UPLOAD_PROGRESS
apc.rfc1867_prefix	upload_
apc.rfc1867_ttl	3600
apc.shm_segments	1
apc.shm_size	128
apc.stat	0
apc.stat_ctime	0
apc.ttl	7200
apc.use_request_time	1
apc.user_entries_hint	4096
apc.user_ttl	7200
apc.write_lock	1

Unable to reproduce under apc.

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.

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.

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?

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.

I wonder if this has been fixed.

I've noticed the same behavior in php5.6 (PHP 5.6.39-1+ubuntu16.04.1+deb.sury.org+1). I know it's an old version but I am just checking if some solution was proposed.

- opcache enabled
- open_basedir disabled

after open() is issued, 4 exactly same fstat() calls occur. I guess 3 of them are not necessary and in long-term it eats sys% like this:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 20.23    0.008665           2      5511           fstat
 18.91    0.008097           3      2382           poll
 14.58    0.006244           3      2382           recvfrom
 10.25    0.004390           3      1341           munmap
  9.69    0.004151           3      1467           open
  9.34    0.004000         222        18           shutdown
  7.20    0.003083          10       318           brk
  4.07    0.001741           1      1481           sendto
  2.55    0.001093           1      1072        19 access
  1.30    0.000555           6        90           write
  0.72    0.000308           0      1341           mmap
...

See the time CPU mostly spent in syscalls is at the very fast but redundant fstat() call.

...
access("luigisBoxHtmlBodyEnd.php", R_OK) = 0
open("luigisBoxHtmlBodyEnd.php", O_RDONLY) = 7
fstat(7, {st_mode=S_IFREG|0644, st_size=438, ...}) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=438, ...}) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=438, ...}) = 0
fstat(7, {st_mode=S_IFREG|0644, st_size=438, ...}) = 0
mmap(NULL, 438, PROT_READ, MAP_SHARED, 7, 0) = 0x7f8560433000
...


Would this be fixed in php7 if the site is moved there?

Thanks.

我也遇到了这个问题好像是opchache无法使用的情况下
access("/data/web/releases/20190122_1036111_2/src/application/Models/LocalModel.php", F_OK) = 0
open("/data/web/releases/20190122_1036111_2/src/application/Models/LocalModel.php", O_RDONLY) = 9
fstat(9, {st_mode=S_IFREG|0755, st_size=416, ...}) = 0
fstat(9, {st_mode=S_IFREG|0755, st_size=416, ...}) = 0
fstat(9, {st_mode=S_IFREG|0755, st_size=416, ...}) = 0
mmap(NULL, 416, PROT_READ, MAP_SHARED, 9, 0) = 0x7fea60241000
munmap(0x7fea60241000, 416)             = 0
close(9)                                = 0

I've dropped two fstat() calls per include in 7.4, so only a single fstat() call should be happening now.

I commented too early ... there will be two fstats after all. Still one less than before...

Okay, duplicate fstat removed after all in https://github.com/php/php-src/commit/07a4d134abd07690f9921eb0d0c7eeb671b0b875, now there should be just the one.