Edit report at https://bugs.php.net/bug.php?id=63160&edit=1
ID: 63160
Updated by: nikic@php.net
Reported by: remi@php.net
Summary: Lot of fstat call during include
-Status: Open
+Status: Closed
Type: Bug
Package: Performance problem
Operating System: GNU/Linux
PHP Version: 5.4.7
-Assigned To:
+Assigned To: nikic
Block user comment: N
Private report: N
New Comment:
This is fixed in PHP 7.4. One goes away because we no longer use mmap and the other is removed in https://github.com/php/php-src/commit/07a4d134abd07690f9921eb0d0c7eeb671b0b875
by avoiding the "force" just for includes, where we don't need it.
Previous Comments:
------------------------------------------------------------------------
[2012-09-25 11:59:36] remi@php.net
I agree, APC is interesting (for lot of other reasons) and it reduces the 3 "fstat" calls
to 2 "stat" calls.
Droping the "force" option doesn't seems acceptable ;)
------------------------------------------------------------------------
[2012-09-25 09:27:06] laruence@php.net
the simple way is make the plain stream stat not force, like:
diff --git a/main/streams/plain_wrapper.c b/main/streams/plain_wrapper.c
index 80c22ce..2bc81a5 100644
--- a/main/streams/plain_wrapper.c
+++ b/main/streams/plain_wrapper.c
@@ -543,7 +543,7 @@ static int php_stdiop_stat(php_stream *stream,
php_stream_statbuf *ssb TSRMLS_DC
assert(data != NULL);
- ret = do_fstat(data, 1);
+ ret = do_fstat(data, 0);
memcpy(&ssb->sb, &data->sb, sizeof(ssb->sb));
return ret;
}
but, this might introduce some unexpected issues. so, run with apc :)
------------------------------------------------------------------------
[2012-09-25 08:10:27] remi@php.net
Here is the backtrace for each fstat call
Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=0) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138 {
(gdb) bt
#0 do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=0) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1 0x0000000000581d0b in _php_stream_fopen (filename=<optimized out>, mode=0x6a3831
"rb", opened_path=0x7fffffffa7d0, options=<optimized out>) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:967
#2 0x000000000057d4f2 in _php_stream_open_wrapper_ex (path=0x7ffff7fcb238
"/home/rcollet/test/test2.php", path@entry=0x7ffff7eba2e0 "test2.php",
mode=mode@entry=0x6a3831 "rb", options=16520,
opened_path=opened_path@entry=0x7fffffffa7d0, context=context@entry=0x0) at
/usr/src/debug/php-5.4.7/main/streams/streams.c:2049
#3 0x0000000000562a21 in php_stream_open_for_zend_ex (filename=0x7ffff7eba2e0
"test2.php", handle=0x7fffffffa7c0, mode=<optimized out>) at
/usr/src/debug/php-5.4.7/main/main.c:1303
#4 0x00000000005d919c in zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0,
buf=buf@entry=0x7fffffffa500, len=len@entry=0x7fffffffa508) at
/usr/src/debug/php-5.4.7/Zend/zend_stream.c:187
#5 0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at
Zend/zend_language_scanner.l:486
#6 0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at
Zend/zend_language_scanner.l:569
#7 0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at
/usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8 0x000000000058e2e0 in compile_filename (type=type@entry=2,
filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9 0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0,
file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at
/usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
(gdb) c
Continuing.
Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138 {
(gdb) bt
#0 do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1 0x00000000005807fa in php_stdiop_stat (stream=<optimized out>, ssb=0x7fffffffa360) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:546
#2 0x000000000056132f in php_zend_stream_fsizer (handle=handle@entry=0x7ffff7fcbfa0) at
/usr/src/debug/php-5.4.7/main/main.c:1286
#3 0x0000000000562aaf in php_stream_open_for_zend_ex (filename=0x7ffff7eba2e0
"test2.php", handle=0x7fffffffa7c0, mode=<optimized out>) at
/usr/src/debug/php-5.4.7/main/main.c:1318
#4 0x00000000005d919c in zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0,
buf=buf@entry=0x7fffffffa500, len=len@entry=0x7fffffffa508) at
/usr/src/debug/php-5.4.7/Zend/zend_stream.c:187
#5 0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at
Zend/zend_language_scanner.l:486
#6 0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at
Zend/zend_language_scanner.l:569
#7 0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at
/usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8 0x000000000058e2e0 in compile_filename (type=type@entry=2,
filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9 0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0,
file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at
/usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
(gdb) c
Continuing.
Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138 {
(gdb) bt
#0 do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1 0x00000000005807fa in php_stdiop_stat (stream=<optimized out>, ssb=0x7fffffffa3a0) at
/usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:546
#2 0x000000000056132f in php_zend_stream_fsizer (handle=<optimized out>) at
/usr/src/debug/php-5.4.7/main/main.c:1286
#3 0x00000000005d94b7 in zend_stream_fsize (file_handle=<optimized out>) at
/usr/src/debug/php-5.4.7/Zend/zend_stream.c:115
#4 zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0, buf=buf@entry=0x7fffffffa500,
len=len@entry=0x7fffffffa508) at /usr/src/debug/php-5.4.7/Zend/zend_stream.c:222
#5 0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at
Zend/zend_language_scanner.l:486
#6 0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at
Zend/zend_language_scanner.l:569
#7 0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at
/usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8 0x000000000058e2e0 in compile_filename (type=type@entry=2,
filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9 0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at
/usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0,
file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at
/usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at
/usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
------------------------------------------------------------------------
[2012-09-25 08:09:07] remi@php.net
Description:
------------
Hi,
Each "include" statement call fstat 3 time, which can be "slow" in some cluster
environment (usgin GFS2 p.e.)
Already open as #49383 (but closed as "not a bug")
The fstat cache is only available inside "plain_wrapper".
A solution could be to expose a stream_cached_stat (in _php_stream_wrapper_ops) and use it during
open process (or a additionnal parameter to stream_stat).
But this will introduce a important bc break.
Test script:
---------------
Trivial test code:
test1.php: <?php include('test2.php'); echo "done\n";
test2.php: irrevelant, can even be empty
$ strace php test1.php
Expected result:
----------------
...
open("xxx/test2.php", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
mmap(NULL, 20, PROT_READ, MAP_SHARED, 3, 0) = 0x7f0d595da000
munmap(0x7f0d595da000, 20) = 0
close(3)
...
Actual result:
--------------
...
open("xxx/test2.php", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
mmap(NULL, 20, PROT_READ, MAP_SHARED, 3, 0) = 0x7f0d595da000
munmap(0x7f0d595da000, 20) = 0
close(3)
...
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=63160&edit=1